Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
nagkumar opened this issue Jun 30, 2023 · 3 comments
Open

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

nagkumar opened this issue Jun 30, 2023 · 3 comments

Comments

@nagkumar
Copy link

nagkumar commented Jun 30, 2023 •
edited
Loading 

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
Copy link
Owner

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
Copy link
Author

nagkumar commented Jun 30, 2023 •
edited
Loading

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

@noconnor
Copy link
Owner

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@nagkumar @noconnor