Warm-up really doesn't help much, if anything at all, in performance

[kaby76]

This is a sample of the performance times for the pdp7 grammar in grammars-v4. The following are a sample run of the parser on all examples, the first using successive warm-up.

Kenne@DESKTOP-DL44R7B MINGW64 ~/issues/issue-3462/kaby76/asm/pdp7/Generated-PHP
$ php -d memory_limit=1G Test.php ../examples/*
PHP 0 ../examples/adm.s success 11.0138797
PHP 1 ../examples/apr.s success 10.6252017
PHP 2 ../examples/as.s success 14.5321134
PHP 3 ../examples/bc.s success 5.6172839
PHP 4 ../examples/bi.s success 9.7434439
PHP 5 ../examples/bl.s success 3.7069562
PHP 6 ../examples/brt.s success 4.9765548
PHP 7 ../examples/cas.s success 7.7473598
PHP 8 ../examples/cat.s success 1.9028137
PHP 9 ../examples/check.s success 5.8578735
PHP 10 ../examples/chmod.s success 0.874738
PHP 11 ../examples/chown.s success 0.8564517
PHP 12 ../examples/chrm.s success 0.5922323
PHP 13 ../examples/cp.s success 1.2704721
PHP 14 ../examples/db.s success 19.320848
PHP 15 ../examples/dmabs.s success 4.9421895
PHP 16 ../examples/ds.s success 9.2274488
PHP 17 ../examples/dskio.s success 1.2575753
PHP 18 ../examples/dskres.s success 0.3079457
PHP 19 ../examples/dsksav.s success 0.3024641
PHP 20 ../examples/dsw.s success 0.5261863
PHP 21 ../examples/ed1.s success 13.4559798
PHP 22 ../examples/ed2.s success 8.9419334
PHP 23 ../examples/hello.s success 0.0677419
PHP 24 ../examples/init.s success 4.9112263
PHP 25 ../examples/maksys.s success 1.2041924
PHP 26 ../examples/ops.s success 0.3430672
PHP 27 ../examples/pbboot.s success 0.3959028
PHP 28 ../examples/pblsd.s success 3.2266105
PHP 29 ../examples/pbsh.s success 6.000908
PHP 30 ../examples/s1.s success 3.0396919
PHP 31 ../examples/s2.s success 4.0668577
PHP 32 ../examples/s3.s success 6.9326836
PHP 33 ../examples/s4.s success 6.9186337
PHP 34 ../examples/s5.s success 4.6001755
PHP 35 ../examples/s6.s success 6.6948415
PHP 36 ../examples/s7.s success 5.4000285
PHP 37 ../examples/s8.s success 0.8555186
PHP 38 ../examples/s9.s success 1.6304246
PHP 39 ../examples/sop.s success 0.2741589
PHP 40 ../examples/sysmap success 0.5561482
PHP 41 ../examples/trysys.s success 0.5884479
PHP 42 ../examples/wktcat.s success 1.0355136
PHP 43 ../examples/wktcp.s success 1.0071768
PHP 44 ../examples/wktdate.s success 1.724664
PHP 45 ../examples/wktln.s success 0.4833258
PHP 46 ../examples/wktls.s success 3.1686282
PHP 47 ../examples/wktmv.s success 0.4285047
PHP 48 ../examples/wktod.s success 1.1016418
PHP 49 ../examples/wktstat.s success 2.0969983
Total Time: 206.5825112

The following are parse times without any warm-up .

Kenne@DESKTOP-DL44R7B MINGW64 ~/issues/issue-3462/kaby76/asm/pdp7/Generated-PHP
$ make test
bash test.sh
../examples/adm.s
PHP 0 ../examples/adm.s success 10.6846397
Total Time: 10.7246716
../examples/apr.s
PHP 0 ../examples/apr.s success 11.61783
Total Time: 11.657559
../examples/as.s
PHP 0 ../examples/as.s success 14.5487311
Total Time: 14.5898775
../examples/bc.s
PHP 0 ../examples/bc.s success 6.5004033
Total Time: 6.539226
../examples/bi.s
PHP 0 ../examples/bi.s success 10.360398
Total Time: 10.3987107
../examples/bl.s
PHP 0 ../examples/bl.s success 4.5519165
Total Time: 4.5935103
../examples/brt.s
PHP 0 ../examples/brt.s success 6.0734476
Total Time: 6.1114997
../examples/cas.s
PHP 0 ../examples/cas.s success 8.6315575
Total Time: 8.6697294
../examples/cat.s
PHP 0 ../examples/cat.s success 2.6880397
Total Time: 2.7269138
../examples/check.s
PHP 0 ../examples/check.s success 6.3531311
Total Time: 6.3915231
../examples/chmod.s
PHP 0 ../examples/chmod.s success 1.5153027
Total Time: 1.5535042
../examples/chown.s
PHP 0 ../examples/chown.s success 1.5056945
Total Time: 1.5441049
../examples/chrm.s
PHP 0 ../examples/chrm.s success 1.068433
Total Time: 1.1081633
../examples/cp.s
PHP 0 ../examples/cp.s success 1.8565767
Total Time: 1.8946874
../examples/db.s
PHP 0 ../examples/db.s success 20.0562215
Total Time: 20.0962135
../examples/dmabs.s
PHP 0 ../examples/dmabs.s success 5.8840665
Total Time: 5.9231479
../examples/ds.s
PHP 0 ../examples/ds.s success 10.2160737
Total Time: 10.255325
../examples/dskio.s
PHP 0 ../examples/dskio.s success 1.8428187
Total Time: 1.8864235
../examples/dskres.s
PHP 0 ../examples/dskres.s success 0.6423093
Total Time: 0.6804745
../examples/dsksav.s
PHP 0 ../examples/dsksav.s success 0.6445189
Total Time: 0.6833853
../examples/dsw.s
PHP 0 ../examples/dsw.s success 1.1237836
Total Time: 1.1710561
../examples/ed1.s
PHP 0 ../examples/ed1.s success 14.3828733
Total Time: 14.4220581
../examples/ed2.s
PHP 0 ../examples/ed2.s success 9.7511328
Total Time: 9.7909862
../examples/hello.s
PHP 0 ../examples/hello.s success 0.1903819
Total Time: 0.2284939
../examples/init.s
PHP 0 ../examples/init.s success 5.8791759
Total Time: 5.9178624
../examples/maksys.s
PHP 0 ../examples/maksys.s success 2.0680982
Total Time: 2.106212
../examples/ops.s
PHP 0 ../examples/ops.s success 1.0514115
Total Time: 1.090667
../examples/pbboot.s
PHP 0 ../examples/pbboot.s success 1.0002686
Total Time: 1.0376918
../examples/pblsd.s
PHP 0 ../examples/pblsd.s success 4.3169098
Total Time: 4.3569711
../examples/pbsh.s
PHP 0 ../examples/pbsh.s success 7.0682057
Total Time: 7.1084137
../examples/s1.s
PHP 0 ../examples/s1.s success 3.9273563
Total Time: 3.9667569
../examples/s2.s
PHP 0 ../examples/s2.s success 4.7665721
Total Time: 4.8058088
../examples/s3.s
PHP 0 ../examples/s3.s success 7.4540133
Total Time: 7.4930751
../examples/s4.s
PHP 0 ../examples/s4.s success 7.9267007
Total Time: 7.965898
../examples/s5.s
PHP 0 ../examples/s5.s success 5.6681148
Total Time: 5.7084301
../examples/s6.s
PHP 0 ../examples/s6.s success 7.6418979
Total Time: 7.6812904
../examples/s7.s
PHP 0 ../examples/s7.s success 6.6983566
Total Time: 6.7385467
../examples/s8.s
PHP 0 ../examples/s8.s success 1.6644336
Total Time: 1.7047969
../examples/s9.s
PHP 0 ../examples/s9.s success 2.5680441
Total Time: 2.6070198
../examples/sop.s
PHP 0 ../examples/sop.s success 1.7429675
Total Time: 1.7806677
../examples/sysmap
PHP 0 ../examples/sysmap success 0.8605542
Total Time: 0.8997934
../examples/trysys.s
PHP 0 ../examples/trysys.s success 1.3442964
Total Time: 1.3830006
../examples/wktcat.s
PHP 0 ../examples/wktcat.s success 1.5496047
Total Time: 1.5889051
../examples/wktcp.s
PHP 0 ../examples/wktcp.s success 1.627934
Total Time: 1.6664034
../examples/wktdate.s
PHP 0 ../examples/wktdate.s success 2.4064982
Total Time: 2.4453083
../examples/wktln.s
PHP 0 ../examples/wktln.s success 0.9687042
Total Time: 1.0061204
../examples/wktls.s
PHP 0 ../examples/wktls.s success 3.7999109
Total Time: 3.8391993
../examples/wktmv.s
PHP 0 ../examples/wktmv.s success 0.9016187
Total Time: 0.9392889
../examples/wktod.s
PHP 0 ../examples/wktod.s success 1.6610009
Total Time: 1.6989887
../examples/wktstat.s
PHP 0 ../examples/wktstat.s success 2.5835233
Total Time: 2.6216228

For other targets, we usually see a 5x or 10x improvement for runtimes. E.g., C#:

Kenne@DESKTOP-DL44R7B MINGW64 ~/issues/issue-3462/kaby76/asm/pdp7/Generated-CSharp
$ ./bin/Debug/net6.0/Test.exe ../examples/*
CSharp 0 ../examples/adm.s success 0.1618691
CSharp 1 ../examples/apr.s success 0.1142618
CSharp 2 ../examples/as.s success 0.152285
CSharp 3 ../examples/bc.s success 0.0599404
CSharp 4 ../examples/bi.s success 0.1011636
CSharp 5 ../examples/bl.s success 0.0386238
CSharp 6 ../examples/brt.s success 0.0497694
CSharp 7 ../examples/cas.s success 0.074425
CSharp 8 ../examples/cat.s success 0.0229982
CSharp 9 ../examples/check.s success 0.0614206
CSharp 10 ../examples/chmod.s success 0.0084926
CSharp 11 ../examples/chown.s success 0.0090851
CSharp 12 ../examples/chrm.s success 0.0055372
CSharp 13 ../examples/cp.s success 0.0132966
CSharp 14 ../examples/db.s success 0.1972775
CSharp 15 ../examples/dmabs.s success 0.0493398
CSharp 16 ../examples/ds.s success 0.0908554
CSharp 17 ../examples/dskio.s success 0.0122472
CSharp 18 ../examples/dskres.s success 0.0033042
CSharp 19 ../examples/dsksav.s success 0.0028239
CSharp 20 ../examples/dsw.s success 0.0050442
CSharp 21 ../examples/ed1.s success 0.1294552
CSharp 22 ../examples/ed2.s success 0.0834505
CSharp 23 ../examples/hello.s success 0.000606
CSharp 24 ../examples/init.s success 0.0460968
CSharp 25 ../examples/maksys.s success 0.0119937
CSharp 26 ../examples/ops.s success 0.0026134
CSharp 27 ../examples/pbboot.s success 0.0037931
CSharp 28 ../examples/pblsd.s success 0.0299127
CSharp 29 ../examples/pbsh.s success 0.0573688
CSharp 30 ../examples/s1.s success 0.0289441
CSharp 31 ../examples/s2.s success 0.0392431
CSharp 32 ../examples/s3.s success 0.0663038
CSharp 33 ../examples/s4.s success 0.0698731
CSharp 34 ../examples/s5.s success 0.0444728
CSharp 35 ../examples/s6.s success 0.0630716
CSharp 36 ../examples/s7.s success 0.0528757
CSharp 37 ../examples/s8.s success 0.0072066
CSharp 38 ../examples/s9.s success 0.0155911
CSharp 39 ../examples/sop.s success 0.002243
CSharp 40 ../examples/sysmap success 0.0045693
CSharp 41 ../examples/trysys.s success 0.0059326
CSharp 42 ../examples/wktcat.s success 0.0091015
CSharp 43 ../examples/wktcp.s success 0.0096926
CSharp 44 ../examples/wktdate.s success 0.0165528
CSharp 45 ../examples/wktln.s success 0.0041428
CSharp 46 ../examples/wktls.s success 0.0303048
CSharp 47 ../examples/wktmv.s success 0.0048924
CSharp 48 ../examples/wktod.s success 0.0101392
CSharp 49 ../examples/wktstat.s success 0.0201081
Total Time: 2.1761201

These are the runtimes for non-warm-up parses.

Kenne@DESKTOP-DL44R7B MINGW64 ~/issues/issue-3462/kaby76/asm/pdp7/Generated-CSharp
$ make test
bash test.sh
../examples/adm.s
CSharp 0 stdin success 0.1754811
../examples/apr.s
CSharp 0 stdin success 0.1850342
../examples/as.s
CSharp 0 stdin success 0.2326581
../examples/bc.s
CSharp 0 stdin success 0.1260353
../examples/bi.s
CSharp 0 stdin success 0.1706986
../examples/bl.s
CSharp 0 stdin success 0.0999132
../examples/brt.s
CSharp 0 stdin success 0.1189403
../examples/cas.s
CSharp 0 stdin success 0.1450821
../examples/cat.s
CSharp 0 stdin success 0.0808749
../examples/check.s
CSharp 0 stdin success 0.1259671
../examples/chmod.s
CSharp 0 stdin success 0.0678161
../examples/chown.s
CSharp 0 stdin success 0.0654563
../examples/chrm.s
CSharp 0 stdin success 0.0600154
../examples/cp.s
CSharp 0 stdin success 0.0697496
../examples/db.s
CSharp 0 stdin success 0.2658805
../examples/dmabs.s
CSharp 0 stdin success 0.1154895
../examples/ds.s
CSharp 0 stdin success 0.1618286
../examples/dskio.s
CSharp 0 stdin success 0.0693542
../examples/dskres.s
CSharp 0 stdin success 0.0535364
../examples/dsksav.s
CSharp 0 stdin success 0.0527942
../examples/dsw.s
CSharp 0 stdin success 0.0601276
../examples/ed1.s
CSharp 0 stdin success 0.2051506
../examples/ed2.s
CSharp 0 stdin success 0.1603832
../examples/hello.s
CSharp 0 stdin success 0.0429625
../examples/init.s
CSharp 0 stdin success 0.1170006
../examples/maksys.s
CSharp 0 stdin success 0.0724591
../examples/ops.s
CSharp 0 stdin success 0.0566942
../examples/pbboot.s
CSharp 0 stdin success 0.0707361
../examples/pblsd.s
CSharp 0 stdin success 0.0987967
../examples/pbsh.s
CSharp 0 stdin success 0.1313152
../examples/s1.s
CSharp 0 stdin success 0.0951988
../examples/s2.s
CSharp 0 stdin success 0.1025113
../examples/s3.s
CSharp 0 stdin success 0.1380356
../examples/s4.s
CSharp 0 stdin success 0.1396423
../examples/s5.s
CSharp 0 stdin success 0.114189
../examples/s6.s
CSharp 0 stdin success 0.1345514
../examples/s7.s
CSharp 0 stdin success 0.1235048
../examples/s8.s
CSharp 0 stdin success 0.0685052
../examples/s9.s
CSharp 0 stdin success 0.0792619
../examples/sop.s
CSharp 0 stdin success 0.0657133
../examples/sysmap
CSharp 0 stdin success 0.0503479
../examples/trysys.s
CSharp 0 stdin success 0.0639146
../examples/wktcat.s
CSharp 0 stdin success 0.0672026
../examples/wktcp.s
CSharp 0 stdin success 0.0677079
../examples/wktdate.s
CSharp 0 stdin success 0.0779383
../examples/wktln.s
CSharp 0 stdin success 0.0578612
../examples/wktls.s
CSharp 0 stdin success 0.0953644
../examples/wktmv.s
CSharp 0 stdin success 0.0574972
../examples/wktod.s
CSharp 0 stdin success 0.0692217
../examples/wktstat.s
CSharp 0 stdin success 0.0805491

PHP really should not be this slow, but especially, it should be faster for warm-up parsing. Yet it isn't.

[marcospassos]

@kaby76, run benchmarks with the profiler enabled to identify what is hurting the performance. I am interested in helping to fix it.

[kaby76]

Looks like out of the gate of the start of the parse, the first call to GetCachedContext() should be for an empty context ("$"), breaking here.

But, that's not the same as in PHP. For the first context it's skipping past that short circuit, and stopping here, should have called this. The first call to the function is for an empty context in C#, but a singleton prediction context in PHP.

That's a major failure. Never mind. The method is recursive and I wasn't looking at the entire stack.

But, this looks very suspect. https://github.com/antlr/antlr-php-runtime/blob/dev/src/PredictionContexts/PredictionContext.php#L594. That's not correct because it's not calling the usual hash() and equals() functions for the map or set.

I'll work on profiling after I start tracing how the parse works on multiple files and comparing that to C#.

I made changes for grammars in v4 for PHP in PR antlr/grammars-v4#2977. So far, the ATN trace and parse trees are identical, which is great to see.

[kaby76]

OK, the table for PredictionContext was an array, not implemented as a Map, newed here. It was not working. I rewrote that to Map<PredictionContext,PredictionContext> as in C#, and it now has 20% speed up with warm-up. That's good, but not great. This code should be much much faster. There's more to find. My feeling is that it's in the engine that needs to handle ambiguity because it seems to be much much slower when the input exercises that code.
diffs.txt

[marcospassos]

WOW! With these fixes, we'll probably come close to the performance of other targets. I am looking forward to seeing the target performance ranking after theses changes.

[kaby76]

Not sure why, but debugging side-by-side of pdp7 grammar, input file s1.s, first breakpoint here has 'altsets' containing just 2 items in C#, 31 items in PHP. It should not be doing this. Never mind. Hard to switch between debuggers with different UI.

I agree--the PHP target should not be this slow. When there's no ambiguity, it is just as fast as the other targets. There's something wrong here.

[kaby76]

Although a minor issue, this code in PHP does not have a cardinality check for alt sets as done in C#. That would cut short the looping through the 31 elements--although not likely much of an issue.

[kaby76]

Bug, but not the problem https://github.com/antlr/antlr4/blob/76fa05c21b12b96a6c12a0a82e611ed9d87d5af4/runtime/CSharp/src/Atn/ATNConfigSet.cs#L280 (cached hash value should be reset to null, not -1, since everywhere else it's reset to null.)

[kaby76]

Not that it makes much difference, but the hash code for an ATN state is the state number as in Java and CSharp, not the state type as in PHP.

Counts of ATNConfigSet hash and equals almost identical between CSharp and PHP. That's good. Moving down a layer to check hash and equals/equivalent calls.

[marcospassos]

Not that it makes much difference, but the hash code for an ATN state is the state number as in Java and CSharp, not the state type as in PHP.

Let's make it identical to make the maintenance and debugging easier.

[kaby76]

An absolutely humongous number of constructors are called for ATNConfig. It's easily 11x that for C# and Java. That's likely a symptom of the problem. Not sure why it's calling all this.

A second possible problem is that there's no lazy evaluation of enumerables. Instead, lists and arrays created to iterator over. PHP does have a yield statement so this might be useful to short circuit loops in which not all elements are need in a list.

[marcospassos]

A second possible problem is that there's no lazy evaluation of enumerables. Instead, lists and arrays created to iterator over. PHP does have a yield statement so this might be useful to short circuit loops in which not all elements are need in a list.

Can you share the snippet where you think it may be problematic?

[marcospassos]

An absolutely humongous number of constructors are called for ATNConfig. It's easily 11x that for C# and Java. That's likely a symptom of the problem. Not sure why it's calling all this.

Where is it happening? Can you share more info, like a print of the stack or a link to the source where it happens?

[kaby76]

An absolutely humongous number of constructors are called for ATNConfig. It's easily 11x that for C# and Java. That's likely a symptom of the problem. Not sure why it's calling all this.

Where is it happening? Can you share more info, like a print of the stack or a link to the source where it happens?

Sigh. I didn't count two other constructors for ATNConfig (three total, here, here, and here). The number is identical between C# and PHP, and likely for Java (checking). That's actually very good news in that the PHP code looks like it's working identically to that in the other targets.

A second possible problem is that there's no lazy evaluation of enumerables. Instead, lists and arrays created to iterator over. PHP does have a yield statement so this might be useful to short circuit loops in which not all elements are need in a list.

Can you share the snippet where you think it may be problematic?

On the enumerables idea, there are numerous methods that have an IEnumerable parameter, and inside, a foreach over the IEnumerable. For example, here, with IEnumerable altsets. When iterating with a foreach, an enumerator is created and called to iterate through the enumerable, so it can be a lazy computation instead of requiring a collection. Unfortunately, I don't see methods that actually return IEnumerable, which means everything that is returned from a method is a scalar or a collection.

For example, I was reading the code that creates a collection here. The full collection isn't needed always because this method returns a result on a partial analysis of the collection. Probably not very significant, but worth doing an analysis down the road.

Still reading the code...and grasping at straws. Profiling just says closure_() is taking 17% the total run time in the method itself. Duh. But it also says hashArray() takes 10% of the total run time, too. That's why I am still looking over the hashing code.

[marcospassos]

How far is PHP from other targets' performance? Also, how different is the time consumption of closure_ and hashCode calls between PHP and any other baseline?

Not sure how frequently the same instance is hashed, but if it's significantly high, we can use a WeakMap to memoize immutable values. My guess is that it won't make any significant difference.