Terrible Golang performance

[movelazar]

Stackoverflow: https://stackoverflow.com/questions/72266899/golang-performance-issues

Google group: https://groups.google.com/g/antlr-discussion/c/OdhAIsy2GfI

Example code: https://github.com/movelazar/perf-repro

A simple rule such as:

1 EQ 2 OR
1 EQ 2 OR
1 EQ 2 OR
1 EQ 2 OR
1 EQ 2

takes exponentially longer to parse the more 1 EQ 2 OR clauses there are. This does not happen in python (by my testing) or CSharp, Dart, Java (by stackoverflow comment).

On my machine, # of lines vs parse time:

11: 0.5s
12: 1.2s
13: 3.2s
14: 8.1s
15: 21.9s
16: 57.5s

Given that Python doesn't face this issue I can't imagine I'm doing something terrible in my grammar.

Issue goes away if I put parens on things but that's not a real solution.

On 4.10.1, first noticed with 4.9.1.

Any help is greatly appreciated. Surprised I can't find others with this issue.

[movelazar]

Copying an insightful comment from Stackoverflow:

profiling your bench it appears that this package spends a great amount of time within some internals github.com/antlr/antlr4/runtime/Go/antlr.(*ParserATNSimulator).closureWork:1091. Doing that, it allocates a lot, then it does it again. Somtimes it adds a node to its tree. You can easily observe that by yourself running the trace utility pkg.go.dev/runtime/trace

[kaby76]

Copying an insightful comment from Stackoverflow:

profiling your bench it appears that this package spends a great amount of time within some internals github.com/antlr/antlr4/runtime/Go/antlr.(*ParserATNSimulator).closureWork:1091. Doing that, it allocates a lot, then it does it again. Somtimes it adds a node to its tree. You can easily observe that by yourself running the trace utility pkg.go.dev/runtime/trace

Does anyone know how to use the ggprof utility? The instructions referenced are some of the worse I've ever seen in 40 years. It took me hours to read past the incomplete instructions, syntactically invalid code given, and improper use of standard software engineering terminology, to construct a working parser driver program that sets up a server and turns on "profiling". And even then, "top10" shows diddly squat:

(pprof) top10
Showing nodes accounting for 10ms, 100% of 10ms total
      flat  flat%   sum%        cum   cum%
      10ms   100%   100%       10ms   100%  runtime.stdcall6
         0     0%   100%       10ms   100%  runtime.findrunnable
         0     0%   100%       10ms   100%  runtime.mcall
         0     0%   100%       10ms   100%  runtime.netpoll
         0     0%   100%       10ms   100%  runtime.park_m
         0     0%   100%       10ms   100%  runtime.schedule
(pprof)

I still cannot determine if ggprof is a profiling tool or a tracing tool or both. I still cannot understand why the program actually needs to be modified at all in order to perform profiling aka "sampling" at fixed intervals and recording a stack trace.

[kaby76]

I changed test to use a larger example boolean expression, and redid the run--which gives wildly different results every time--and only this one run outputted more useful results:

(pprof) top111
Showing nodes accounting for 9.50s, 87.16% of 10.90s total
Dropped 134 nodes (cum <= 0.05s)
Showing top 111 nodes out of 115
      flat  flat%   sum%        cum   cum%
     2.06s 18.90% 18.90%      2.06s 18.90%  runtime.stdcall2
     1.27s 11.65% 30.55%      6.20s 56.88%  github.com/antlr/antlr4/runtime/Go/antlr.(*ParserATNSimulator).closureWork
     0.69s  6.33% 36.88%      0.69s  6.33%  runtime.stdcall1
     0.56s  5.14% 42.02%      2.03s 18.62%  runtime.mallocgc
     0.51s  4.68% 46.70%      0.71s  6.51%  runtime.heapBitsSetType
     0.36s  3.30% 50.00%      2.52s 23.12%  github.com/antlr/antlr4/runtime/Go/antlr.(*ParserATNSimulator).getEpsilonTarget
     0.27s  2.48% 52.48%      0.27s  2.48%  runtime.nextFreeFast (inline)
     0.22s  2.02% 54.50%      0.27s  2.48%  runtime.mapaccess1_fast64
     0.20s  1.83% 56.33%      1.67s 15.32%  github.com/antlr/antlr4/runtime/Go/antlr.NewBaseATNConfig
     0.17s  1.56% 57.89%      6.20s 56.88%  github.com/antlr/antlr4/runtime/Go/antlr.(*ParserATNSimulator).closureCheckingStopState
     0.16s  1.47% 59.36%      0.57s  5.23%  runtime.scanobject
     0.15s  1.38% 60.73%      0.15s  1.38%  runtime.memclrNoHeapPointers
     0.15s  1.38% 62.11%      0.15s  1.38%  runtime.stdcall3
     0.14s  1.28% 63.39%      0.21s  1.93%  runtime.heapBitsForAddr (inline)
     0.14s  1.28% 64.68%      0.14s  1.28%  runtime.markBits.isMarked (inline)
     0.13s  1.19% 65.87%      0.13s  1.19%  runtime.(*itabTableType).find
     0.13s  1.19% 67.06%      0.13s  1.19%  runtime.stdcall6
     0.12s  1.10% 68.17%      1.74s 15.96%  github.com/antlr/antlr4/runtime/Go/antlr.(*BaseATNConfigSet).Add
     0.11s  1.01% 69.17%      0.13s  1.19%  github.com/antlr/antlr4/runtime/Go/antlr.(*ParserATNSimulator).canDropLoopEntryEdgeInLeftRecursiveRule
     0.10s  0.92% 70.09%      0.12s  1.10%  runtime.findObject
     0.10s  0.92% 71.01%      0.26s  2.39%  runtime.greyobject
     0.09s  0.83% 71.83%      0.09s  0.83%  github.com/antlr/antlr4/runtime/Go/antlr.(*BaseATNState).GetTransitions
     0.08s  0.73% 72.57%      0.21s  1.93%  runtime.getitab
     0.07s  0.64% 73.21%      0.08s  0.73%  github.com/antlr/antlr4/runtime/Go/antlr.(*BaseATNConfig).GetState
     0.07s  0.64% 73.85%      0.07s  0.64%  github.com/antlr/antlr4/runtime/Go/antlr.(*BaseTransition).getSerializationType
     0.07s  0.64% 74.50%      0.52s  4.77%  github.com/antlr/antlr4/runtime/Go/antlr.(*array2DHashSet).innerAdd
     0.07s  0.64% 75.14%      0.20s  1.83%  github.com/antlr/antlr4/runtime/Go/antlr.equalATNConfigs
     0.07s  0.64% 75.78%      0.07s  0.64%  runtime._ExternalCode
     0.07s  0.64% 76.42%      2.56s 23.49%  runtime.gcDrain
     0.07s  0.64% 77.06%      0.08s  0.73%  runtime.ifaceeq
     0.07s  0.64% 77.71%      2.09s 19.17%  runtime.newobject
     0.06s  0.55% 78.26%      0.06s  0.55%  github.com/antlr/antlr4/runtime/Go/antlr.murmurFinish (inline)
     0.06s  0.55% 78.81%      0.06s  0.55%  runtime.(*lfstack).pop (inline)
     0.06s  0.55% 79.36%      0.06s  0.55%  runtime.(*sweepLocker).tryAcquire (inline)
     0.06s  0.55% 79.91%      0.21s  1.93%  runtime.assertE2I
     0.06s  0.55% 80.46%      0.96s  8.81%  runtime.findrunnable
     0.05s  0.46% 80.92%      1.62s 14.86%  github.com/antlr/antlr4/runtime/Go/antlr.NewBaseATNConfig4
     0.05s  0.46% 81.38%      0.22s  2.02%  github.com/antlr/antlr4/runtime/Go/antlr.hashATNConfig
     0.05s  0.46% 81.83%      0.08s  0.73%  runtime.gcWriteBarrier
     0.04s  0.37% 82.20%      1.80s 16.51%  runtime.lock2
     0.04s  0.37% 82.57%      0.48s  4.40%  runtime.stealWork
     0.04s  0.37% 82.94%      0.09s  0.83%  runtime.unlock2
     0.03s  0.28% 83.21%      0.25s  2.29%  github.com/antlr/antlr4/runtime/Go/antlr.(*array2DHashSet).getBuckets (inline)
     0.03s  0.28% 83.49%      0.25s  2.29%  github.com/antlr/antlr4/runtime/Go/antlr.NewArrayPredictionContext
     0.03s  0.28% 83.76%      0.91s  8.35%  github.com/antlr/antlr4/runtime/Go/antlr.merge
     0.03s  0.28% 84.04%      0.11s  1.01%  runtime.(*mheap).allocSpan
     0.03s  0.28% 84.31%      0.60s  5.50%  runtime.notewakeup
     0.03s  0.28% 84.59%      1.27s 11.65%  runtime.schedule
     0.02s  0.18% 84.77%      0.64s  5.87%  github.com/antlr/antlr4/runtime/Go/antlr.(*ParserATNSimulator).precedenceTransition
     0.02s  0.18% 84.95%      0.27s  2.48%  github.com/antlr/antlr4/runtime/Go/antlr.SingletonBasePredictionContextCreate (inline)
     0.02s  0.18% 85.14%      0.50s  4.59%  runtime.checkTimers
     0.02s  0.18% 85.32%      0.15s  1.38%  runtime.netpoll
     0.01s 0.092% 85.41%      0.27s  2.48%  github.com/antlr/antlr4/runtime/Go/antlr.(*DoubleDict).Get (inline)
     0.01s 0.092% 85.50%      0.42s  3.85%  github.com/antlr/antlr4/runtime/Go/antlr.(*ParserATNSimulator).ruleTransition
     0.01s 0.092% 85.60%      0.07s  0.64%  github.com/antlr/antlr4/runtime/Go/antlr.(*Predicate).hash
     0.01s 0.092% 85.69%      0.53s  4.86%  github.com/antlr/antlr4/runtime/Go/antlr.(*array2DHashSet).Add
     0.01s 0.092% 85.78%      0.12s  1.10%  github.com/antlr/antlr4/runtime/Go/antlr.NewBaseATNConfig5 (inline)
     0.01s 0.092% 85.87%      0.25s  2.29%  github.com/antlr/antlr4/runtime/Go/antlr.NewBaseSingletonPredictionContext
     0.01s 0.092% 85.96%      0.21s  1.93%  github.com/antlr/antlr4/runtime/Go/antlr.mergeArrays
     0.01s 0.092% 86.06%      1.91s 17.52%  runtime.(*gcWork).balance
     0.01s 0.092% 86.15%      0.26s  2.39%  runtime.(*mcache).nextFree
     0.01s 0.092% 86.24%      0.07s  0.64%  runtime.(*sweepLocked).sweep
     0.01s 0.092% 86.33%      0.07s  0.64%  runtime.gcWriteBarrierCX
     0.01s 0.092% 86.42%      0.37s  3.39%  runtime.injectglist
     0.01s 0.092% 86.51%      1.81s 16.61%  runtime.lock (inline)
     0.01s 0.092% 86.61%      0.17s  1.56%  runtime.newstack
     0.01s 0.092% 86.70%      1.93s 17.71%  runtime.preemptM
     0.01s 0.092% 86.79%      0.06s  0.55%  runtime.resettimer (inline)
     0.01s 0.092% 86.88%      0.44s  4.04%  runtime.runtimer
     0.01s 0.092% 86.97%      0.17s  1.56%  runtime.sweepone
     0.01s 0.092% 87.06%      0.16s  1.47%  runtime.sysUnused
     0.01s 0.092% 87.16%      3.12s 28.62%  runtime.systemstack
         0     0% 87.16%      0.13s  1.19%  github.com/antlr/antlr4/runtime/Go/antlr.NewBaseATNConfig1
         0     0% 87.16%      0.08s  0.73%  github.com/antlr/antlr4/runtime/Go/antlr.NewBasePredictionContext (inline)
         0     0% 87.16%      0.18s  1.65%  github.com/antlr/antlr4/runtime/Go/antlr.mergeSingletons
         0     0% 87.16%      1.85s 16.97%  runtime.(*gcControllerState).enlistWorker
         0     0% 87.16%      0.25s  2.29%  runtime.(*mcache).refill
         0     0% 87.16%      0.21s  1.93%  runtime.(*mcentral).cacheSpan
         0     0% 87.16%      0.15s  1.38%  runtime.(*mcentral).grow
         0     0% 87.16%      0.15s  1.38%  runtime.(*mheap).alloc
         0     0% 87.16%      0.11s  1.01%  runtime.(*mheap).alloc.func1
         0     0% 87.16%      0.18s  1.65%  runtime.(*pageAlloc).scavenge
         0     0% 87.16%      0.17s  1.56%  runtime.(*pageAlloc).scavengeOne
         0     0% 87.16%      0.16s  1.47%  runtime.(*pageAlloc).scavengeRangeLocked
         0     0% 87.16%      0.07s  0.64%  runtime._System
         0     0% 87.16%      0.06s  0.55%  runtime.assertE2I2
         0     0% 87.16%      0.15s  1.38%  runtime.bgscavenge
         0     0% 87.16%      0.39s  3.58%  runtime.bgscavenge.func1
         0     0% 87.16%      0.19s  1.74%  runtime.bgscavenge.func2
         0     0% 87.16%      0.17s  1.56%  runtime.bgsweep
         0     0% 87.16%      0.06s  0.55%  runtime.gcAssistAlloc.func1
         0     0% 87.16%      0.06s  0.55%  runtime.gcAssistAlloc1
         0     0% 87.16%      0.81s  7.43%  runtime.gcBgMarkWorker
         0     0% 87.16%      2.57s 23.58%  runtime.gcBgMarkWorker.func2
         0     0% 87.16%      0.06s  0.55%  runtime.gcDrainN
         0     0% 87.16%      0.16s  1.47%  runtime.gopreempt_m
         0     0% 87.16%      0.21s  1.93%  runtime.goschedImpl
         0     0% 87.16%      0.36s  3.30%  runtime.injectglist.func1 (inline)
         0     0% 87.16%      1.80s 16.51%  runtime.lockWithRank (inline)
         0     0% 87.16%      1.21s 11.10%  runtime.mcall
         0     0% 87.16%      0.15s  1.38%  runtime.morestack
         0     0% 87.16%      1.16s 10.64%  runtime.park_m
         0     0% 87.16%      0.07s  0.64%  runtime.preemptall
         0     0% 87.16%      1.92s 17.61%  runtime.preemptone
         0     0% 87.16%      0.24s  2.20%  runtime.resetspinning
         0     0% 87.16%      0.40s  3.67%  runtime.runOneTimer
         0     0% 87.16%      0.11s  1.01%  runtime.scavengeSleep
         0     0% 87.16%      1.74s 15.96%  runtime.semasleep
         0     0% 87.16%      0.62s  5.69%  runtime.semawakeup
         0     0% 87.16%      0.60s  5.50%  runtime.startm
         0     0% 87.16%      0.09s  0.83%  runtime.unlock (inline)
(pprof) Time: 15.072 s

It's not clear how one changes the sampling interval.

[kaby76]

I think the problem is that the there is excessive pressure on the heap and stack. This is because the definitions for many of the Antlr data structures are actually incorrect. Most fields of structs are structs themselves, whereas they should be pointers. Go is very much like C++, and one must explicitly use pointers, e.g., this is a struct, not a pointer to a struct. Contrast that with the Cpp target, where it is explicitly a pointer. The erroneous confusion of struct vs pointer to struct manifests in another problem that I mentioned here. Yes, this is just conjecture on my part. I'll try at some point to modify the code to redo the data structures to see if that fixes the performance, but it's low priority for me.

[parrt]

I was just going to say that wildly different times could indicate an issue with garbage collection. I also noticed that the go target who is kind of walkie when I tried it once. @jcking is taking a look at the target at the moment I think.

[kaby76]

I should note, for strings of (1 EQ 2 OR)* 1 EQ 2, the runtime climbs exponentially per each "1 EQ 2 OR" sub-string added, just as what @movelazar says. But, process memory is pretty much constant! And, it's only 10 or 20 MB! You can't get more than 15 pairs of "1 EQ 2" before it starts to hang. I attached a debugger to the process on Windows, and whenever I did a break, it would be in a lock routine in the OS, likely to keep memory allocation/GC re-entrant or to single thread the runtime.

[parrt]

zoiks!!! @jcking here's a good used case for testing and upgraded Go target.

[kylege]

Same issue here.

[parrt]

Yeah, somebody needs to take a serious look at rebuilding the Go target. I might take a walk at it but it's lower on my priority list. sorry!

[jimidle]

Did anyone look in to this more? If not, then I may do this myself. Go should be about the fastest target, assuming that it has implemented the various algorithms in the runtime as well as any other target.

[kaby76]

It's likely caused by a bug in the Go Antlr runtime. Turning on debug for the runtime (and cleaning out the Go runtime where we get a core dump because atn_config printing is passed a nil pointer), we see that the edges in the dfas are not correct.

See https://github.com/kaby76/issue-3718 for a complete side-by-side exact run comparison, driver code that was generated by my trgen program--handles all targets except "Swift".

CSharp here:

SLL altSubSets=[{1, 2}, {1, 2}, {1, 2}, {1, 2}, {1, 2}], configs=[(10,1,[52 $]), (14,1,[52 $]), (16,1,[52 $]), (56,1,[24 52 $]), (22,1,[52 $]), (10,2,[52 $],up=8), (14,2,[52 $],up=8), (16,2,[52 $],up=8), (56,2,[24 52 $],up=8), (22,2,[52 $],up=8)],dipsIntoOuterContext, predict=0, allSubsetsConflict=True, conflictingAlts={1, 2}
EDGE 0:[(26,1,[$]), (29,1,[$]), (32,1,[$]), (35,1,[$]), (38,1,[$]), (45,1,[$]), (7,2,[$],up=1), (12,2,[$],up=1), (26,2,[$],up=8), (29,2,[$],up=8), (32,2,[$],up=8), (35,2,[$],up=8), (38,2,[$],up=8), (45,2,[$],up=8), (19,2,[$],up=2), (40,2,[$],up=3), (47,2,[$],up=7)],dipsIntoOuterContext -> -1:[(10,1,[52 $]), (14,1,[52 $]), (16,1,[52 $]), (56,1,[24 52 $]), (22,1,[52 $]), (10,2,[52 $],up=8), (14,2,[52 $],up=8), (16,2,[52 $],up=8), (56,2,[24 52 $],up=8), (22,2,[52 $],up=8)],conflictingAlts={1, 2},dipsIntoOuterContext=>1 upon OR<2>
adding new DFA state: 4:[(10,1,[52 $]), (14,1,[52 $]), (16,1,[52 $]), (56,1,[24 52 $]), (22,1,[52 $]), (10,2,[52 $],up=8), (14,2,[52 $],up=8), (16,2,[52 $],up=8), (56,2,[24 52 $],up=8), (22,2,[52 $],up=8)],conflictingAlts={1, 2},dipsIntoOuterContext=>1
DFA=
s0-OR->:s4^=>1
s0-EQ->:s1^=>1
s2-OR->:s3=>2

Go here:

SLL altSubSets=[{1, 2} {1, 2} {1, 2} {1, 2} {1, 2}], previous=[(26,1,[$]), (29,1,[$]), (32,1,[$]), (35,1,[$]), (38,1,[$]), (45,1,[$]), (7,2,[$],up=1), (12,2,[$],up=1), (26,2,[$],up=8), (29,2,[$],up=8), (32,2,[$],up=8), (35,2,[$],up=8), (38,2,[$],up=8), (45,2,[$],up=8), (19,2,[$],up=2), (40,2,[$],up=3), (47,2,[$],up=7)],dipsIntoOuterContext, configs=[(10,1,[52 $]), (14,1,[52 $]), (16,1,[52 $]), (56,1,[24 52 $]), (22,1,[52 $]), (10,2,[52 $],up=8), (14,2,[52 $],up=8), (16,2,[52 $],up=8), (56,2,[24 52 $],up=8), (22,2,[52 $],up=8)],dipsIntoOuterContext, predict=0, allSubsetsConflict=true, conflictingAlts={1, 2}
EDGE 0:[(26,1,[$]), (29,1,[$]), (32,1,[$]), (35,1,[$]), (38,1,[$]), (45,1,[$]), (7,2,[$],up=1), (12,2,[$],up=1), (26,2,[$],up=8), (29,2,[$],up=8), (32,2,[$],up=8), (35,2,[$],up=8), (38,2,[$],up=8), (45,2,[$],up=8), (19,2,[$],up=2), (40,2,[$],up=3), (47,2,[$],up=7)],dipsIntoOuterContext -> -1:[(10,1,[52 $]), (14,1,[52 $]), (16,1,[52 $]), (56,1,[24 52 $]), (22,1,[52 $]), (10,2,[52 $],up=8), (14,2,[52 $],up=8), (16,2,[52 $],up=8), (56,2,[24 52 $],up=8), (22,2,[52 $],up=8)],conflictingAlts={1, 2},dipsIntoOuterContext=>1 upon <2>
DFA=
s0-->:s1^=>1
s0-->:s1^=>1
s2-->:s3=>2

Most of the debug output has a 1 to 1 correspondence between the Go and CSharp runtimes (although, it would really really help to be consistent in debug output formatted strings to make life easier). The major diff occurs where a DFA is added in CSharp but not in Go. Note, the Go runtime does print out new DFA creation, but after a few, this is the first where it's not recorded. There are 11 DFA states created in the CSharp target, 9 DFA states created in the Go target.

(And, anticipating the argument "But Java code is the gold standard!", I also did it for that target. There are 11 new DFA states added, just as with CSharp, and the with this important add also in the Java debug output.)

Unless this bug is fixed, it's unlikely to know for sure whether this is the "performance issue". I have been programming for ~50 years. There is lttle sense in tracking down a "performance issue" when the basic behavior of the software is not working.

[kaby76]

The problem is here and it goes to how DFAState objects are kept in a hash table.

Let's compare the CSharp and Go target code side by side:

CSharp	Go
AddDFAState(dfa, to)	p.addDFAState(dfa, to)
dfa.states.Get(D)	dfa.getState(hash)
dictionary.TryGetValue(key, out value)	no equality compare

Hashing is never perfect. In this case, there is a collision between two dfa states, one that exists in a table, and another which should be entered into the table. After computing the hash value of the DFAState to enter, you have to perform an equality check to verify that the state you want to enter is already in the table, i.e., has an identical hash but are equality different.

Note here in C#, "states" is a map from DFAState to DFAState. The C# runtime actually performs an equality comparison and notices the hash is identical with something that is already in the table, but the value of the new DFAState is equality compare different than the one that is already in the table. So, a new state is created.

But, in Go, it is a map from int to DFAState. Collisions in hash values are never checked because it's a mapping of hash value to DFAState not DFAState to DFAState. So, a new state is not created.

@parrt This is a serious problem.

[parrt]

Thanks, @kaby76 for tracking this down! yeah, I was under impression Go target was kinda screwed up.

Does anybody know Go well enough to fix this hash issue?