Skip to content

Commit

Permalink
Improve system performance test
Browse files Browse the repository at this point in the history 
1) Various task statistics are logged in CSV format.
2) File names now contain short test characterization.
3) Overall time is logged into summary file.
  • Loading branch information
@mederly
mederly committed May 6, 2021
1 parent b69ee7c commit cb41a8e
Show file tree
Hide file tree
Showing 6 changed files with 132 additions and 24 deletions.
2 changes: 1 addition & 1 deletion ...main/java/com/evolveum/midpoint/schema/statistics/CachePerformanceInformationPrinter.java
View file
Expand Up @@ -24,7 +24,7 @@
*/
public class CachePerformanceInformationPrinter extends AbstractStatisticsPrinter<CachesPerformanceInformationType> {

CachePerformanceInformationPrinter(@NotNull CachesPerformanceInformationType information, Options options) {
public CachePerformanceInformationPrinter(@NotNull CachesPerformanceInformationType information, Options options) {
super(information, options, null, null);
}

Expand Down
73 changes: 71 additions & 2 deletions infra/test-util/src/main/java/com/evolveum/midpoint/test/util/TestReportUtil.java
View file
Expand Up @@ -7,13 +7,14 @@
package com.evolveum.midpoint.test.util;

import static com.evolveum.midpoint.schema.statistics.AbstractStatisticsPrinter.Format.RAW;
import static com.evolveum.midpoint.schema.statistics.AbstractStatisticsPrinter.SortBy.NAME;
import static com.evolveum.midpoint.schema.statistics.AbstractStatisticsPrinter.SortBy.TIME;

import com.evolveum.midpoint.schema.statistics.*;
import com.evolveum.midpoint.tools.testng.TestMonitor;
import com.evolveum.midpoint.tools.testng.TestReportSection;
import com.evolveum.midpoint.util.statistics.OperationsPerformanceMonitor;
import com.evolveum.midpoint.xml.ns._public.common.common_3.OperationsPerformanceInformationType;
import com.evolveum.midpoint.xml.ns._public.common.common_3.*;

public class TestReportUtil {

Expand All @@ -29,12 +30,80 @@ public static void reportGlobalPerfData(TestMonitor testMonitor) {
OperationsPerformanceInformationPrinter printer = new OperationsPerformanceInformationPrinter(performanceInformation,
new AbstractStatisticsPrinter.Options(RAW, TIME), null, null, false);

addPrinterData(testMonitor, "globalPerformanceInformation", printer);
}

private static void addPrinterData(TestMonitor testMonitor, String sectionName, AbstractStatisticsPrinter<?> printer) {
printer.prepare();
Data data = printer.getData();
Formatting formatting = printer.getFormatting();

TestReportSection section = testMonitor.addReportSection("globalPerformanceInformation")
TestReportSection section = testMonitor.addReportSection(sectionName)
.withColumns(formatting.getColumnLabels().toArray(new String[0]));
data.getRawDataStream().forEach(section::addRow);
}

/**
* Adds operation performance for a given task to the {@link TestMonitor}.
*/
public static void reportTaskOperationPerformance(TestMonitor testMonitor, String label,
TaskType task, Integer iterations, Integer seconds) {
OperationsPerformanceInformationType performanceInformationFromTask =
task.getOperationStats() != null ? task.getOperationStats().getOperationsPerformanceInformation() : null;
OperationsPerformanceInformationType performanceInformation = performanceInformationFromTask != null ?
performanceInformationFromTask : new OperationsPerformanceInformationType();

OperationsPerformanceInformationPrinter printer = new OperationsPerformanceInformationPrinter(performanceInformation,
new AbstractStatisticsPrinter.Options(RAW, TIME), iterations, seconds, false);

addPrinterData(testMonitor, label + ":operationPerformance", printer);
}

/**
* Adds repository performance for a given task to the {@link TestMonitor}.
*/
public static void reportTaskRepositoryPerformance(TestMonitor testMonitor, String label,
TaskType task, Integer iterations, Integer seconds) {
RepositoryPerformanceInformationType performanceInformationFromTask =
task.getOperationStats() != null ? task.getOperationStats().getRepositoryPerformanceInformation() : null;
RepositoryPerformanceInformationType performanceInformation = performanceInformationFromTask != null ?
performanceInformationFromTask : new RepositoryPerformanceInformationType();

RepositoryPerformanceInformationPrinter printer = new RepositoryPerformanceInformationPrinter(performanceInformation,
new AbstractStatisticsPrinter.Options(RAW, NAME), iterations, seconds);

addPrinterData(testMonitor, label + ":repositoryPerformance", printer);
}

/**
* Adds caches performance for a given task to the {@link TestMonitor}.
*/
public static void reportTaskCachesPerformance(TestMonitor testMonitor, String label, TaskType task) {
CachesPerformanceInformationType performanceInformationFromTask =
task.getOperationStats() != null ? task.getOperationStats().getCachesPerformanceInformation() : null;
CachesPerformanceInformationType performanceInformation = performanceInformationFromTask != null ?
performanceInformationFromTask : new CachesPerformanceInformationType();

CachePerformanceInformationPrinter printer = new CachePerformanceInformationPrinter(performanceInformation,
new AbstractStatisticsPrinter.Options(RAW, NAME));

addPrinterData(testMonitor, label + ":cachePerformance", printer);
}

/**
* Adds provisioning operations statistics for a given task to the {@link TestMonitor}.
*/
public static void reportTaskProvisioningStatistics(TestMonitor testMonitor, String label, TaskType task) {
EnvironmentalPerformanceInformationType envPerformanceInformationFromTask =
task.getOperationStats() != null ? task.getOperationStats().getEnvironmentalPerformanceInformation() : null;
ProvisioningStatisticsType provisioningStatisticsFromTask = envPerformanceInformationFromTask != null ?
envPerformanceInformationFromTask.getProvisioningStatistics() : null;
ProvisioningStatisticsType provisioningStatistics = provisioningStatisticsFromTask != null ?
provisioningStatisticsFromTask : new ProvisioningStatisticsType();

ProvisioningStatisticsPrinter printer = new ProvisioningStatisticsPrinter(provisioningStatistics,
new AbstractStatisticsPrinter.Options(RAW, NAME));

addPrinterData(testMonitor, label + ":provisioningStatistics", printer);
}
}
16 changes: 9 additions & 7 deletions ...ng/story/src/test/java/com/evolveum/midpoint/testing/story/sysperf/DetailsOutputFile.java
View file
@@ -1,24 +1,26 @@
package com.evolveum.midpoint.testing.story.sysperf;

import com.evolveum.midpoint.schema.util.task.TaskOperationStatsUtil;
import com.evolveum.midpoint.schema.util.task.TaskPerformanceInformation;
import com.evolveum.midpoint.xml.ns._public.common.common_3.TaskType;
import static com.evolveum.midpoint.testing.story.sysperf.TestSystemPerformance.*;

import java.io.File;
import java.io.FileWriter;
import java.io.IOException;
import java.io.PrintWriter;

import static com.evolveum.midpoint.testing.story.sysperf.TestSystemPerformance.START;
import static com.evolveum.midpoint.testing.story.sysperf.TestSystemPerformance.TARGET_DIR;
import com.evolveum.midpoint.schema.util.task.TaskOperationStatsUtil;
import com.evolveum.midpoint.schema.util.task.TaskPerformanceInformation;
import com.evolveum.midpoint.xml.ns._public.common.common_3.TaskType;

class DetailsOutputFile {

private static final File FILE = new File(TARGET_DIR, START + "-details.txt");
private final PrintWriter writer;

DetailsOutputFile() throws IOException {
writer = new PrintWriter(new FileWriter(FILE));
writer = new PrintWriter(new FileWriter(getFile()));
}

private File getFile() {
return new File(TARGET_DIR, START + "-" + OTHER_PARAMETERS.label + "-details.txt");
}

void logTaskFinish(String desc, TaskType taskAfter, TaskPerformanceInformation performanceInformation) {
Expand Down
12 changes: 7 additions & 5 deletions ...g/story/src/test/java/com/evolveum/midpoint/testing/story/sysperf/ProgressOutputFile.java
View file
@@ -1,25 +1,27 @@
package com.evolveum.midpoint.testing.story.sysperf;

import com.evolveum.midpoint.task.api.Task;
import static com.evolveum.midpoint.testing.story.sysperf.TestSystemPerformance.*;

import java.io.File;
import java.io.FileWriter;
import java.io.IOException;
import java.io.PrintWriter;

import static com.evolveum.midpoint.testing.story.sysperf.TestSystemPerformance.TARGET_DIR;
import static com.evolveum.midpoint.testing.story.sysperf.TestSystemPerformance.START;
import com.evolveum.midpoint.task.api.Task;

class ProgressOutputFile {

static final File FILE = new File(TARGET_DIR, START + "-progress.csv");
private final PrintWriter writer;

ProgressOutputFile() throws IOException {
writer = new PrintWriter(new FileWriter(FILE));
writer = new PrintWriter(new FileWriter(getFile()));
writer.println("test;time;progress");
}

private File getFile() {
return new File(TARGET_DIR, START + "-" + OTHER_PARAMETERS.label + "-progress.csv");
}

void recordProgress(String label, Task task) {
long start = task.getLastRunStartTimestamp();
Long lastFinish = task.getLastRunFinishTimestamp();
Expand Down
21 changes: 17 additions & 4 deletions ...ng/story/src/test/java/com/evolveum/midpoint/testing/story/sysperf/SummaryOutputFile.java
View file
Expand Up @@ -10,23 +10,27 @@

class SummaryOutputFile {

private static final File FILE = new File(TARGET_DIR, START + "-summary.txt");
private final PrintWriter writer;

SummaryOutputFile() throws IOException {
writer = new PrintWriter(new FileWriter(FILE));
writer = new PrintWriter(new FileWriter(getFile()));
}

private File getFile() {
return new File(TARGET_DIR, START + "-" + OTHER_PARAMETERS.label + "-summary.txt");
}

void logStart() {
writer.println("Started: " + new Date(START) + " (" + START + ")");
writer.println("Label: " + OTHER_PARAMETERS.label);
writer.println();
writer.printf("Schema: %s\n", SCHEMA_CONFIGURATION);
writer.printf("Sources: %s\n", SOURCES_CONFIGURATION);
writer.printf("Targets: %s\n", TARGETS_CONFIGURATION);
writer.printf("Roles: %s\n", ROLES_CONFIGURATION);
writer.printf("Import: %s\n", IMPORTS_CONFIGURATION);
writer.printf("Reconciliation: %s\n", RECONCILIATIONS_CONFIGURATION);
writer.printf("Recomputation: %s\n", RECOMPUTATION_CONFIGURATION);
writer.printf("Progress file: %s\n\n", ProgressOutputFile.FILE);
writer.printf("Recomputation: %s\n\n", RECOMPUTATION_CONFIGURATION);
writer.flush();
}

Expand All @@ -36,4 +40,13 @@ void logTaskFinish(String desc, long executionTime, double timePerAccount) {
writer.printf("Time per account: %,.1f ms\n\n", timePerAccount);
writer.flush();
}

void logFinish() {
long end = System.currentTimeMillis();
writer.printf("Finished at: %s\n", new Date(end));
long millis = end - START;
writer.printf("Took: %,.1f seconds = %.1f minutes\n", millis / 1000.0, millis / 60000.0);
writer.printf("Accounts: %,d\n", SOURCES_CONFIGURATION.getNumberOfAccounts());
writer.flush();
}
}
32 changes: 27 additions & 5 deletions ...tory/src/test/java/com/evolveum/midpoint/testing/story/sysperf/TestSystemPerformance.java
View file
Expand Up @@ -24,6 +24,8 @@
import java.util.regex.Pattern;
import java.util.stream.Collectors;

import com.evolveum.midpoint.test.util.TestReportUtil;

import org.apache.commons.collections4.ListUtils;
import org.springframework.test.annotation.DirtiesContext;
import org.springframework.test.context.ContextConfiguration;
Expand Down Expand Up @@ -75,7 +77,7 @@ public class TestSystemPerformance extends AbstractStoryTest implements Performa
static final ReconciliationConfiguration RECONCILIATIONS_CONFIGURATION;
static final RecomputationConfiguration RECOMPUTATION_CONFIGURATION;

private static final OtherParameters OTHER_PARAMETERS;
static final OtherParameters OTHER_PARAMETERS;

private static final List<DummyTestResource> RESOURCE_SOURCE_LIST;
private static final List<DummyTestResource> RESOURCE_TARGET_LIST;
Expand All @@ -94,7 +96,6 @@ public class TestSystemPerformance extends AbstractStoryTest implements Performa

static final long START = System.currentTimeMillis();

private static final String REPORT_FILE_PREFIX = TARGET_DIR_PATH + "/" + START + "-report";
private static final String REPORT_SECTION_SUMMARY_NAME = "summary";
private static final String REPORT_SECTION_TASK_EXECUTION_NAME = "taskExecution";
private static final String REPORT_SECTION_TASK_EXECUTION_DENORMALIZED_NAME = "taskExecutionDenormalized";
Expand Down Expand Up @@ -130,7 +131,11 @@ public class TestSystemPerformance extends AbstractStoryTest implements Performa
TASK_RECONCILIATION_LIST = RECONCILIATIONS_CONFIGURATION.getGeneratedTasks();
TASK_RECOMPUTE = RECOMPUTATION_CONFIGURATION.getGeneratedTask();

System.setProperty(PERF_REPORT_PREFIX_PROPERTY_NAME, REPORT_FILE_PREFIX);
System.setProperty(PERF_REPORT_PREFIX_PROPERTY_NAME, createReportFilePrefix());
}

private static String createReportFilePrefix() {
return TARGET_DIR_PATH + "/" + START + "-" + OTHER_PARAMETERS.label + "-report";
}

public TestSystemPerformance() throws IOException {
Expand Down Expand Up @@ -247,7 +252,6 @@ public void test000LogStart() {
logger.info("Import: {}", IMPORTS_CONFIGURATION);
logger.info("Reconciliation: {}", RECONCILIATIONS_CONFIGURATION);
logger.info("Recomputation: {}", RECOMPUTATION_CONFIGURATION);
logger.info("Progress file: {}", ProgressOutputFile.FILE);

summaryOutputFile.logStart();
}
Expand Down Expand Up @@ -457,6 +461,11 @@ public void test130RecomputeUsers() throws Exception {
logTaskFinish(taskAfter, "");
}

@Test
public void test999Finish() {
logFinish();
}

private long getExecutionTime(PrismObject<TaskType> taskAfter) {
long start = XmlTypeConverter.toMillis(taskAfter.asObjectable().getLastRunStartTimestamp());
long end = XmlTypeConverter.toMillis(taskAfter.asObjectable().getLastRunFinishTimestamp());
Expand All @@ -478,7 +487,9 @@ private void logTaskFinish(PrismObject<TaskType> taskAfter, String label) {

TaskPerformanceInformation performanceInformation = TaskPerformanceInformation.fromTaskTree(taskAfter.asObjectable());
long executionTime = getExecutionTime(taskAfter);
double timePerAccount = (double) executionTime / (double) SOURCES_CONFIGURATION.getNumberOfAccounts();
int executionTimeSeconds = (int) (executionTime / 1000);
int numberOfAccounts = SOURCES_CONFIGURATION.getNumberOfAccounts();
double timePerAccount = (double) executionTime / (double) numberOfAccounts;

logger.info("********** FINISHED: {} **********\n", desc);
logger.info(String.format("Task execution time: %,d ms", executionTime));
Expand All @@ -494,6 +505,17 @@ private void logTaskFinish(PrismObject<TaskType> taskAfter, String label) {
.addRow(dataRow.toArray());
taskExecutionDenormalizedReportSection
.addRow(ListUtils.union(summaryReportDataRow, dataRow).toArray());

TestReportUtil.reportTaskOperationPerformance(testMonitor(), desc, taskAfter.asObjectable(),
numberOfAccounts, executionTimeSeconds);
TestReportUtil.reportTaskRepositoryPerformance(testMonitor(), desc, taskAfter.asObjectable(),
numberOfAccounts, executionTimeSeconds);
TestReportUtil.reportTaskCachesPerformance(testMonitor(), desc, taskAfter.asObjectable());
TestReportUtil.reportTaskProvisioningStatistics(testMonitor(), desc, taskAfter.asObjectable());
}

private void logFinish() {
summaryOutputFile.logFinish();
}

private void recordProgress(String label, Task task) {
Expand Down

0 comments on commit cb41a8e

Please sign in to comment.