Merge pull request #5031 from tkyjovsk/KEYCLOAK-5973

KEYCLOAK-5973 Filtering of Gatling results

testsuite/performance/README.md

@@ -146,6 +146,7 @@ Usage: `mvn verify -Ptest[,cluster] [-DtestParameter=value]`.
 | `warmUpPeriod` | Period with steady number of users intended for the system under test to warm up. (seconds) | `0` |
 | `measurementPeriod` | A measurement period after the system is warmed up. (seconds) | `30` |
 | `rampDownASAP` | When `true` the test will be checking for ramp-down condition after each *scenario step*. When `false` the check will be done only at the end of a *scenario iteration*. | `false` |
+| `filterResults` | Whether to filter out requests which are outside of the `measurementPeriod`. | `false` |
 | `pace` | A dynamic pause after each *scenario iteration*. For example if the pace is 30s and one scenario iteration takes only 20s, the simulation will wait additional 10s before continuing to the next iteration. | `0` |
 | `userThinkTime` | Pause between individual scenario steps. | `5` |
 | `refreshTokenPeriod`| Period after which token should be refreshed. | `10` |

testsuite/performance/tests/pom.xml

@@ -278,6 +278,7 @@
                         <include>keycloak.DemoSimulation2</include>
                     </includes-->
                     <jvmArgs>
+                        <param>-Dproject.build.directory=${project.build.directory}</param>
                         <param>-Dkeycloak.server.uris=${keycloak.frontend.servers}</param>
                         <param>-DnumOfRealms=${numOfRealms}</param>
                         <param>-DusersPerRealm=${usersPerRealm}</param>

testsuite/performance/tests/src/main/java/org/keycloak/performance/TestConfig.java

@@ -60,6 +60,7 @@ public class TestConfig {
     public static final int warmUpPeriod = Integer.getInteger("warmUpPeriod", 0);
     public static final int measurementPeriod = Integer.getInteger("measurementPeriod", 30);
     public static final boolean rampDownASAP = Boolean.getBoolean("rampDownASAP"); // check for rampdown condition after each scenario step
+    public static final boolean filterResults = Boolean.getBoolean("filterResults"); // filter out results outside of measurementPeriod
     public static final int pace = Integer.getInteger("pace", 0); // additional dynamic "pause buffer" between scenario loops
     public static final int userThinkTime = Integer.getInteger("userThinkTime", 0);
     public static final int refreshTokenPeriod = Integer.getInteger("refreshTokenPeriod", 0);
@@ -122,10 +123,11 @@ public class TestConfig {
                 + "  warmUpPeriod: %s\n"
                 + "  measurementPeriod: %s\n"
                 + "  rampDownASAP: %s\n"
+                + "  filterResults: %s\n"
                 + "  pace: %s\n"
                 + "  userThinkTime: %s\n"
                 + "  refreshTokenPeriod: %s",
-                runUsers, rampUpPeriod, warmUpPeriod, measurementPeriod, rampDownASAP, pace, userThinkTime, refreshTokenPeriod
+                runUsers, rampUpPeriod, warmUpPeriod, measurementPeriod, rampDownASAP, filterResults, pace, userThinkTime, refreshTokenPeriod
         );
     }
 

testsuite/performance/tests/src/main/java/org/keycloak/performance/log/LogProcessor.java

@@ -5,13 +5,19 @@ import java.io.File;
 import java.io.FileInputStream;
 import java.io.FileNotFoundException;
 import java.io.FileOutputStream;
+import java.io.FileReader;
 import java.io.IOException;
 import java.io.InputStreamReader;
 import java.io.OutputStreamWriter;
 import java.io.PrintWriter;
+import java.io.Reader;
+import java.io.Writer;
 import java.nio.charset.Charset;
+import java.nio.file.Files;
 import java.util.ArrayList;
+import java.util.Arrays;
 import java.util.HashMap;
+import java.util.HashSet;
 import java.util.LinkedHashMap;
 import java.util.LinkedHashSet;
 import java.util.Map;
@@ -29,6 +35,7 @@ public class LogProcessor {
 
     static boolean INLAYED_INCLUDED = false;
     static boolean OUTLAYED_INCLUDED = false;
+    static boolean COMPLETE_SESSIONS = false;
 
     File simulationLogFile;
     String lastRequestLabel;
@@ -56,6 +63,25 @@ public class LogProcessor {
         simulationLogFile = new File(logFilePath);
     }
 
+    public LogProcessor(Class simulationClass) {
+        this(getLatestSimulationLogDir(getSimulationId(simulationClass)).getAbsoluteFile().toString() + "/simulation.log");
+    }
+
+    public static String getSimulationId(Class simulationClass) {
+        return simulationClass.getSimpleName().toLowerCase();
+    }
+    
+    private static File getLatestSimulationLogDir(String simulationId) {
+        String buildDirPath = System.getProperty("project.build.directory", "target");
+        String resultsDirPath = System.getProperty("gatling.core.directory.results", buildDirPath + "/gatling");
+        File resultsDir = new File(resultsDirPath);
+        
+        return Arrays.stream(resultsDir.listFiles((dir, name) -> name.startsWith(simulationId)))
+                .sorted((a, b) -> -a.compareTo(b))
+                .findFirst()
+                .orElseThrow(() -> new IllegalStateException("Latest simulation.log not found."));
+    }
+    
     public Stats stats() throws IOException {
 
         Stats stats = new Stats();
@@ -125,15 +151,55 @@ public class LogProcessor {
         currentIterations.put(scenario, 1 + currentIterations.getOrDefault(scenario, 1));
     }
 
+    public void filterLog(long start, long end) throws IOException {
+        filterLog(start, end, INLAYED_INCLUDED, OUTLAYED_INCLUDED, COMPLETE_SESSIONS);
+    }
+    
+    public void filterLog(long start, long end, boolean inlayedIncluded, boolean outlayedIncluded, boolean completeSessions) throws IOException {
+        INLAYED_INCLUDED = inlayedIncluded;
+        OUTLAYED_INCLUDED = outlayedIncluded;
+        COMPLETE_SESSIONS = completeSessions;
+        
+        System.out.println(String.format("Filtering %s/%s \nINLAYED_INCLUDED: %s \nOUTLAYED_INCLUDED: %s \nCOMPLETE_SESSIONS: %s", 
+                simulationLogFile.getParentFile().getName(), simulationLogFile.getName(), INLAYED_INCLUDED, OUTLAYED_INCLUDED, COMPLETE_SESSIONS));
+
+        File simulationLogFileFiltered = new File(simulationLogFile.getAbsoluteFile() + ".filtered");
+        File simulationLogFileUnfiltered = new File(simulationLogFile.getAbsoluteFile() + ".unfiltered");
+
+        PrintWriter out = new PrintWriter(new OutputStreamWriter(new FileOutputStream(simulationLogFileFiltered), "utf-8"));
+        copyPartialLog(out, start, end);
+
+        simulationLogFile.renameTo(simulationLogFileUnfiltered);
+        simulationLogFileFiltered.renameTo(simulationLogFile);
+    }
+    
     public void copyPartialLog(PrintWriter output, long start, long end) throws IOException {
 
+        File tmpFile = null, headFile = null;
+        PrintWriter tmp = null, startHead = null;
+        HashMap<String, LogLine> starts = new HashMap<>();
+        HashSet<String> actives = new HashSet<>();
+
+        if (COMPLETE_SESSIONS) {
+            tmp = output;
+            tmpFile = getTmpFile();
+            output = new PrintWriter(new OutputStreamWriter(new FileOutputStream(tmpFile), "utf-8"));
+
+            headFile = getTmpFile();
+            startHead = new PrintWriter(new OutputStreamWriter(new FileOutputStream(headFile), "utf-8"));
+        }
+
         LogReader reader = new LogReader(simulationLogFile);
         try {
             LogLine line;
             while ((line = reader.readLine()) != null) {
 
                 if (line.type() == LogLine.Type.RUN) {
-                    output.println(line.rawLine());
+                    if (COMPLETE_SESSIONS) {
+                        startHead.println(line.rawLine());
+                    } else {
+                        output.println(line.rawLine());
+                    }
                     continue;
                 }
 
@@ -149,13 +215,73 @@ public class LogProcessor {
                 } else if (INLAYED_INCLUDED && endTime >= start && endTime < end) {
                     output.println(line.rawLine());
                 }
+
+                if (COMPLETE_SESSIONS) {
+                    if (line.type() == LogLine.Type.USER_START) {
+                        if (startTime < end) {
+                            starts.put(line.userId(), line);
+                        }
+                    } else if (line.type() == LogLine.Type.USER_END) {
+                        if (endTime < start) {
+                            starts.remove(line.userId());
+                        } else if (endTime >= start && endTime < end) {
+                            LogLine sline = starts.remove(line.userId());
+                            if (sline != null) {
+                                startHead.println(sline.rawLine());
+                            }
+                            actives.remove(line.userId());
+                        } else if (endTime >= end) {
+                            boolean was = actives.remove(line.userId());
+                            if (was) {
+                                output.println(line.rawLine());
+                            }
+                        }
+                    } else if (line.type() == LogLine.Type.REQUEST) {
+                        if ((startTime >= start && startTime < end) || (endTime >= start && endTime < end)) {
+                            LogLine sline = starts.remove(line.userId());
+                            if (sline != null) {
+                                startHead.println(sline.rawLine());
+                            }
+                            actives.add(line.userId());
+                        }
+                    }
+                }
             }
         } finally {
             reader.close();
             output.flush();
+
+            if (COMPLETE_SESSIONS) {
+                startHead.close();
+                output.close();
+
+
+                BufferedReader tmpIn = new BufferedReader(new FileReader(headFile));
+                copyStream(tmpIn, tmp);
+
+                tmpIn = new BufferedReader(new FileReader(tmpFile));
+                copyStream(tmpIn, tmp);
+
+                tmp.flush();
+
+                Files.delete(headFile.toPath());
+                Files.delete(tmpFile.toPath());
+            }
         }
     }
 
+    private static void copyStream(Reader reader, Writer writer) throws IOException {
+        char [] buff = new char[16 * 1024];
+        int rc;
+        while ((rc = reader.read(buff)) != -1) {
+            writer.write(buff, 0, rc);
+        }
+    }
+
+    private File getTmpFile() throws IOException {
+        return Files.createTempFile("perftest", ".log").toFile();
+    }
+
     public void setLastRequestLabel(String lastRequestLabel) {
         this.lastRequestLabel = lastRequestLabel;
     }
@@ -333,7 +459,7 @@ public class LogProcessor {
                 start = Long.parseLong(cols[4]);
                 end = Long.parseLong(cols[5]);
             } else {
-                throw new RuntimeException("Unknow log entry type: " + cols[3]);
+                throw new RuntimeException("Unknow log entry type: " + cols[2]);
             }
 
             return this;
@@ -407,6 +533,11 @@ public class LogProcessor {
                         }
                         endMillis = Long.valueOf(args[++i]);
                         break;
+                    case "--completeSessions":
+                        //INLAYED_INCLUDED = true;
+                        OUTLAYED_INCLUDED = true;
+                        COMPLETE_SESSIONS = true;
+                        break;
                     case "--lastRequest":
                         if (i == args.length - 1) {
                             throw new RuntimeException("Argument " + arg + " requires a LABEL");

testsuite/performance/tests/src/test/scala/keycloak/AdminConsoleSimulation.scala

@@ -99,4 +99,9 @@ class AdminConsoleSimulation extends Simulation {
   setUp(adminScenario
     .inject(rampUsers(TestConfig.runUsers) over TestConfig.rampUpPeriod)
     .protocols(httpProtocol))
+
+  after {
+    filterResults(getClass)
+  }
+
 }

testsuite/performance/tests/src/test/scala/keycloak/BasicOIDCSimulation.scala

@@ -59,4 +59,8 @@ class BasicOIDCSimulation extends Simulation {
     .inject(rampUsers(TestConfig.runUsers) over TestConfig.rampUpPeriod)
     .protocols(httpDefault))
 
+  after {
+    filterResults(getClass)
+  }
+
 }

testsuite/performance/tests/src/test/scala/keycloak/CommonScenarioBuilder.scala

@@ -4,6 +4,7 @@ import io.gatling.core.Predef._
 import io.gatling.http.Predef._
 import org.keycloak.gatling.Predef._
 import keycloak.BasicOIDCScenarioBuilder._
+import org.keycloak.performance.log.LogProcessor
 
 import java.util.concurrent.atomic.AtomicInteger
 
@@ -27,5 +28,14 @@ object CommonScenarioBuilder {
     System.currentTimeMillis < TestConfig.measurementEndTime
   }
 
+  def filterResults(clazz: Class[_]) = {
+    if (TestConfig.filterResults) {
+      new LogProcessor(clazz).filterLog(
+        TestConfig.measurementStartTime, 
+        TestConfig.measurementEndTime,
+        false, true, true)
+    }
+  }
+
 }