TRACE c.g.n.j.statements.EvaluationTask - Warmup error

nagkumar commented 1 year ago

dBLogService.log(
    "Withdrawal of 500.0 made from account 456"
);
-> at com.tejasoft.edu.bank.tests.doubles.mocks.TestBAWMock.testWithdrawWithSufficientBalanceAndAccess(TestBAWMock.java:66)
Actually, there were zero interactions with this mock.

                at com.tejasoft.edu.bank.tests.doubles.mocks.TestBAWMock.testWithdrawWithSufficientBalanceAndAccess(TestBAWMock.java:66)
                at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
                ... 6 common frames omitted
            12:29:38.912 TRACE c.g.n.j.statements.EvaluationTask - Warmup error
            java.lang.reflect.InvocationTargetException: null
                at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:119)
                at java.base/java.lang.reflect.Method.invoke(Method.java:578)
                at com.github.noconnor.junitperf.statements.FullStatement.evaluate(FullStatement.java:37)
                at com.github.noconnor.junitperf.statements.EvaluationTask.evaluateStatement(EvaluationTask.java:80)
                at com.github.noconnor.junitperf.statements.EvaluationTask.run(EvaluationTask.java:60)
                at com.github.noconnor.junitperf.statements.PerformanceEvaluationStatement.lambda$createTask$0(PerformanceEvaluationStatement.java:94)
                at java.base/java.lang.Thread.run(Thread.java:1589)
            Caused by: org.mockito.exceptions.verification.WantedButNotInvoked:
Wanted but not invoked:
dBLogService.log(
    "Withdrawal of 500.0 made from account 456"
);
-> at com.tejasoft.edu.bank.tests.doubles.mocks.TestBAWMock.testWithdrawWithSufficientBalanceAndAccess(TestBAWMock.java:66)
Actually, there were zero interactions with this mock.

                at com.tejasoft.edu.bank.tests.doubles.mocks.TestBAWMock.testWithdrawWithSufficientBalanceAndAccess(TestBAWMock.java:66)
                at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
                ... 6 common frames omitted
            12:29:38.913 TRACE c.g.n.j.statements.EvaluationTask - Warmup error
            java.lang.reflect.InvocationTargetException: null
                at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:119)
                at java.base/java.lang.reflect.Method.invoke(Method.java:578)
                at com.github.noconnor.junitperf.statements.FullStatement.evaluate(FullStatement.java:37)
                at com.github.noconnor.junitperf.statements.EvaluationTask.evaluateStatement(EvaluationTask.java:80)
                at com.github.noconnor.junitperf.statements.EvaluationTask.run(EvaluationTask.java:60)
                at com.github.noconnor.junitperf.statements.PerformanceEvaluationStatement.lambda$createTask$0(PerformanceEvaluationStatement.java:94)
                at java.base/java.lang.Thread.run(Thread.java:1589)
            Caused by: org.mockito.exceptions.verification.WantedButNotInvoked:
Wanted but not invoked:
dBLogService.log(
    "Withdrawal of 500.0 made from account 456"
);

for the code with @JUnitPerfTest(totalExecutions = 1000, rampUpPeriodMs=10000, threads = 20, warmUpMs = 1000)

package com.tejasoft.tests.ju.ju5.ut.perf.noconnor;

import com.github.noconnor.junitperf.JUnitPerfReportingConfig;
import com.github.noconnor.junitperf.JUnitPerfTest;
import com.github.noconnor.junitperf.JUnitPerfTestActiveConfig;
import com.github.noconnor.junitperf.JUnitPerfTestRequirement;
import org.junit.platform.suite.api.SelectPackages;
import org.junit.platform.suite.api.Suite;

import static com.tejasoft.tests.ju.ju5.ut.perf.noconnor.utils.ReportingUtils.newHtmlReporter;

@Suite
@SelectPackages("com.tejasoft")
@JUnitPerfTest(totalExecutions = 1000, rampUpPeriodMs=10000, threads = 20, warmUpMs = 1000)
//@JUnitPerfTest(totalExecutions = 10)
//@JUnitPerfTestRequirement(allowedErrorPercentage = 100)
public final class TestSuitePerfNCR
{
    @JUnitPerfTestActiveConfig
    public static JUnitPerfReportingConfig config =
        JUnitPerfReportingConfig.builder().reportGenerator(newHtmlReporter("ncr_perf_suite_report.html"))
                    .build();
}

noconnor commented 1 year ago

This is just a trace log indicating that there was a failure in the test TestBAWMock.java at line 66 during the warm up phase : Actually, there were zero interactions with this mock.

Errors during the warmup phase are logged at TRACE level but do not count toward your test error count (see definition of warmUpMs here)

nagkumar commented 1 year ago

Errors during the warmup phase are logged at TRACE level but do not count toward your test error count (see definition of warmUpMs here)

15:21:46.592 DEBUG c.g.n.junitperf.JUnitPerfInterceptor - Test already configured
15:21:46.592 DEBUG c.g.n.junitperf.JUnitPerfInterceptor - Test already configured
15:21:46.592 DEBUG c.g.n.junitperf.JUnitPerfInterceptor - Test already configured
15:21:46.593 DEBUG c.g.n.junitperf.JUnitPerfInterceptor - Test already configured
15:21:46.594 INFO  c.g.n.j.r.p.HtmlReportGenerator - Rendering report to: G:\DWork\osource\experiments\java\edu\build\reports\perf\ncr\ncr_perf_suite_report.html
15:21:46.685 INFO  c.g.n.j.r.p.HtmlReportGenerator - Rendering report to: G:\DWork\osource\experiments\java\edu\build\reports\perf\ncr\ncr_perf_suite_report.html
15:21:46.770 INFO  c.g.n.j.r.p.HtmlReportGenerator - Rendering report to: G:\DWork\osource\experiments\java\edu\build\reports\perf\ncr\ncr_perf_suite_report.html
15:21:46.772 TRACE c.g.n.junitperf.JUnitPerfInterceptor - Proceed error
org.opentest4j.AssertionFailedError: expected: <1> but was: <2>
    at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
    at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
    at org.junit.jupiter.api.AssertEquals.failNotEqual(AssertEquals.java:197)
    at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:150)
    at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:145)
    at org.junit.jupiter.api.Assertions.assertEquals(Assertions.java:527)
    at com.tejasoft.edu.bank.tests.doubles.fakes.TestBAWFake.testWithdrawWithInsufficientFunds(TestBAWFake.java:79)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    at java.base/java.lang.reflect.Method.invoke(Method.java:578)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:728)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at com.github.noconnor.junitperf.JUnitPerfInterceptor.proceedQuietly(JUnitPerfInterceptor.java:207)
    at com.github.noconnor.junitperf.JUnitPerfInterceptor.interceptTestMethod(JUnitPerfInterceptor.java:126)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:218)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:214)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:139)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:69)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:202)
    at java.base/java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:194)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.tryRemoveAndExec(ForkJoinPool.java:1350)
    at java.base/java.util.concurrent.ForkJoinTask.awaitDone(ForkJoinTask.java:422)
    at java.base/java.util.concurrent.ForkJoinTask.join(ForkJoinTask.java:651)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService.joinConcurrentTasksInReverseOrderToEnableWorkStealing(ForkJoinPoolHierarchicalTestExecutorService.java:179)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService.invokeAll(ForkJoinPoolHierarchicalTestExecutorService.java:153)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:202)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService.executeNonConcurrentTasks(ForkJoinPoolHierarchicalTestExecutorService.java:172)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService.invokeAll(ForkJoinPoolHierarchicalTestExecutorService.java:152)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:202)
    at java.base/java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:194)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1311)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1841)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1806)
    at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:177)
15:21:46.856 INFO  c.g.n.j.r.p.HtmlReportGenerator - Rendering report to: G:\DWork\osource\experiments\java\edu\build\reports\perf\ncr\ncr_perf_suite_report.html
15:21:46.856 TRACE c.g.n.junitperf.JUnitPerfInterceptor - Proceed error
org.opentest4j.AssertionFailedError: expected: <500.0> but was: <0.0>
    at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
    at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
    at org.junit.jupiter.api.AssertEquals.failNotEqual(AssertEquals.java:197)
    at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:70)
    at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:65)
    at org.junit.jupiter.api.Assertions.assertEquals(Assertions.java:885)
    at com.tejasoft.edu.bank.tests.doubles.fakes.TestBAWFake.testWithdrawWithSufficientFunds(TestBAWFake.java:62)
    at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
    at java.base/java.lang.reflect.Method.invoke(Method.java:578)
    at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:728)
    at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131)
    at com.github.noconnor.junitperf.JUnitPerfInterceptor.proceedQuietly(JUnitPerfInterceptor.java:207)
    at com.github.noconnor.junitperf.JUnitPerfInterceptor.interceptTestMethod(JUnitPerfInterceptor.java:126)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147)
    at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestMethod(TimeoutExtension.java:86)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45)
    at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92)
    at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:218)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:214)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:139)
    at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:69)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at org.junit.platform.engine.support.hierarchical.ForkJoinPoolHierarchicalTestExecutorService$ExclusiveTask.compute(ForkJoinPoolHierarchicalTestExecutorService.java:202)
    at java.base/java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:194)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:387)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1311)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1841)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1806)

I have used just `@JUnitPerfTest(totalExecutions = 10)'

however junit reports show everything as passed.. but above asserts are shown in console output..

How is this possible..

noconnor commented 1 year ago

The only way this is possible is if an error is thrown after the parallel evaluation completes

If this is the case, it would mean the test ran successfully 10 times and then failed on the call to proceed. If there was a failure during the test execution, then the runParallelExecution would have failed (unless allowedErrorPercentage was set to a non zero value)

If you can consistently produce this error with a sample code block i would be able to debug further.

noconnor / JUnitPerf

TRACE c.g.n.j.statements.EvaluationTask - Warmup error #109