Feature #11317
Implementing multi-threaded parsing
100%
Related issues
History
#1 Updated by Octavian Adrian Gavril 7 months ago
- Related to Feature #3211: implement multi-threaded pattern engine and rework the ConversionDriver to leverage it added
#2 Updated by Greg Shah about 2 months ago
- Related to Bug #3833: Conversion broken by multithreading added
#3 Updated by Alexandru Lungu about 1 month ago
- Assignee set to Octavian Adrian Gavril
While testing the latest trunk with changes from #3211, I saw several times threads blocking on public static synchronized int lookupTokenType(String tokenName) from ProgressParser. This is quite important as it is called by BinaryAstCodec.readNode. When I did a thread dump for a conversion with 16 threads, most of them were loading ASTs with BinaryAstCodec. As loading means looking up token types, the lookupTokenType made the threads constantly wait for the monitor at each token read.
Why would lookupTokenType be syncrhonized. I understand that tokenLookup is lazily computed, but it is computed only once, as it is a static collection. After that, all threads need to read from that map without contention. Currently they block each other when reading from tokenLookup.
Can we compute lookupTokenType only once at the bootstrap time and eliminate the synchronized when looking up token type? It is the only synchronization inside ProgressParser AFAIK.
I would expect to be a quick fix for a large gain.
#4 Updated by Greg Shah about 1 month ago
Octavian: Let's go ahead with #11317-3 immediately, without addressing the larger threading issue.
#5 Updated by Octavian Adrian Gavril about 1 month ago
Created task branch 11317a.
#6 Updated by Octavian Adrian Gavril about 1 month ago
- % Done changed from 0 to 100
- Status changed from New to WIP
I've committed the change in 11317a/16735.
#7 Updated by Octavian Adrian Gavril about 1 month ago
- Status changed from WIP to Review
- reviewer Alexandru Lungu added
Alex, please review. I have tested it with Hotel_GUI so far.
#8 Updated by Alexandru Lungu about 1 month ago
- Status changed from Review to Internal Test
Review of 11317a:
- I am OK with the changes.
Please run a large customer application to check if there is any visible performance improvement and regression test at the same time. IMHO, it is a (very) safe change, so one large application test should be enough.
#9 Updated by Octavian Adrian Gavril about 1 month ago
The large customer application completed successfully. I got 3h13m with 11317a and 2h54m with trunk/16731. There are no differences between the generated outputs. I ran both using 16 threads and a 24G conversion heap. Here are my machine's specifications: Show
#10 Updated by Octavian Adrian Gavril about 1 month ago
The time difference was unexpected, so I checked for potential causes. I found that the conversion with 11317a ran with the debug agent enabled, which likely explains the variance. I'll rerun the conversion to confirm.
#11 Updated by Octavian Adrian Gavril about 1 month ago
I ran both conversions again. The one with 11317a took 2h56m, and the one with trunk took 2h52m. The results are more expected now. There's still no noticeable performance improvement, but the execution times are virtually the same.
#12 Updated by Alexandru Lungu 29 days ago
- Status changed from Internal Test to Merge Pending
Please merge 11317a to trunk now.
#13 Updated by Octavian Adrian Gavril 29 days ago
- Status changed from Merge Pending to WIP
- % Done changed from 100 to 0
Branch 11317a was merged into trunk as rev. 16753 and archived.
Moved back to WIP and 0% Done for the rest of the work that needs to be done.
#14 Updated by Alexandru Lungu 29 days ago
- File locks2.png added
- File locks.png added
Octavian, I am still running trunk/16749, but I found a similar problem that might not be assessed by 11317a:

I am not entirely sure what was the phase the is being run when this was captured. On a thread dump, I see:
"Conversion-Thread-2" #36 prio=5 os_prio=0 cpu=74657,68ms elapsed=169,18s tid=0x00007542d5f87e30 nid=0xe4a2 waiting on condition [0x00007542363f2000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@17.0.20/Native Method)
- parking to wait for <0x000000042080fec8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(java.base@17.0.20/LockSupport.java:211)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.20/AbstractQueuedSynchronizer.java:715)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.20/AbstractQueuedSynchronizer.java:938)
at java.util.concurrent.locks.ReentrantLock$Sync.lock(java.base@17.0.20/ReentrantLock.java:153)
at java.util.concurrent.locks.ReentrantLock.lock(java.base@17.0.20/ReentrantLock.java:322)
at com.goldencode.ast.XmlFilePlugin.loadTree(XmlFilePlugin.java:287)
at com.goldencode.ast.AstManager.loadTree(AstManager.java:373)
at com.goldencode.p2j.pattern.AstSymbolResolver.loadTree(AstSymbolResolver.java:362)
at com.goldencode.p2j.pattern.AstSymbolResolver.getAst(AstSymbolResolver.java:417)
at com.goldencode.p2j.pattern.CommonAstSupport$Library.getAst(CommonAstSupport.java:1653)
at com.goldencode.p2j.pattern.CommonAstSupport$Library.getAst(CommonAstSupport.java:1635)
at com.goldencode.expr.CE904.execute(Unknown Source)
at com.goldencode.expr.Expression.execute(Expression.java:410)
at com.goldencode.p2j.pattern.Rule.apply(Rule.java:501)
at com.goldencode.p2j.pattern.Rule.executeActions(Rule.java:792)
at com.goldencode.p2j.pattern.Rule.coreProcessing(Rule.java:758)
at com.goldencode.p2j.pattern.Rule.apply(Rule.java:538)
at com.goldencode.p2j.pattern.RuleContainer.apply(RuleContainer.java:665)
at com.goldencode.p2j.pattern.AstWalker.walk(AstWalker.java:262)
at com.goldencode.p2j.pattern.AstWalker.walk(AstWalker.java:210)
at com.goldencode.p2j.pattern.PatternEngine.apply(PatternEngine.java:1834)
at com.goldencode.p2j.pattern.PatternEngine.processAst(PatternEngine.java:1718)
at com.goldencode.p2j.pattern.AstProcessorJob.run(AstProcessorJob.java:255)
at com.goldencode.p2j.pattern.AstProcessorThread.run(AstProcessorThread.java:140)
Locked ownable synchronizers:
- None
"Conversion-Thread-3" #37 prio=5 os_prio=0 cpu=75887,58ms elapsed=169,18s tid=0x00007542d5f07cb0 nid=0xe4a3 waiting on condition [0x00007542888f4000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@17.0.20/Native Method)
- parking to wait for <0x000000042080fec8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(java.base@17.0.20/LockSupport.java:211)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.20/AbstractQueuedSynchronizer.java:715)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.20/AbstractQueuedSynchronizer.java:938)
at java.util.concurrent.locks.ReentrantLock$Sync.lock(java.base@17.0.20/ReentrantLock.java:153)
at java.util.concurrent.locks.ReentrantLock.lock(java.base@17.0.20/ReentrantLock.java:322)
at com.goldencode.ast.XmlFilePlugin.loadTree(XmlFilePlugin.java:287)
at com.goldencode.ast.AstManager.loadTree(AstManager.java:373)
at com.goldencode.p2j.pattern.AstSymbolResolver.loadTree(AstSymbolResolver.java:362)
at com.goldencode.p2j.pattern.AstSymbolResolver.getAst(AstSymbolResolver.java:417)
at com.goldencode.p2j.pattern.CommonAstSupport$Library.getAst(CommonAstSupport.java:1653)
at com.goldencode.p2j.pattern.CommonAstSupport$Library.getAst(CommonAstSupport.java:1635)
at com.goldencode.expr.CE904.execute(Unknown Source)
at com.goldencode.expr.Expression.execute(Expression.java:410)
at com.goldencode.p2j.pattern.Rule.apply(Rule.java:501)
at com.goldencode.p2j.pattern.Rule.executeActions(Rule.java:792)
at com.goldencode.p2j.pattern.Rule.coreProcessing(Rule.java:758)
at com.goldencode.p2j.pattern.Rule.apply(Rule.java:538)
at com.goldencode.p2j.pattern.RuleContainer.apply(RuleContainer.java:665)
at com.goldencode.p2j.pattern.AstWalker.walk(AstWalker.java:262)
at com.goldencode.p2j.pattern.AstWalker.walk(AstWalker.java:210)
at com.goldencode.p2j.pattern.PatternEngine.apply(PatternEngine.java:1834)
at com.goldencode.p2j.pattern.PatternEngine.processAst(PatternEngine.java:1718)
at com.goldencode.p2j.pattern.AstProcessorJob.run(AstProcessorJob.java:255)
at com.goldencode.p2j.pattern.AstProcessorThread.run(AstProcessorThread.java:140)
Locked ownable synchronizers:
- None
So, again, there seems to be a contention on AST loading. The locks are delivered by:
ReentrantLock lock = LOCK_CACHE.computeIfAbsent(artifact.getRelativePath(), k -> new ReentrantLock());
- It is weird why all threads want the same artifact almost at the same time. Maybe they require schema p2o (that are only very few).
- The whole situation takes ~4 minutes in a conversion of 20 minutes. After these 4 minutes, another phase kicks in and it works fast again.
However, after around 10 minutes in which all threads are working in parallel, I face this issue again:

On thread dumps I see the same stack traces.
I was wondering why we would need to synchronize the loading of these ASTs? From the looks of it, the process is immutable so it doesn't need synchronization. The same locks are shared indeed with saveTree and persist, but I guess we can use a ReadWriteReentrantLock instead to allow concurrent reads.
As a side idea, I wonder if we can keep a static cache of ASTs to be reused directly from memory. So, instead of flushing to disk and reading again, to have a small cache in-memory to keep the most used ASTs (schema ASTs I suppose are one of them, but super-classes used anywhere can fit as well). We need to avoid thrashing such cache with one-time asts, so maybe we can also persist a "hit count" and if the hit count exceeds a threshold to also save the ASTs in a memory registry.
#15 Updated by Octavian Adrian Gavril 29 days ago
I'll start experimenting based on your ideas.
#16 Updated by Alexandru Lungu 29 days ago
As a side idea, I wonder if we can keep a static cache of ASTs to be reused directly from memory. So, instead of flushing to disk and reading again, to have a small cache in-memory to keep the most used ASTs (schema ASTs I suppose are one of them, but super-classes used anywhere can fit as well). We need to avoid thrashing such cache with one-time asts, so maybe we can also persist a "hit count" and if the hit count exceeds a threshold to also save the ASTs in a memory registry.
Don't force the cache now. It may be a small gain. The ReadWriteReentrantLock may be major.
#17 Updated by Alexandru Lungu 28 days ago
Some context on a similar project as the one above.
- Parser: 8m32s (I know this is not multi-threaded)
- Post-parse fix-ups: 47s (can't tell why this is so slow)
- Early annotations: 2m09s -> this was the phase from which I extracted the first image above
- Gap analysis: 15s
- Schema fix-ups: 2s
- Schema annotations: 6s
- Preprocess P2O: 5s
- P2O Generation: 13s
- P2O post-processing: 2s
- Generate DMO: 10s
- Generate Java DMO: 11s
- Unreachable Code 10s
- Code Conversion Anno Prep: 17s
- Code Conversion Annotations: 10m53s -> this was the phase from which I extracted the second image above
- Frame generator: 13s
- Business Logic Base Structure: 28s
- Core Code Conversion: 2m2s -> this is all green, no locking. It is pure TRPL work (most threads are in
RuleContainer.apply) - Generate Java: 19s
I may have missed some phases, but they were most probably < 10s.
#18 Updated by Octavian Adrian Gavril 27 days ago
I have tested the changes with ReentrantReadWriteLock, but it's really hard to see any noticeable improvement. I think performance strongly depends on the project and how it is structured, as we might be dealing with more dependencies between artifacts.
Alex, could you provide the Utilizing N concurrent thread(s) to process M file(s); K CPU(s), H MiB heap log message if it is still available?
#19 Updated by Alexandru Lungu 27 days ago
Utilizing 16 concurrent thread(s) to process 6800 file(s); 16 CPU, 16384 MiB heap.
This is what I have.
#20 Updated by Alexandru Lungu 27 days ago
I have tested the changes with ReentrantReadWriteLock, but it's really hard to see any noticeable improvement. I think performance strongly depends on the project and how it is structured, as we might be dealing with more dependencies between artifacts.
Feel free to commit the changes, I can test them and let you know if I see an improvement on it.
#21 Updated by Octavian Adrian Gavril 27 days ago
Alexandru Lungu wrote:
Feel free to commit the changes, I can test them and let you know if I see an improvement on it.
Created task branch 11317b.
I've committed the changes in 11317b/16762.
#22 Updated by Octavian Adrian Gavril 19 days ago
- % Done changed from 0 to 100
- Status changed from WIP to Review
conversion threads:
- I found a bug in the way the keys for the locks are computed. At first glance there are
two places that useartifact.getRelativePath()and one that usedtarget.toString(). The
one withtarget.toString()is not a problem, because it is only used forcfg/registry.xml; for that one I had to implement a safe read path as well. The real issue
is with classes: the reads are done with keys based on the artifacts incvt(which is
correct), while the writes were made with keys based on artifacts inabl, where no reader
ever looks. The root cause wasprocessClassVariables, which computed the wrong key by
concatenation instead of usingArtifactManager.getPathToProjectFolder. As a result, we
ended up with unused.cls.astfiles whereverprocessClassVariableswas involved and, of
course, with a locking mechanism that protected nothing; - In
AnnotatedAstI took the annotation key cache off a single monitor and offString.intern(); - I added
loadTreeHeaderandreadHeaderto avoid decoding an entire tree for just a few
pieces of information, such asCLASS_DEFandINTERFACE_DEF. These are used inTransformDriver.sortLegacyClassesandAstProcessorJob.run(); - I removed three monitors that guarded context-local state;
- I fixed
PatternEngine.addThreadJobAndWaitso that it runs the job on the main thread
when the pool is empty.
process is now green, and here are some metrics from my local machine:
- Total time was 18 minutes with trunk and 13 minutes with 11317b;
Early Annotationsfinished in 1m38s with trunk and in 38s with 11317b;Code Conversion Annotationscompleted in 7m53s with trunk and in 4m43s with
11317b.
So the main gains are in Early Annotations and Code Conversion Annotations.
All of these are committed in 11317b/16763.
Alex, please review.
#23 Updated by Alexandru Lungu 16 days ago
- I am not entirely sure
AnnotatedAst.javachange is reasonable. Please do a bzr blame to check the author of theCollections.synchronizedMap(new IdentityHashMap<>())data structure in the first place. The goal of theinternwas exactly to force == comparison instead of .equals. As you runConcurrentHashMapandString lower = ANNO_LOWER.get(anno);, theannonot being internalized, it will be often compared withequalscharacter by character. Please check the OG task that addedIdentityHashMapand add the author as a watcher to review. I would prefer some benchmark tho for this decision (16 threads thrashing such data structure).- TBH, a synchronized collection here might be a dead weight. I can't understand why a simple
toLowerCasewon't work faster in a multi-threaded environment, then a synchronized structure. The annotation keys are short and ASCII usually, so paying a monitor price seems too much.
- TBH, a synchronized collection here might be a dead weight. I can't understand why a simple
loadTreeHeaderis a reasonable change.
+ if (ast == null)
+ {
+ // no class or interface definition in there, nothing to do
+ return;
+ }
- this is a new path that was not considered before. Isn't this a fatal case that should throw?
- Or log?
- Or fallback to
Aast ast = mgr.loadTree(artifact);?
- Also, the upcoming
Aast def = ast.getImmediateChild(ProgressParserTokenTypes.CLASS_DEF, null);assumes that the header reads classes, but I guess it can also read interfaces according to the header reading implementation. CLASS_TREE_POSTFIX = ".cls.ast";assumes that an artifact ending with.cls.astis an OO class AST. I think this is correct, but this should be tested (can a class be defined in a.p.astor something like.class.ast? I guess not, I never saw this, but such hard-coded value should be rather confirmed.- I would have liked something like
CLASS_POSTFIX+ . +AST_POSTFIX. AFAIK, the AST_POSTFIX can be configurable (?)
- I would have liked something like
- Please compress the history entries to keep them usually one-line; any extra information should rather go in javadocs.
- The code in
CommonAstSupport.javais no longer synchronized. Please triple check that all the users are properly locked and there are no other synchronized orsynchronize(this)in the class or sub-class or asynchronized (support)(instance wide locking) that could share the same monitor.
#24 Updated by Octavian Adrian Gavril 14 days ago
Alexandru Lungu wrote:
- I am not entirely sure
AnnotatedAst.javachange is reasonable. Please do a bzr blame to check the author of theCollections.synchronizedMap(new IdentityHashMap<>())data structure in the first place. The goal of theinternwas exactly to force == comparison instead of .equals. As you runConcurrentHashMapandString lower = ANNO_LOWER.get(anno);, theannonot being internalized, it will be often compared withequalscharacter by character. Please check the OG task that addedIdentityHashMapand add the author as a watcher to review. I would prefer some benchmark tho for this decision (16 threads thrashing such data structure).
The behaviour is the same as with trunk: the returned key is still the canonical, interned instance for every annotation. It is faster only because the lookup into ANNO_LOWER no longer has to intern its argument on every call and interning now happens once, when the entry is first stored. The canonical instance is what annotations needs, since that one is an IdentityHashMap. The cache in front of it does not have to be an IdentityHashMap as well.
| input | trunk | 11317b | gain |
|---|---|---|---|
| literal keys | ~45 ns/op | ~0.9 ns/op | ~50x |
| fresh keys | ~51 ns/op | ~4.1 ns/op | ~12x |
Constantin managed this area in 8363g. Constantin, what do you think?
- TBH, a synchronized collection here might be a dead weight. I can't understand why a simple
toLowerCasewon't work faster in a multi-threaded environment, then a synchronized structure. The annotation keys are short and ASCII usually, so paying a monitor price seems too much.
I think that toLowerCase would make getAnnotationKey return non-canonical keys and there will be additional entries in annotations map since it's an IdentityHashMap.
loadTreeHeaderis a reasonable change.[...]
- this is a new path that was not considered before. Isn't this a fatal case that should throw?
- Or log?
- Or fallback to
Aast ast = mgr.loadTree(artifact);?
This path isn't new. The old implementation silently returned in the same case, just further down. It's related to the next review item.
- Also, the upcoming
Aast def = ast.getImmediateChild(ProgressParserTokenTypes.CLASS_DEF, null);assumes that the header reads classes, but I guess it can also read interfaces according to the header reading implementation.
Yes, it does, but further down, after the header is read:
Aast def = ast.getImmediateChild(ProgressParserTokenTypes.CLASS_DEF, null); Aast header = null; if (def == null) { def = ast.getImmediateChild(ProgressParserTokenTypes.INTERFACE_DEF, null); if (def == null) { // must be an enum, nothing to do return; }
CLASS_TREE_POSTFIX = ".cls.ast";assumes that an artifact ending with.cls.astis an OO class AST. I think this is correct, but this should be tested (can a class be defined in a.p.astor something like.class.ast? I guess not, I never saw this, but such hard-coded value should be rather confirmed.
- I would have liked something like
CLASS_POSTFIX+ . +AST_POSTFIX. AFAIK, the AST_POSTFIX can be configurable (?)- Please compress the history entries to keep them usually one-line; any extra information should rather go in javadocs.
I fixed these in 11317b/16764. I also replaced the hard-coded value from TransforDriver as well and used configured file extensions.
- The code in
CommonAstSupport.javais no longer synchronized. Please triple check that all the users are properly locked and there are no other synchronized orsynchronize(this)in the class or sub-class or asynchronized (support)(instance wide locking) that could share the same monitor.
All three methods I removed synchronized from (classForName, create, nextSequenceValue) only touch context-local state, so the monitor was serializing every conversion thread for nothing. I rechecked the users and every other synchronized in the class: the rest lock a collection or a parameter rather than the Library instance, and there is no sub-class. The only two that do take that monitor are processClassVariables and processClassBuffers, and they are fine as they are: they reach the shared TRPL globals, the AST and the persisted tree, which is not in conflict with the context-local state the three methods touch, so nothing was relying on them being mutually exclusive.
#25 Updated by Alexandru Lungu 7 days ago
Constantin managed this area in 8363g. Constantin, what do you think?
Constantin, please assess. IMHO, I am fine to remove the .intern calls as they (might) be slower than actual keys and equals, considering annotations are short(ish) and alphanumerical.
Otherwise, I am ok with the changes in 11317b and I would like to proceed with Testing.