diff --git a/testsuite/performance/README.md b/testsuite/performance/README.md index 5987c57651..fdd93d7987 100644 --- a/testsuite/performance/README.md +++ b/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` | diff --git a/testsuite/performance/tests/pom.xml b/testsuite/performance/tests/pom.xml index 117bd80149..37bb52bf20 100644 --- a/testsuite/performance/tests/pom.xml +++ b/testsuite/performance/tests/pom.xml @@ -278,6 +278,7 @@ keycloak.DemoSimulation2 + -Dproject.build.directory=${project.build.directory} -Dkeycloak.server.uris=${keycloak.frontend.servers} -DnumOfRealms=${numOfRealms} -DusersPerRealm=${usersPerRealm} diff --git a/testsuite/performance/tests/src/main/java/org/keycloak/performance/TestConfig.java b/testsuite/performance/tests/src/main/java/org/keycloak/performance/TestConfig.java index bbb896d0fc..6d7d5d7845 100644 --- a/testsuite/performance/tests/src/main/java/org/keycloak/performance/TestConfig.java +++ b/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 ); } diff --git a/testsuite/performance/tests/src/main/java/org/keycloak/performance/log/LogProcessor.java b/testsuite/performance/tests/src/main/java/org/keycloak/performance/log/LogProcessor.java index 7c6a5ec3a8..da835f25ae 100644 --- a/testsuite/performance/tests/src/main/java/org/keycloak/performance/log/LogProcessor.java +++ b/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 starts = new HashMap<>(); + HashSet 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"); diff --git a/testsuite/performance/tests/src/test/scala/keycloak/AdminConsoleSimulation.scala b/testsuite/performance/tests/src/test/scala/keycloak/AdminConsoleSimulation.scala index 77b97783d2..8ddb9a9597 100644 --- a/testsuite/performance/tests/src/test/scala/keycloak/AdminConsoleSimulation.scala +++ b/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) + } + } diff --git a/testsuite/performance/tests/src/test/scala/keycloak/BasicOIDCSimulation.scala b/testsuite/performance/tests/src/test/scala/keycloak/BasicOIDCSimulation.scala index 140da33e15..20e2f935d2 100644 --- a/testsuite/performance/tests/src/test/scala/keycloak/BasicOIDCSimulation.scala +++ b/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) + } + } diff --git a/testsuite/performance/tests/src/test/scala/keycloak/CommonScenarioBuilder.scala b/testsuite/performance/tests/src/test/scala/keycloak/CommonScenarioBuilder.scala index 18a1b0f92e..39cc1a7261 100644 --- a/testsuite/performance/tests/src/test/scala/keycloak/CommonScenarioBuilder.scala +++ b/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) + } + } + }