Deep dive performance impact of 1.11.8 PatchPoint handling change

[tgregg]

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 read command tests IonWriter.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.

[austnwil]

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%

[tgregg]

@austnwil Are these results for read performance using the benchmark-cli's read command?

[austnwil]

@austnwil Are these results for read performance using the benchmark-cli's read command?

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.10n

ion-dev bm 0.0.1-using-1.11.6 runs 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.

[tgregg]

Those 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.

[austnwil]

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 overtakes stepIn() 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.

[austnwil]

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 addPatchPoint in IonRawBinaryWriter in 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.addPatchPoint is 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.10n

Compared 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