rework benchmarks

[ethanresnick]

This creates a new object before each benchmark's loop, which should make the benchmarks more reliable (since hidden class transitions on the object from prior tests could effect the speed of the redaction). This doesn’t go as far as to create a new object right before each redaction call (i.e., in the for loop) as that seems like it would add more noise/difficulty interpreting the final results, since a bigger chunk of each benchmark’s work would be this object creation.

This also means that the serialize: false tests (and the pino-noir tests, which are effectively serialize false) don’t leave the object in a different state for the subsequent tests, which is required for adding tests for #16. [That's what motivated me to make this change.]

Most of the benchmark times remained similar before and after this change, with some of the fast-redact benchmarks getting 10-30% faster [but idk how much of that is noise]. A few benchmarks seemed to show consistent differences of greater than 30%:

• benchNoirV2 (the first case): about 50% faster [consistently], for
  reasons I don’t quite understand.

• benchFastRedactRestore: about 50% faster

• benchFastRedactIntermediateWild: about 50% slower

• benchNoirV2Wild,benchNoirV2CensorFunction, benchNoirV2Wild,
  benchNoirV2CensorFunction: 2-4x as fast

• benchFastRedactCensorFunction: 50-100% faster

Here are the full results:

Before [ran twice, and the results were pretty similar]

benchNoirV2500: 84.279ms
benchFastRedact500: 14.280ms
benchFastRedactRestore500: 22.773ms
benchNoirV2Wild500: 105.580ms
benchFastRedactWild500: 40.533ms
benchFastRedactWildRestore500: 41.080ms
benchFastRedactIntermediateWild500: 107.193ms
benchFastRedactIntermediateWildRestore500: 92.896ms
benchJSONStringify500: 323.536ms
benchNoirV2Serialize500: 407.667ms
benchFastRedactSerialize500: 337.723ms
benchNoirV2WildSerialize500: 380.418ms
benchFastRedactWildSerialize500: 372.057ms
benchFastRedactIntermediateWildSerialize500: 417.458ms
benchFastRedactIntermediateWildMatchWildOutcomeSerialize500: 572.464ms
benchFastRedactStaticMatchWildOutcomeSerialize500: 348.632ms
benchNoirV2CensorFunction500: 70.804ms
benchFastRedactCensorFunction500: 59.476ms
benchNoirV2500: 48.808ms
benchFastRedact500: 11.550ms
benchFastRedactRestore500: 13.436ms
benchNoirV2Wild500: 61.383ms
benchFastRedactWild500: 31.472ms
benchFastRedactWildRestore500: 34.325ms
benchFastRedactIntermediateWild500: 128.071ms
benchFastRedactIntermediateWildRestore500: 128.602ms
benchJSONStringify500: 317.474ms
benchNoirV2Serialize500: 395.179ms
benchFastRedactSerialize500: 323.449ms
benchNoirV2WildSerialize500: 369.051ms
benchFastRedactWildSerialize500: 356.204ms
benchFastRedactIntermediateWildSerialize500: 426.994ms
benchFastRedactIntermediateWildMatchWildOutcomeSerialize500: 531.789ms
benchFastRedactStaticMatchWildOutcomeSerialize500: 340.540ms
benchNoirV2CensorFunction500: 38.953ms
benchFastRedactCensorFunction500: 53.361ms

After [ran twice, and the results were pretty similar]

benchNoirV2500: 54.057ms
benchFastRedact500: 15.949ms
benchFastRedactRestore500: 13.749ms
benchNoirV2Wild500: 34.787ms
benchFastRedactWild500: 44.642ms
benchFastRedactWildRestore500: 42.949ms
benchFastRedactIntermediateWild500: 162.311ms
benchFastRedactIntermediateWildRestore500: 106.921ms
benchJSONStringify500: 306.766ms
benchNoirV2Serialize500: 403.440ms
benchFastRedactSerialize500: 321.294ms
benchNoirV2WildSerialize500: 366.650ms
benchFastRedactWildSerialize500: 342.946ms
benchFastRedactIntermediateWildSerialize500: 437.797ms
benchFastRedactIntermediateWildMatchWildOutcomeSerialize500: 573.556ms
benchFastRedactStaticMatchWildOutcomeSerialize500: 336.521ms
benchNoirV2CensorFunction500: 27.110ms
benchFastRedactCensorFunction500: 47.454ms
benchNoirV2500: 38.437ms
benchFastRedact500: 10.272ms
benchFastRedactRestore500: 9.693ms
benchNoirV2Wild500: 18.504ms
benchFastRedactWild500: 30.266ms
benchFastRedactWildRestore500: 35.108ms
benchFastRedactIntermediateWild500: 131.794ms
benchFastRedactIntermediateWildRestore500: 110.691ms
benchJSONStringify500: 299.861ms
benchNoirV2Serialize500: 384.236ms
benchFastRedactSerialize500: 314.049ms
benchNoirV2WildSerialize500: 365.485ms
benchFastRedactWildSerialize500: 344.158ms
benchFastRedactIntermediateWildSerialize500: 426.421ms
benchFastRedactIntermediateWildMatchWildOutcomeSerialize500: 537.079ms
benchFastRedactStaticMatchWildOutcomeSerialize500: 340.104ms
benchNoirV2CensorFunction500: 16.021ms
benchFastRedactCensorFunction500: 31.100ms

[davidmarkclements]

wow. amazing work thank you

[davidmarkclements]

have you verified that V8 doesn't optimize for the getObj shape (which would essentially lead to the same situation)? If we could randomly generate slightly different shapes (but with the necessary paths) this would be even more realistic.

[ethanresnick]

have you verified that V8 doesn't optimize for the getObj shape (which would essentially lead to the same situation)?

I haven't verified anything in v8...but I'm not sure I understand the point you're raising. What I'm trying to control with this PR is the object's shape was previously changing between benchmark cases: it starts with the keys as strings, then pino-noir sets some of the keys to Redacted objects, and then default censor value for fast-redact sets them back to strings, and so on.

[ethanresnick]

In the meantime, I've fixed up the style

[davidmarkclements]

Yeah that’s true this does remove the confounding factor of the shared obj

V8 also uses hidden classes (aka shapes, aka “maps”) to optimise multiple objects created with the same shape. So that means the function returning the same shape can also suffer from a related issue where the later tests will be faster because of behind the scenes optimisation. To avoid this varying the shape between scenarios should be even more realistic

[ethanresnick]

V8 also uses hidden classes (aka shapes, aka “maps”) to optimise multiple objects created with the same shape. So that means the function returning the same shape can also suffer from a related issue where the later tests will be faster because of behind the scenes optimisation. To avoid this varying the shape between scenarios should be even more realistic

Ahh, gotcha. And I’m not opposed to randomly tweaking the shape per test.

Two ideas, though, which might be simpler:

1. Maybe we could just move the getObj() calls outside the benchmark case (i.e., make each case’s object before we start the clock)? I guess we’d store those objects in an array, and each benchmark case would start with const obj = objects[xxxx], since I think(?) it’s safe to assume that lookup will always be the same speed?

2. If the above assumption isn’t safe, maybe we can just call getObj a bunch of times in a loop [where the result’s saved/used somewhere so the whole loop isn’t compiled away], to get V8 into kicking in whatever optimizations it’s gonna make for getObj before any test start.

That said, the object creation only happens once per case, vs the redaction happening 500 times, so I have to imagine that that creation isn’t effecting the results much

[davidmarkclements]

yeah creation isn't an issue - but rather it's possible that creating the same shape a few times can trigger an optimization of the shape.

Since theres only a few cases you could just create a different object (but equal in size) for each benchmark - so for instance, manually create different single-letter properties in each case

[ethanresnick]

Ahh, now I think I follow. Take a look at the commit I just pushed, and see if it gets at the issue. For now, I only varied the top-level keys, but I think that's enough?

[davidmarkclements]

yeah that should be enough - are the results any different?

[ethanresnick]

Not really, or at least it all looks like noise to me:

benchNoirV2*500: 56.187ms
benchFastRedact*500: 15.636ms
benchFastRedactRestore*500: 18.708ms
benchNoirV2Wild*500: 37.492ms
benchFastRedactWild*500: 41.489ms
benchFastRedactWildRestore*500: 41.012ms
benchFastRedactIntermediateWild*500: 177.360ms
benchFastRedactIntermediateWildRestore*500: 99.931ms
benchJSONStringify*500: 321.774ms
benchNoirV2Serialize*500: 406.218ms
benchFastRedactSerialize*500: 324.288ms
benchNoirV2WildSerialize*500: 419.127ms
benchFastRedactWildSerialize*500: 369.263ms
benchFastRedactIntermediateWildSerialize*500: 450.892ms
benchFastRedactIntermediateWildMatchWildOutcomeSerialize*500: 661.560ms
benchFastRedactStaticMatchWildOutcomeSerialize*500: 375.092ms
benchNoirV2CensorFunction*500: 26.578ms
benchFastRedactCensorFunction*500: 41.205ms
benchNoirV2*500: 39.721ms
benchFastRedact*500: 8.976ms
benchFastRedactRestore*500: 10.869ms
benchNoirV2Wild*500: 16.557ms
benchFastRedactWild*500: 27.925ms
benchFastRedactWildRestore*500: 32.596ms
benchFastRedactIntermediateWild*500: 172.279ms
benchFastRedactIntermediateWildRestore*500: 125.881ms
benchJSONStringify*500: 312.815ms
benchNoirV2Serialize*500: 406.060ms
benchFastRedactSerialize*500: 333.660ms
benchNoirV2WildSerialize*500: 419.161ms
benchFastRedactWildSerialize*500: 365.389ms
benchFastRedactIntermediateWildSerialize*500: 452.600ms
benchFastRedactIntermediateWildMatchWildOutcomeSerialize*500: 630.983ms
benchFastRedactStaticMatchWildOutcomeSerialize*500: 370.881ms
benchNoirV2CensorFunction*500: 16.885ms
benchFastRedactCensorFunction*500: 29.958ms

[mcollina]

lgtm