Repository navigation
Deep dive performance impact of 1.11.8 PatchPoint handling change #1095
Description
Activity
A large-ish dataset I have (stream of a few thousand top-level structs, most nested a few levels deep) demonstrates a performance hit at 1.11.8 and another one at 1.11.9 despite a drop in allocation rate for both changes.
AverageTime (us/op) Change previous Alloc rate (MB/s) Change previous GC count Change previous 1.11.6 8456.855 ± 149.248 1279.133 ± 22.203 625 1.11.7 8385.530 ± 76.282 -0.84% 1289.805 ± 11.619 0.83% 628 0.48% 1.11.8 8983.468 ± 83.453 7.13% 1161.378 ± 10.519 -9.96% 569 -9.39% 1.11.9 9767.795 ± 65.564 8.73% 1068.155 ± 7.043 -8.03% 529 -7.03% @austnwil Are these results for read performance using the benchmark-cli's
readcommand?This is using the version of benchmark-cli with the modified read task you linked above, so it's testing
IonWriter.writeValues()from a reader. This is the command used (for 1.11.6):ion-dev bm 0.0.1-using-1.11.6 read --mode AverageTime --time-unit microseconds --ion-reader non_incremental --io-type buffer ~/testfiles/pres2020/pres2020_tags_as_annots_utf8.10nion-dev bm 0.0.1-using-1.11.6runs the benchmark cli with v1.11.6 of ion-java.Read performance
Here are benchmarks for actual read performance - that is, the same command as above but with an unmodified ion-java-benchmark-cli.
AverageTime (us/op) Change previous Alloc rate (MB/s) Change previous GC count Change previous 1.11.6 2770.858 ± 11.054 675.380 ± 2.655 388 1.11.7 2738.689 ± 11.565 -1.16% 683.354 ± 2.830 1.18% 382 -1.55% 1.11.8 2754.164 ± 12.509 0.57% 679.512 ± 3.132 -0.56% 390 2.09% 1.11.9 2786.220 ± 11.857 1.16% 671.595 ± 2.889 -1.17% 387 -0.77% Basically no change in read performance for this dataset between these versions.
Reacted by Tyler GreggThose are some very interesting results. I'm surprised to see another regression in 1.11.9 given the apparent lack of write-side changes: v1.11.8...v1.11.9
I'm curious to see if this is repeatable, and if so what the profiles show.
On a couple profiles of the dataset I mentioned above on 1.11.7 and 1.11.8, I'm seeing a jump in the percentage of time it takes to
stepOut()of a struct? Sometimes it overtakesstepIn()in hogging execution time.1.11.7 IonWriter.writeValues() profiles
With
ion-dev bm 0.0.1-using-1.11.7 read --profile --mode AverageTime --time-unit microseconds --ion-reader non_incremental --io-type buffer ~/testfiles/pres2020/pres2020_tags_as_annots_utf8.10n(on read-tests-writevalues)
1.11.8 IonWriter.writeValues() profiles
With
ion-dev bm 0.0.1-using-1.11.8 read --profile --mode AverageTime --time-unit microseconds --ion-reader non_incremental --io-type buffer ~/testfiles/pres2020/pres2020_tags_as_annots_utf8.10n(on read-tests-writevalues)
Gonna run a few more profiles to see if I can pinpoint a consistent increase in execution time here.
I do believe this regression may have to do with attaching patch points to ancestor containers that do not have them when a deeply nested child container ends up needing one.
See
addPatchPointinIonRawBinaryWriterin version 1.11.8:private void addPatchPoint(final ContainerInfo container, final long position, final int oldLength, final long value) { // If we're adding a patch point we first need to ensure that all of our ancestors (containing values) already // have a patch point. No container can be smaller than the contents, so all outer layers also require patches. // Instead of allocating iterator, we share one iterator instance within the scope of the container stack and reset the cursor every time we track back to the ancestors. ListIterator<ContainerInfo> stackIterator = containers.iterator(); // Walk down the stack until we find an ancestor which already has a patch point while (stackIterator.hasNext() && stackIterator.next().patchIndex == -1); // The iterator cursor is now positioned on an ancestor container that has a patch point // Ascend back up the stack, fixing the ancestors which need a patch point assigned before us while (stackIterator.hasPrevious()) { ContainerInfo ancestor = stackIterator.previous(); if (ancestor.patchIndex == -1) { ancestor.patchIndex = patchPoints.push(PatchPoint::clear); } } // record the size of the length data. final int patchLength = WriteBuffer.varUIntLength(value); container.appendPatch(position, oldLength, value); updateLength(patchLength - oldLength); }
It has to chase its way down the container stack looking for the first ancestor that does not have a patch point and then ascend back up, fixing the ancestors that need patch points before assigning one to the current container.
Compare to the version from 1.11.7, which is much simpler:
private void addPatchPoint(final long position, final int oldLength, final long value) { // record the length of the patch final int patchLength = WriteBuffer.varUIntLength(value); final PatchPoint patch = new PatchPoint(position, oldLength, value); if (containers.isEmpty()) { // not nested, just append to the root list patchPoints.append(patch); } else { // nested, apply it to the current container containers.peek().appendPatch(patch); } updateLength(patchLength - oldLength); }
I don't know if this logic was present elsewhere and just moved into this function or if this parent fix-up wasn't done prior to 1.11.8, but CPU profiles show a pretty big performance hit here.
CPU profile of 1.11.7 write of deeply nested structs -
IonRawBinaryWriter.addPatchPointis basically instant:
Command used here:
ion-dev bm 0.0.1-using-1.11.7 read --profile --mode AverageTime --time-unit microseconds --warmups 5 --iterations 5 --ion-reader non_incremental --io-type buffer ~/testfiles/deeply_nested_structs_utf.10nCompared with 1.11.8, where fixing up missing patch points on parents now eats 30% of the same execution time:
I am not familiar enough with what's happening in the patch point logic to determine whether or not the same functionality can be implemented without having to back down the stack and apply patch points to ancestor containers if a child container ends up needing one. Perhaps we can at least keep track of the nearest ancestor that does not have a patch point so we can jump right to it in the stack instead of searching downwards for it and ascending back up the stack.
However, I do believe there is room for improvement in the current implementation of
addPatchPoint. A quick and dirty patch I applied that iterates over containers directly (just by making the RecyclingStack's backing list public) rather than getting an iterator from the RecyclingStack showed a decent amount of improvement in CPU time - a 50% reduction for the problematic function in particular:
Some more quick benchmarks between 1.11.7, 1.11.8, and the quick patch:
Average time (us/op) Average time change from 1.11.7 GC alloc rate (MB/sec) GC count 1.11.7 3539.033 ± 21.122 0% 3377.924 ± 21.179 368 1.11.8 3843.890 ± 22.294 8.61% 2618.029 ± 14.796 350 1.11.8 quick iterative patch 3685.194 ± 8.836 4.13% 2730.643 ± 8.182 360 Reacted by Tyler Gregg
While investigating other performance concerns, I found that 1.11.8 introduced a regression to writing in certain circumstances. Related change: #521
Dataset: deeply nested single value
Benchmarking code: ion-java-benchmark-cli, modified so that the
readcommand testsIonWriter.writeValues(IonReader)with stream copy optimization disabled. I will formally add an option to the tool that does this in a separate PR.CLI command:
./benchmark-cli read --mode AverageTime --time-unit microseconds --iterations 2 --warmups 2 --forks 2 --ion-reader non_incremental --io-type buffer <file>1.11.5
Time: 42.918 us/op
Allocation rate: 26 KB/op
1.11.8 (another regression happened here, related to the change to how PatchPoints are handled. This will be addressed separately)
Time: 44.937 us/op
Allocation rate: 32 KB/op
Based on the increase in allocation rate I tried tuning the initial size of the PatchPoint recycling queue for this dataset. I achieved best performance at size 64 (down from 512), which closed the allocation rate gap but still left a performance gap. Based on CPU profiles, I suspect that the change negatively impacted the optimizations the JIT can make. Optimization that worked in a similar situation: #1094
We should spend some time investigating and experimenting with this. Achieving the same performance as 1.11.5 should be possible.
NOTE: #521 demonstrated positive performance impact for some datasets, so we need to be careful not to optimize for some at the expense of others.