JUnitPerf icon indicating copy to clipboard operation
JUnitPerf copied to clipboard
verified publisher icon noconnor

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

Open nagkumar opened this issue 2 years ago • 3 comments 

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();
}

nagkumar avatar Jun 30 '23 07:06 nagkumar

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)

noconnor avatar Jun 30 '23 08:06 noconnor

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..

image

image

How is this possible..

nagkumar avatar Jun 30 '23 10:06 nagkumar

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 avatar Jun 30 '23 10:06 noconnor