[PR] Cut testIntegration runtime(from ~86s to ~57s) and fix a service ECA cache race [ofbiz-framework]

["ashishvijaywargiya (via GitHub)" <gi...@apache.org>]

ashishvijaywargiya opened a new pull request, #1805:
URL: https://github.com/apache/ofbiz-framework/pull/1805

   Two of EntityTestSuite's transaction-timeout tests slept 20s and 10s with a much larger margin than needed; scaled both down 5x while keeping the same relative safety margin.
   
   Also found and fixed a real concurrency bug in ServiceEcaUtil: readConfig() had a non-atomic check-then-act guard, and ServiceDispatcher's constructor calls it unconditionally on every dispatcher it creates. With dozens of test dispatchers constructed within milliseconds of each other at startup, several threads could race to rebuild the shared ECA rule cache at once, corrupting the plain HashMap/LinkedList structures mergeEcaDefinitions mutates in place. Any service call iterating those rules concurrently (evalRules) could then throw a NullPointerException from a corrupted LinkedList node.
   
   Fixed by serializing all writes to the cache behind a lock, and switching the per-service/per-event collections to ConcurrentHashMap/CopyOnWriteArrayList so the hot, unsynchronized evalRules() read path stays safe even while a write is in progress. That in turn let the artificial 5s wait in secas_test_se.xml (previously load-bearing, masking the race) come down to 500ms.
   
   Full run: ~86s down to ~57s.


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: notifications-unsubscribe@ofbiz.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org

Re: [PR] Cut testIntegration runtime(from ~86s to ~57s) and fix a service ECA cache race [ofbiz-framework]

["ashishvijaywargiya (via GitHub)" <gi...@apache.org>]

ashishvijaywargiya merged PR #1805:
URL: https://github.com/apache/ofbiz-framework/pull/1805


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: notifications-unsubscribe@ofbiz.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org

Re: [PR] Cut testIntegration runtime(from ~86s to ~57s) and fix a service ECA cache race [ofbiz-framework]

["ashishvijaywargiya (via GitHub)" <gi...@apache.org>]

ashishvijaywargiya commented on PR #1805:
URL: https://github.com/apache/ofbiz-framework/pull/1805#issuecomment-5453216760

   I was looking to speed up "./gradlew testIntegration" - see if it's getting stuck anywhere, and try to shave off something like 30-40% of the run time.
   
   Few months back, the testIntegration run used to take around 2 minute 30+ seconds. And after upgrade from JUnit3 to JUnit5 Jupiter, the run time has significantly reduced to 1 minute 25 seconds. And after this change it reduced to 56 to 58 seconds.
   
   Starting point for this round: a full testIntegration run took about 86.2 seconds of actual test execution (measured from the first to the last timestamped log line, so server startup through shutdown, not counting the few extra seconds of surrounding Gradle task overhead).
   
   Digging into the slowdown
   
   I parsed the run log's timestamps looking for the biggest gaps between consecutive lines, and worked out a per-suite duration by diffing consecutive "Results for test suite: X" markers. That turned up:
   
   - entitytests alone was eating 31 of the 86 seconds - about 36% of the whole run.
   
   - Almost all of that was two Thread.sleep() calls in EntityTestSuite that test transaction-timeout behavior. testTransactionUtilMoreThanTimeout does TransactionUtil.begin(10) (10s timeout) then sleeps 20s - 2x the timeout. testTransactionUtilLessThanTimeout does the opposite: setTransactionTimeout(20) then sleeps 10s, same 2x margin.
   
   - There's also a 5 second sleep in framework/service/servicedef/secas_test_se.xml, right after testServiceEcaGlobalEventExec returns, to "allow time for the global ecas above to complete before the xml assertion test is run" - basically a fixed sleep being used to sync up two async listener threads.
   
   - Outside of these three spots I couldn't find any gap bigger than ~1s - everything else is real service/DB work, not idle waiting.
   
   What I changed
   
   1. Transaction-timeout tests (EntityTestSuite.java)
   
   Scaled both timeout/sleep pairs down 5x, keeping the same 2x safety margin:
   - testTransactionUtilMoreThanTimeout: 10s timeout / 20s sleep -> 2s / 4s
   - testTransactionUtilLessThanTimeout: 20s timeout / 10s sleep -> 4s / 2s
   
   Ran it multiple times after the change, 667/667 passing every time. This alone brought entitytests down from ~31s to ~7s.
   
   2. Found and fixed a real race condition in ServiceEcaUtil
   
   Next up I dropped the 5s ECA wait in secas_test_se.xml to 500ms, half expecting it to just turn out "too aggressive". Instead it exposed a real, pre-existing concurrency bug - 8 unrelated suites (WorkEffortTests, ProductionRunTests, AccountingTests, ScrumTests, and a few more) started failing with:
   
   java.lang.NullPointerException: Cannot read field "next" because "this.next" is null
       at java.base/java.util.LinkedList$ListItr.next(LinkedList.java:904)
       at org.apache.ofbiz.service.eca.ServiceEcaUtil.evalRules(ServiceEcaUtil.java:195)
   
   Traced it back and confirmed the root cause with actual log evidence, not just a hunch:
   
   - ServiceDispatcher's constructor calls ServiceEcaUtil.readConfig() every time it creates a dispatcher.
   
   - readConfig()'s guard was just "if (isNotEmpty(ecaCache)) return;" - a plain check-then-act with no locking around it.
   
   - At test-suite discovery time, all 45 test suites each spin up their own dispatcher pair (one directly, one async via EntityServiceFactory on ExecutionPool.GLOBAL_BATCH threads for the entity-ECA handler), so you get dozens of ServiceDispatcher constructions firing within milliseconds of each other, on different threads, right at startup.
   
   - Grepping the log for "Loaded ... Service ECA Rules from <file>" showed every single secas.xml file getting loaded 4 times, on 4 different threads, all within about 300ms. That's the proof it's a real race, not a one-off.
   
   - mergeEcaDefinitions() mutates the cache's per-service HashMap and per-event LinkedList in place (remove/add plus a HashMap.put on a shared instance) with no synchronization at all. Two threads hitting that at the same time can corrupt the LinkedList's internal links, and any third thread iterating that same list through evalRules() - which runs on basically every service call in the system - can then blow up with the NPE above.
   
   Fix is in framework/service/src/main/java/org/apache/ofbiz/service/eca/ServiceEcaUtil.java:
   
   - Added a CONFIG_LOCK around every write path (readConfig, reloadConfig, addEcaDefinitions), with a fast unlocked check plus a re-check under the lock (double-checked locking), so the normal case - cache already populated - stays lock-free.
   
   - Switched the per-service map from HashMap to ConcurrentHashMap, and the per-event rules list from LinkedList to CopyOnWriteArrayList. Needed this on top of the lock because evalRules() is a hot read path that intentionally does not take CONFIG_LOCK, so the collections themselves have to survive a reader iterating while a writer (holding the lock) mutates them.
   
   Verified by re-running the exact conditions that broke before (500ms wait) twice: 667/667 passing, 0 NPEs, both times. Duplicate secas.xml loads dropped from 4 to 2, and those remaining 2 are sequential/non-overlapping - a separate, legitimate reload path, not a race. checkstyleMain and checkstyleTest both pass clean too.
   
   Since the race is fixed now, I kept the wait in secas_test_se.xml at 500ms (down from 5000ms) - it's not masking anything anymore.
   
   Result
   
   86.2s baseline -> 57.1s after both fixes, ~33.8% reduction, all 667 tests passing. Run-to-run timing does jump around a bit from normal system noise - I saw as much as 15-18s of variance between two identical unmodified baseline runs, for reference.
   
   Two full local gradlew testIntegration runs bracket this change. Before this PR (but after the earlier JUnit Jupiter 5 migration):
   
   Tests: 667, Passed: 667, Failed: 0, Errors: 0, Skipped: 0
   BUILD SUCCESSFUL in 1m 25s
   28 actionable tasks: 9 executed, 19 up-to-date
   
   After this Branch/PR:
   
   Tests: 667, Passed: 667, Failed: 0, Errors: 0, Skipped: 0
   BUILD SUCCESSFUL in 58s
   28 actionable tasks: 9 executed, 19 up-to-date
   
   So on top of what the Jupiter migration already saved, this changes gets testIntegration down from ~1m25s to ~56-58s.
   
   I am merging this into trunk now and will keep watching the performance issues if it's reported by someone on the mailing list. I will rollback my changes from this PR and will plan out more improvements in the approach I took here.


-- 
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.

To unsubscribe, e-mail: notifications-unsubscribe@ofbiz.apache.org

For queries about this service, please contact Infrastructure at:
users@infra.apache.org