[improvement] add jmh benchmark - #179

Merged
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh
Jun 19, 2019
Merged

[improvement] add jmh benchmark#179
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh

Conversation

@wenhoujx

@wenhoujxwenhoujx commented Jun 18, 2019

Copy link
Copy Markdown
Contributor

add span benchmarks according to @carterkozak 's comments on #176
remove

Before this PR

After this PR

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@wenhoujx
wenhoujx requested a review from a team as a code ownerJune 18, 2019 16:42
@wenhoujxwenhoujx changed the title [improvement] add jmh benchmark[wip][improvement] add jmh benchmarkJun 18, 2019
@wenhoujx

Copy link
Copy Markdown
ContributorAuthor
Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 8.000 ± 1.116 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.007 ± 0.018 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2415.347 ± 343.585 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 6515.868 ± 952.898 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.002 ± 0.004 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 6657.981 ± 1158.048 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1554.165 ± 282.045 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.207 ± 0.415 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.048 ± 0.095 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 62.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.undecidedCallable avgt 5 2064.025 ± 496.632 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 6414.531 ± 1457.700 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1275.209 ± 0.080 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 6466.522 ± 2177.014 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1283.894 ± 176.306 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.250 ± 0.119 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.050 ± 0.018 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 2469.110 ± 552.636 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 5264.609 ± 1174.790 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.013 ± 0.097 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 5355.468 ± 847.513 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1272.001 ± 273.956 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.136 ± 0.215 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.032 ± 0.054 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 45.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 45.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 154163.541 ± 60469.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 7292.102 ± 2372.250 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108564.545 ± 13.229 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 7433.542 ± 2531.196 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110667.398 ± 10206.453 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.230 ± 0.175 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.490 ± 3.741 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 232746.583 ± 61347.557 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 4880.881 ± 1344.496 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108926.232 ± 9.732 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 5037.797 ± 2114.684 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 112203.221 ± 18934.702 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.080 ± 0.108 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 1.809 ± 2.714 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 39.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 45.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 172844.869 ± 47191.122 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 6543.852 ± 1775.645 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 108321.556 ± 11.003 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 6670.054 ± 2739.824 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110249.676 ± 20044.784 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.145 ± 0.086 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.396 ± 0.759 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 56.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 51.000 ms

@wenhoujxwenhoujx changed the title [wip][improvement] add jmh benchmark[improvement] add jmh benchmarkJun 18, 2019
Tracer.fastCompleteSpan();
}
};
blackhole.consume(callable.call());

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need to blackhole the null result from our callable, however we should blackhole the output, which in this case is a series of Span objects:

Tracer.subscribe("jmh", blackhole::consume);

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak thanks for CR, does it matter that every call of Tracer.startSpan("span"); starts a span with the same name?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Spans with the same name are totally fine, we have them in practice via recursive methods ;-)

@wenhoujxwenhoujxJun 18, 2019

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good example. do you want each span subscribed by blackhole::consume? which makes the precomputed Callable<Object> becomes a Function<BlackHole, Object> or even Consumer<BlackHole>

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We just need to set the subscriber at the beginning when we get the blackhole instance. Ideally we could configure that globally instead of for each benchmark method, but I’m not sure how. Note that tracing observer registration is a static per jvm, so concurrent measurements will reset the observer

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak can i use a UUID as the observer name? so that each invocation has different observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, you'll end up writing each span to N observers instead of the case we want to benchmark with a single observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd start with something along these lines:

@Fork(1)
@Threads(1)
@State(Scope.Benchmark)
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 3, time = 3)
publicclassSimpleBenchmark {
@Setuppublicvoidsetup(Blackholeblackhole) {
Tracer.subscribe("jmh", blackhole::consume);
Tracer.setSampler(AlwaysSampler.INSTANCE);
}
@TearDownpublicvoidtearDown() {
Tracer.unsubscribe("jmh");
}
@BenchmarkpublicvoidnestedSpans() {
for (inti = 0; i < 100; i++) {
Tracer.startSpan("span");
}
for (inti = 0; i < 100; i++) {
Tracer.fastCompleteSpan();
}
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The sampler can be parameterized so that we can write one benchmark and get results for both the sampled and unsampled cases using parameterized values in state, see the internal class I linked in a DM.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cool 👍

return NOOP_CALLABLE.call();
} finally {
Tracer.fastCompleteSpan();
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should precompute the callable wrappers.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

the three benchmarks has similar throughput and gc? i must be doing something wrong:

Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 7.038 ± 1.780 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.010 ± 0.024 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2044.400 ± 666.394 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 7716.063 ± 2366.255 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.001 ± 0.003 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 7824.897 ± 1877.372 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1543.332 ± 148.294 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.215 ± 0.295 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.042 ± 0.059 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 48.000 ms
TracingBenchmark.undecidedCallable avgt 5 1866.992 ± 143.168 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 7203.966 ± 614.308 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1276.788 ± 0.104 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 7253.810 ± 743.664 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1285.946 ± 145.356 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.249 ± 0.230 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.044 ± 0.043 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 66.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 1814.516 ± 187.818 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 7299.155 ± 860.457 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.001 ± 0.003 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 7375.237 ± 1013.081 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1261.238 ± 132.557 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.261 ± 0.217 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.045 ± 0.036 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 69.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 132066.752 ± 13804.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 8434.893 ± 861.115 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108771.325 ± 97.708 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8511.749 ± 1666.471 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109709.414 ± 11697.728 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.241 ± 0.212 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.108 ± 2.845 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 69.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 52.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 133724.771 ± 33937.147 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 8392.403 ± 1989.890 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 109025.207 ± 14.804 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8443.440 ± 1705.394 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109793.656 ± 15341.244 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.274 ± 0.169 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.569 ± 2.340 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 49.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 130368.665 ± 20251.780 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 8542.379 ± 1342.633 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108754.963 ± 6.620 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8682.420 ± 564.495 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110647.106 ± 14168.551 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.212 ± 0.182 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.698 ± 2.276 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 73.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 53.000 ms

Comment threadtracing-benchmarks/build.gradle Outdated
dependencies {
annotationProcessor 'org.openjdk.jmh:jmh-generator-annprocess'
compileOnly 'org.openjdk.jmh:jmh-generator-annprocess'
compile "org.immutables:value::annotations"

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about compileOnly + annotationProocessor?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.


> Task :tracing-benchmarks:compileJmhJava FAILED
warning: unknown enum constant ImplementationVisibility.PACKAGE
reason: class file for org.immutables.value.Value$Style$ImplementationVisibility not found
warning: unknown enum constant ImplementationVisibility.PACKAGE
error: warnings found and -Werror specified
1 error
2 warnings

the same

@carterkozak

Copy link
Copy Markdown
Contributor

Will take a look in a while.

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

new benchmark with parameters and Blackhole in @Setup method

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 25 19142.332 ± 446.597 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 25 1494.972 ± 34.335 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space SAMPLE avgt 25 1496.533 ± 34.313 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm SAMPLE avgt 25 31522.248 ± 216.732 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm SAMPLE avgt 25 0.109 ± 0.010 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 25 1161.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 25 857.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 25 20399.207 ± 1887.793 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 25 1420.130 ± 117.529 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space DO_NOT_SAMPLE avgt 25 1420.401 ± 116.523 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm DO_NOT_SAMPLE avgt 25 31500.468 ± 241.627 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen DO_NOT_SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm DO_NOT_SAMPLE avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 25 1051.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 25 867.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 25 19134.032 ± 618.860 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 25 1496.999 ± 48.254 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space UNDECIDED avgt 25 1500.946 ± 47.072 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm UNDECIDED avgt 25 31573.414 ± 185.387 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen UNDECIDED avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm UNDECIDED avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 25 1077.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 25 849.000 ms

@wenhoujx

wenhoujx commented Jun 19, 2019

Copy link
Copy Markdown
ContributorAuthor

new benchmark for commit 7d1d92f


Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@carterkozakcarterkozak left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, thanks!

@bulldozer-bot
bulldozer-botBot merged commit 42aafc8 into palantir:developJun 19, 2019
@schlosnaschlosna mentioned this pull request Jun 19, 2019
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

@wenhoujx@carterkozak@schlosna
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Add copy buttons to all
 blocks\n(function() {\n function addCopyButtons() {\n document.querySelectorAll('pre code').forEach(function(codeBlock) {\n if (codeBlock.parentElement.hasAttribute('data-copy-added')) return;\n codeBlock.parentElement.setAttribute('data-copy-added', 'true');\n \n var btn = document.createElement('button');\n btn.textContent = 'Copy';\n btn.style.cssText = 'position:absolute;top:4px;right:4px;padding:2px 8px;font-size:11px;background:#4ecdc4;border:none;border-radius:4px;color:#1a1a2e;cursor:pointer;opacity:0.7;transition:opacity 0.2s;';\n btn.onmouseover = function() { this.style.opacity = '1'; };\n btn.onmouseout = function() { this.style.opacity = '0.7'; };\n btn.onclick = function() {\n navigator.clipboard.writeText(codeBlock.textContent).then(function() {\n btn.textContent = 'Copied!';\n setTimeout(function() { btn.textContent = 'Copy'; }, 1500);\n });\n };\n codeBlock.parentElement.style.position = 'relative';\n codeBlock.parentElement.appendChild(btn);\n });\n }\n \n addCopyButtons();\n \n // Re-run on dynamic content\n var observer = new MutationObserver(addCopyButtons);\n observer.observe(document.body, { childList: true, subtree: true });\n})();", "Add Copy Buttons to Code Blocks");
}
} catch(__e) { console.warn('[Userscript:Add Copy Buttons to Code Blocks]', __e); }
})();
(function(){
try {
var __m = "github.com";
var __re = new RegExp('^' + "github\\.com" + '
Skip to content

[improvement] add jmh benchmark - #179

Merged
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh
Jun 19, 2019
Merged

[improvement] add jmh benchmark#179
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh

Conversation

@wenhoujx

@wenhoujxwenhoujx commented Jun 18, 2019

Copy link
Copy Markdown
Contributor

add span benchmarks according to @carterkozak 's comments on #176
remove

Before this PR

After this PR

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@wenhoujx
wenhoujx requested a review from a team as a code ownerJune 18, 2019 16:42
@wenhoujxwenhoujx changed the title [improvement] add jmh benchmark[wip][improvement] add jmh benchmarkJun 18, 2019
@wenhoujx

Copy link
Copy Markdown
ContributorAuthor
Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 8.000 ± 1.116 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.007 ± 0.018 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2415.347 ± 343.585 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 6515.868 ± 952.898 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.002 ± 0.004 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 6657.981 ± 1158.048 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1554.165 ± 282.045 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.207 ± 0.415 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.048 ± 0.095 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 62.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.undecidedCallable avgt 5 2064.025 ± 496.632 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 6414.531 ± 1457.700 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1275.209 ± 0.080 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 6466.522 ± 2177.014 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1283.894 ± 176.306 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.250 ± 0.119 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.050 ± 0.018 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 2469.110 ± 552.636 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 5264.609 ± 1174.790 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.013 ± 0.097 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 5355.468 ± 847.513 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1272.001 ± 273.956 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.136 ± 0.215 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.032 ± 0.054 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 45.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 45.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 154163.541 ± 60469.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 7292.102 ± 2372.250 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108564.545 ± 13.229 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 7433.542 ± 2531.196 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110667.398 ± 10206.453 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.230 ± 0.175 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.490 ± 3.741 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 232746.583 ± 61347.557 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 4880.881 ± 1344.496 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108926.232 ± 9.732 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 5037.797 ± 2114.684 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 112203.221 ± 18934.702 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.080 ± 0.108 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 1.809 ± 2.714 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 39.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 45.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 172844.869 ± 47191.122 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 6543.852 ± 1775.645 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 108321.556 ± 11.003 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 6670.054 ± 2739.824 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110249.676 ± 20044.784 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.145 ± 0.086 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.396 ± 0.759 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 56.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 51.000 ms

@wenhoujxwenhoujx changed the title [wip][improvement] add jmh benchmark[improvement] add jmh benchmarkJun 18, 2019
Tracer.fastCompleteSpan();
}
};
blackhole.consume(callable.call());

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need to blackhole the null result from our callable, however we should blackhole the output, which in this case is a series of Span objects:

Tracer.subscribe("jmh", blackhole::consume);

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak thanks for CR, does it matter that every call of Tracer.startSpan("span"); starts a span with the same name?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Spans with the same name are totally fine, we have them in practice via recursive methods ;-)

@wenhoujxwenhoujxJun 18, 2019

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good example. do you want each span subscribed by blackhole::consume? which makes the precomputed Callable<Object> becomes a Function<BlackHole, Object> or even Consumer<BlackHole>

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We just need to set the subscriber at the beginning when we get the blackhole instance. Ideally we could configure that globally instead of for each benchmark method, but I’m not sure how. Note that tracing observer registration is a static per jvm, so concurrent measurements will reset the observer

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak can i use a UUID as the observer name? so that each invocation has different observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, you'll end up writing each span to N observers instead of the case we want to benchmark with a single observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd start with something along these lines:

@Fork(1)
@Threads(1)
@State(Scope.Benchmark)
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 3, time = 3)
publicclassSimpleBenchmark {
@Setuppublicvoidsetup(Blackholeblackhole) {
Tracer.subscribe("jmh", blackhole::consume);
Tracer.setSampler(AlwaysSampler.INSTANCE);
}
@TearDownpublicvoidtearDown() {
Tracer.unsubscribe("jmh");
}
@BenchmarkpublicvoidnestedSpans() {
for (inti = 0; i < 100; i++) {
Tracer.startSpan("span");
}
for (inti = 0; i < 100; i++) {
Tracer.fastCompleteSpan();
}
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The sampler can be parameterized so that we can write one benchmark and get results for both the sampled and unsampled cases using parameterized values in state, see the internal class I linked in a DM.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cool 👍

return NOOP_CALLABLE.call();
} finally {
Tracer.fastCompleteSpan();
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should precompute the callable wrappers.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

the three benchmarks has similar throughput and gc? i must be doing something wrong:

Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 7.038 ± 1.780 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.010 ± 0.024 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2044.400 ± 666.394 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 7716.063 ± 2366.255 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.001 ± 0.003 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 7824.897 ± 1877.372 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1543.332 ± 148.294 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.215 ± 0.295 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.042 ± 0.059 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 48.000 ms
TracingBenchmark.undecidedCallable avgt 5 1866.992 ± 143.168 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 7203.966 ± 614.308 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1276.788 ± 0.104 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 7253.810 ± 743.664 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1285.946 ± 145.356 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.249 ± 0.230 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.044 ± 0.043 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 66.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 1814.516 ± 187.818 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 7299.155 ± 860.457 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.001 ± 0.003 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 7375.237 ± 1013.081 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1261.238 ± 132.557 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.261 ± 0.217 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.045 ± 0.036 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 69.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 132066.752 ± 13804.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 8434.893 ± 861.115 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108771.325 ± 97.708 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8511.749 ± 1666.471 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109709.414 ± 11697.728 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.241 ± 0.212 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.108 ± 2.845 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 69.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 52.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 133724.771 ± 33937.147 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 8392.403 ± 1989.890 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 109025.207 ± 14.804 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8443.440 ± 1705.394 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109793.656 ± 15341.244 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.274 ± 0.169 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.569 ± 2.340 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 49.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 130368.665 ± 20251.780 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 8542.379 ± 1342.633 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108754.963 ± 6.620 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8682.420 ± 564.495 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110647.106 ± 14168.551 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.212 ± 0.182 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.698 ± 2.276 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 73.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 53.000 ms

Comment threadtracing-benchmarks/build.gradle Outdated
dependencies {
annotationProcessor 'org.openjdk.jmh:jmh-generator-annprocess'
compileOnly 'org.openjdk.jmh:jmh-generator-annprocess'
compile "org.immutables:value::annotations"

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about compileOnly + annotationProocessor?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.


> Task :tracing-benchmarks:compileJmhJava FAILED
warning: unknown enum constant ImplementationVisibility.PACKAGE
reason: class file for org.immutables.value.Value$Style$ImplementationVisibility not found
warning: unknown enum constant ImplementationVisibility.PACKAGE
error: warnings found and -Werror specified
1 error
2 warnings

the same

@carterkozak

Copy link
Copy Markdown
Contributor

Will take a look in a while.

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

new benchmark with parameters and Blackhole in @Setup method

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 25 19142.332 ± 446.597 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 25 1494.972 ± 34.335 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space SAMPLE avgt 25 1496.533 ± 34.313 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm SAMPLE avgt 25 31522.248 ± 216.732 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm SAMPLE avgt 25 0.109 ± 0.010 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 25 1161.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 25 857.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 25 20399.207 ± 1887.793 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 25 1420.130 ± 117.529 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space DO_NOT_SAMPLE avgt 25 1420.401 ± 116.523 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm DO_NOT_SAMPLE avgt 25 31500.468 ± 241.627 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen DO_NOT_SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm DO_NOT_SAMPLE avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 25 1051.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 25 867.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 25 19134.032 ± 618.860 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 25 1496.999 ± 48.254 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space UNDECIDED avgt 25 1500.946 ± 47.072 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm UNDECIDED avgt 25 31573.414 ± 185.387 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen UNDECIDED avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm UNDECIDED avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 25 1077.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 25 849.000 ms

@wenhoujx

wenhoujx commented Jun 19, 2019

Copy link
Copy Markdown
ContributorAuthor

new benchmark for commit 7d1d92f


Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@carterkozakcarterkozak left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, thanks!

@bulldozer-bot
bulldozer-botBot merged commit 42aafc8 into palantir:developJun 19, 2019
@schlosnaschlosna mentioned this pull request Jun 19, 2019
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

@wenhoujx@carterkozak@schlosna
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Force GitHub README to respect dark mode\n(function() {\n var style = document.createElement('style');\n style.textContent = '\n .markdown-body {\n color-scheme: dark light;\n }\n .markdown-body pre { background: #161b22 !important; }\n .markdown-body code { background: rgba(110, 118, 129, 0.4) !important; }\n .markdown-body table th, .markdown-body table td { border-color: #30363d !important; }\n .markdown-body img { background: #0d1117; }\n .markdown-body blockquote { border-left-color: #8b949e; }\n .markdown-body hr { border-color: #30363d; }\n ';\n document.head.appendChild(style);\n})();", "GitHub Dark Mode README Fix"); } } catch(__e) { console.warn('[Userscript:GitHub Dark Mode README Fix]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + '
Skip to content

[improvement] add jmh benchmark - #179

Merged
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh
Jun 19, 2019
Merged

[improvement] add jmh benchmark#179
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh

Conversation

@wenhoujx

@wenhoujxwenhoujx commented Jun 18, 2019

Copy link
Copy Markdown
Contributor

add span benchmarks according to @carterkozak 's comments on #176
remove

Before this PR

After this PR

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@wenhoujx
wenhoujx requested a review from a team as a code ownerJune 18, 2019 16:42
@wenhoujxwenhoujx changed the title [improvement] add jmh benchmark[wip][improvement] add jmh benchmarkJun 18, 2019
@wenhoujx

Copy link
Copy Markdown
ContributorAuthor
Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 8.000 ± 1.116 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.007 ± 0.018 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2415.347 ± 343.585 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 6515.868 ± 952.898 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.002 ± 0.004 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 6657.981 ± 1158.048 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1554.165 ± 282.045 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.207 ± 0.415 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.048 ± 0.095 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 62.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.undecidedCallable avgt 5 2064.025 ± 496.632 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 6414.531 ± 1457.700 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1275.209 ± 0.080 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 6466.522 ± 2177.014 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1283.894 ± 176.306 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.250 ± 0.119 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.050 ± 0.018 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 2469.110 ± 552.636 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 5264.609 ± 1174.790 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.013 ± 0.097 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 5355.468 ± 847.513 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1272.001 ± 273.956 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.136 ± 0.215 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.032 ± 0.054 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 45.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 45.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 154163.541 ± 60469.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 7292.102 ± 2372.250 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108564.545 ± 13.229 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 7433.542 ± 2531.196 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110667.398 ± 10206.453 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.230 ± 0.175 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.490 ± 3.741 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 232746.583 ± 61347.557 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 4880.881 ± 1344.496 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108926.232 ± 9.732 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 5037.797 ± 2114.684 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 112203.221 ± 18934.702 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.080 ± 0.108 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 1.809 ± 2.714 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 39.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 45.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 172844.869 ± 47191.122 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 6543.852 ± 1775.645 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 108321.556 ± 11.003 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 6670.054 ± 2739.824 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110249.676 ± 20044.784 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.145 ± 0.086 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.396 ± 0.759 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 56.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 51.000 ms

@wenhoujxwenhoujx changed the title [wip][improvement] add jmh benchmark[improvement] add jmh benchmarkJun 18, 2019
Tracer.fastCompleteSpan();
}
};
blackhole.consume(callable.call());

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need to blackhole the null result from our callable, however we should blackhole the output, which in this case is a series of Span objects:

Tracer.subscribe("jmh", blackhole::consume);

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak thanks for CR, does it matter that every call of Tracer.startSpan("span"); starts a span with the same name?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Spans with the same name are totally fine, we have them in practice via recursive methods ;-)

@wenhoujxwenhoujxJun 18, 2019

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good example. do you want each span subscribed by blackhole::consume? which makes the precomputed Callable<Object> becomes a Function<BlackHole, Object> or even Consumer<BlackHole>

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We just need to set the subscriber at the beginning when we get the blackhole instance. Ideally we could configure that globally instead of for each benchmark method, but I’m not sure how. Note that tracing observer registration is a static per jvm, so concurrent measurements will reset the observer

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak can i use a UUID as the observer name? so that each invocation has different observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, you'll end up writing each span to N observers instead of the case we want to benchmark with a single observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd start with something along these lines:

@Fork(1)
@Threads(1)
@State(Scope.Benchmark)
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 3, time = 3)
publicclassSimpleBenchmark {
@Setuppublicvoidsetup(Blackholeblackhole) {
Tracer.subscribe("jmh", blackhole::consume);
Tracer.setSampler(AlwaysSampler.INSTANCE);
}
@TearDownpublicvoidtearDown() {
Tracer.unsubscribe("jmh");
}
@BenchmarkpublicvoidnestedSpans() {
for (inti = 0; i < 100; i++) {
Tracer.startSpan("span");
}
for (inti = 0; i < 100; i++) {
Tracer.fastCompleteSpan();
}
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The sampler can be parameterized so that we can write one benchmark and get results for both the sampled and unsampled cases using parameterized values in state, see the internal class I linked in a DM.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cool 👍

return NOOP_CALLABLE.call();
} finally {
Tracer.fastCompleteSpan();
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should precompute the callable wrappers.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

the three benchmarks has similar throughput and gc? i must be doing something wrong:

Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 7.038 ± 1.780 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.010 ± 0.024 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2044.400 ± 666.394 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 7716.063 ± 2366.255 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.001 ± 0.003 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 7824.897 ± 1877.372 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1543.332 ± 148.294 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.215 ± 0.295 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.042 ± 0.059 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 48.000 ms
TracingBenchmark.undecidedCallable avgt 5 1866.992 ± 143.168 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 7203.966 ± 614.308 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1276.788 ± 0.104 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 7253.810 ± 743.664 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1285.946 ± 145.356 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.249 ± 0.230 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.044 ± 0.043 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 66.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 1814.516 ± 187.818 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 7299.155 ± 860.457 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.001 ± 0.003 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 7375.237 ± 1013.081 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1261.238 ± 132.557 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.261 ± 0.217 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.045 ± 0.036 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 69.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 132066.752 ± 13804.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 8434.893 ± 861.115 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108771.325 ± 97.708 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8511.749 ± 1666.471 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109709.414 ± 11697.728 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.241 ± 0.212 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.108 ± 2.845 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 69.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 52.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 133724.771 ± 33937.147 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 8392.403 ± 1989.890 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 109025.207 ± 14.804 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8443.440 ± 1705.394 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109793.656 ± 15341.244 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.274 ± 0.169 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.569 ± 2.340 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 49.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 130368.665 ± 20251.780 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 8542.379 ± 1342.633 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108754.963 ± 6.620 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8682.420 ± 564.495 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110647.106 ± 14168.551 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.212 ± 0.182 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.698 ± 2.276 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 73.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 53.000 ms

Comment threadtracing-benchmarks/build.gradle Outdated
dependencies {
annotationProcessor 'org.openjdk.jmh:jmh-generator-annprocess'
compileOnly 'org.openjdk.jmh:jmh-generator-annprocess'
compile "org.immutables:value::annotations"

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about compileOnly + annotationProocessor?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.


> Task :tracing-benchmarks:compileJmhJava FAILED
warning: unknown enum constant ImplementationVisibility.PACKAGE
reason: class file for org.immutables.value.Value$Style$ImplementationVisibility not found
warning: unknown enum constant ImplementationVisibility.PACKAGE
error: warnings found and -Werror specified
1 error
2 warnings

the same

@carterkozak

Copy link
Copy Markdown
Contributor

Will take a look in a while.

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

new benchmark with parameters and Blackhole in @Setup method

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 25 19142.332 ± 446.597 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 25 1494.972 ± 34.335 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space SAMPLE avgt 25 1496.533 ± 34.313 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm SAMPLE avgt 25 31522.248 ± 216.732 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm SAMPLE avgt 25 0.109 ± 0.010 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 25 1161.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 25 857.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 25 20399.207 ± 1887.793 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 25 1420.130 ± 117.529 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space DO_NOT_SAMPLE avgt 25 1420.401 ± 116.523 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm DO_NOT_SAMPLE avgt 25 31500.468 ± 241.627 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen DO_NOT_SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm DO_NOT_SAMPLE avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 25 1051.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 25 867.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 25 19134.032 ± 618.860 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 25 1496.999 ± 48.254 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space UNDECIDED avgt 25 1500.946 ± 47.072 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm UNDECIDED avgt 25 31573.414 ± 185.387 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen UNDECIDED avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm UNDECIDED avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 25 1077.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 25 849.000 ms

@wenhoujx

wenhoujx commented Jun 19, 2019

Copy link
Copy Markdown
ContributorAuthor

new benchmark for commit 7d1d92f


Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@carterkozakcarterkozak left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, thanks!

@bulldozer-bot
bulldozer-botBot merged commit 42aafc8 into palantir:developJun 19, 2019
@schlosnaschlosna mentioned this pull request Jun 19, 2019
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

@wenhoujx@carterkozak@schlosna
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Highlight search terms from Google/DuckDuckGo/Bing referrer\n(function() {\n var ref = document.referrer;\n var terms = [];\n \n if (ref.includes('google.com') || ref.includes('duckduckgo.com') || ref.includes('bing.com')) {\n var url = new URL(ref);\n var q = url.searchParams.get('q') || url.searchParams.get('p');\n if (q) {\n terms = q.split(/\\s+/).filter(function(t) { return t.length > 2; });\n }\n }\n \n if (terms.length === 0) return;\n \n var style = document.createElement('style');\n style.textContent = '.userscript-highlight { background: #fbbf24; color: #1a1a2e; padding: 1px 3px; border-radius: 2px; }';\n document.head.appendChild(style);\n \n function highlight(node) {\n if (node.nodeType === 3) { // text node\n var text = node.textContent;\n var found = false;\n terms.forEach(function(term) {\n var regex = new RegExp('(' + term.replace(/[.*+?^${}()|[\\]\\\\]/g, '\\\\') + ')', 'gi');\n if (regex.test(text)) {\n found = true;\n var frag = document.createDocumentFragment();\n var parts = text.split(regex);\n parts.forEach(function(part, i) {\n if (i % 2 === 0) {\n frag.appendChild(document.createTextNode(part));\n } else {\n var span = document.createElement('span');\n span.className = 'userscript-highlight';\n span.textContent = part;\n frag.appendChild(span);\n }\n });\n node.parentNode.replaceChild(frag, node);\n }\n });\n } else if (node.nodeType === 1 && node.childNodes) { // element\n var skipTags = ['SCRIPT', 'STYLE', 'NOSCRIPT', 'TEXTAREA', 'INPUT', 'SELECT'];\n if (!skipTags.includes(node.tagName)) {\n Array.from(node.childNodes).forEach(highlight);\n }\n }\n }\n \n highlight(document.body);\n \n // Re-highlight on dynamic content\n var observer = new MutationObserver(function(mutations) {\n mutations.forEach(function(m) {\n m.addedNodes.forEach(function(node) {\n if (node.nodeType === 1 || node.nodeType === 3) highlight(node);\n });\n });\n });\n observer.observe(document.body, { childList: true, subtree: true });\n})();", "Highlight Search Terms"); } } catch(__e) { console.warn('[Userscript:Highlight Search Terms]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + '
Skip to content

[improvement] add jmh benchmark - #179

Merged
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh
Jun 19, 2019
Merged

[improvement] add jmh benchmark#179
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh

Conversation

@wenhoujx

@wenhoujxwenhoujx commented Jun 18, 2019

Copy link
Copy Markdown
Contributor

add span benchmarks according to @carterkozak 's comments on #176
remove

Before this PR

After this PR

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@wenhoujx
wenhoujx requested a review from a team as a code ownerJune 18, 2019 16:42
@wenhoujxwenhoujx changed the title [improvement] add jmh benchmark[wip][improvement] add jmh benchmarkJun 18, 2019
@wenhoujx

Copy link
Copy Markdown
ContributorAuthor
Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 8.000 ± 1.116 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.007 ± 0.018 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2415.347 ± 343.585 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 6515.868 ± 952.898 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.002 ± 0.004 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 6657.981 ± 1158.048 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1554.165 ± 282.045 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.207 ± 0.415 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.048 ± 0.095 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 62.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.undecidedCallable avgt 5 2064.025 ± 496.632 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 6414.531 ± 1457.700 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1275.209 ± 0.080 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 6466.522 ± 2177.014 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1283.894 ± 176.306 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.250 ± 0.119 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.050 ± 0.018 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 2469.110 ± 552.636 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 5264.609 ± 1174.790 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.013 ± 0.097 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 5355.468 ± 847.513 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1272.001 ± 273.956 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.136 ± 0.215 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.032 ± 0.054 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 45.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 45.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 154163.541 ± 60469.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 7292.102 ± 2372.250 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108564.545 ± 13.229 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 7433.542 ± 2531.196 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110667.398 ± 10206.453 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.230 ± 0.175 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.490 ± 3.741 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 232746.583 ± 61347.557 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 4880.881 ± 1344.496 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108926.232 ± 9.732 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 5037.797 ± 2114.684 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 112203.221 ± 18934.702 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.080 ± 0.108 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 1.809 ± 2.714 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 39.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 45.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 172844.869 ± 47191.122 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 6543.852 ± 1775.645 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 108321.556 ± 11.003 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 6670.054 ± 2739.824 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110249.676 ± 20044.784 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.145 ± 0.086 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.396 ± 0.759 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 56.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 51.000 ms

@wenhoujxwenhoujx changed the title [wip][improvement] add jmh benchmark[improvement] add jmh benchmarkJun 18, 2019
Tracer.fastCompleteSpan();
}
};
blackhole.consume(callable.call());

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need to blackhole the null result from our callable, however we should blackhole the output, which in this case is a series of Span objects:

Tracer.subscribe("jmh", blackhole::consume);

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak thanks for CR, does it matter that every call of Tracer.startSpan("span"); starts a span with the same name?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Spans with the same name are totally fine, we have them in practice via recursive methods ;-)

@wenhoujxwenhoujxJun 18, 2019

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good example. do you want each span subscribed by blackhole::consume? which makes the precomputed Callable<Object> becomes a Function<BlackHole, Object> or even Consumer<BlackHole>

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We just need to set the subscriber at the beginning when we get the blackhole instance. Ideally we could configure that globally instead of for each benchmark method, but I’m not sure how. Note that tracing observer registration is a static per jvm, so concurrent measurements will reset the observer

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak can i use a UUID as the observer name? so that each invocation has different observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, you'll end up writing each span to N observers instead of the case we want to benchmark with a single observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd start with something along these lines:

@Fork(1)
@Threads(1)
@State(Scope.Benchmark)
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 3, time = 3)
publicclassSimpleBenchmark {
@Setuppublicvoidsetup(Blackholeblackhole) {
Tracer.subscribe("jmh", blackhole::consume);
Tracer.setSampler(AlwaysSampler.INSTANCE);
}
@TearDownpublicvoidtearDown() {
Tracer.unsubscribe("jmh");
}
@BenchmarkpublicvoidnestedSpans() {
for (inti = 0; i < 100; i++) {
Tracer.startSpan("span");
}
for (inti = 0; i < 100; i++) {
Tracer.fastCompleteSpan();
}
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The sampler can be parameterized so that we can write one benchmark and get results for both the sampled and unsampled cases using parameterized values in state, see the internal class I linked in a DM.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cool 👍

return NOOP_CALLABLE.call();
} finally {
Tracer.fastCompleteSpan();
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should precompute the callable wrappers.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

the three benchmarks has similar throughput and gc? i must be doing something wrong:

Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 7.038 ± 1.780 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.010 ± 0.024 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2044.400 ± 666.394 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 7716.063 ± 2366.255 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.001 ± 0.003 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 7824.897 ± 1877.372 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1543.332 ± 148.294 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.215 ± 0.295 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.042 ± 0.059 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 48.000 ms
TracingBenchmark.undecidedCallable avgt 5 1866.992 ± 143.168 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 7203.966 ± 614.308 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1276.788 ± 0.104 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 7253.810 ± 743.664 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1285.946 ± 145.356 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.249 ± 0.230 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.044 ± 0.043 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 66.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 1814.516 ± 187.818 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 7299.155 ± 860.457 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.001 ± 0.003 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 7375.237 ± 1013.081 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1261.238 ± 132.557 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.261 ± 0.217 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.045 ± 0.036 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 69.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 132066.752 ± 13804.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 8434.893 ± 861.115 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108771.325 ± 97.708 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8511.749 ± 1666.471 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109709.414 ± 11697.728 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.241 ± 0.212 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.108 ± 2.845 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 69.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 52.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 133724.771 ± 33937.147 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 8392.403 ± 1989.890 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 109025.207 ± 14.804 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8443.440 ± 1705.394 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109793.656 ± 15341.244 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.274 ± 0.169 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.569 ± 2.340 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 49.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 130368.665 ± 20251.780 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 8542.379 ± 1342.633 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108754.963 ± 6.620 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8682.420 ± 564.495 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110647.106 ± 14168.551 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.212 ± 0.182 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.698 ± 2.276 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 73.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 53.000 ms

Comment threadtracing-benchmarks/build.gradle Outdated
dependencies {
annotationProcessor 'org.openjdk.jmh:jmh-generator-annprocess'
compileOnly 'org.openjdk.jmh:jmh-generator-annprocess'
compile "org.immutables:value::annotations"

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about compileOnly + annotationProocessor?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.


> Task :tracing-benchmarks:compileJmhJava FAILED
warning: unknown enum constant ImplementationVisibility.PACKAGE
reason: class file for org.immutables.value.Value$Style$ImplementationVisibility not found
warning: unknown enum constant ImplementationVisibility.PACKAGE
error: warnings found and -Werror specified
1 error
2 warnings

the same

@carterkozak

Copy link
Copy Markdown
Contributor

Will take a look in a while.

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

new benchmark with parameters and Blackhole in @Setup method

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 25 19142.332 ± 446.597 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 25 1494.972 ± 34.335 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space SAMPLE avgt 25 1496.533 ± 34.313 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm SAMPLE avgt 25 31522.248 ± 216.732 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm SAMPLE avgt 25 0.109 ± 0.010 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 25 1161.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 25 857.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 25 20399.207 ± 1887.793 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 25 1420.130 ± 117.529 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space DO_NOT_SAMPLE avgt 25 1420.401 ± 116.523 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm DO_NOT_SAMPLE avgt 25 31500.468 ± 241.627 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen DO_NOT_SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm DO_NOT_SAMPLE avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 25 1051.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 25 867.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 25 19134.032 ± 618.860 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 25 1496.999 ± 48.254 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space UNDECIDED avgt 25 1500.946 ± 47.072 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm UNDECIDED avgt 25 31573.414 ± 185.387 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen UNDECIDED avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm UNDECIDED avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 25 1077.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 25 849.000 ms

@wenhoujx

wenhoujx commented Jun 19, 2019

Copy link
Copy Markdown
ContributorAuthor

new benchmark for commit 7d1d92f


Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@carterkozakcarterkozak left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, thanks!

@bulldozer-bot
bulldozer-botBot merged commit 42aafc8 into palantir:developJun 19, 2019
@schlosnaschlosna mentioned this pull request Jun 19, 2019
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

@wenhoujx@carterkozak@schlosna
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Strip utm_, fbclid, gclid, etc. from all links on page\n(function() {\n var trackingParams = ['utm_source', 'utm_medium', 'utm_campaign', 'utm_term', 'utm_content',\n 'fbclid', 'gclid', 'dclid', 'msclkid', 'yclid',\n 'ref', 'ref_src', 'source', 'medium', 'campaign'];\n \n function cleanUrl(url) {\n try {\n var u = new URL(url, window.location.origin);\n var changed = false;\n trackingParams.forEach(function(p) {\n if (u.searchParams.has(p)) {\n u.searchParams.delete(p);\n changed = true;\n }\n });\n return changed ? u.toString() : url;\n } catch (e) {\n return url;\n }\n }\n \n function cleanLinks() {\n document.querySelectorAll('a[href]').forEach(function(a) {\n var clean = cleanUrl(a.href);\n if (clean !== a.href) a.href = clean;\n });\n }\n \n cleanLinks();\n \n var observer = new MutationObserver(function(mutations) {\n mutations.forEach(function(m) {\n m.addedNodes.forEach(function(node) {\n if (node.nodeType === 1) {\n if (node.tagName === 'A') cleanLinks();\n node.querySelectorAll('a[href]').forEach(function(a) {\n var clean = cleanUrl(a.href);\n if (clean !== a.href) a.href = clean;\n });\n }\n });\n });\n });\n observer.observe(document.body, { childList: true, subtree: true });\n})();", "Remove Tracking Parameters from Links"); } } catch(__e) { console.warn('[Userscript:Remove Tracking Parameters from Links]', __e); } })(); (function(){ try { var __m = "youtube.com"; var __re = new RegExp('^' + "youtube\\.com" + '
Skip to content

[improvement] add jmh benchmark - #179

Merged
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh
Jun 19, 2019
Merged

[improvement] add jmh benchmark#179
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh

Conversation

@wenhoujx

@wenhoujxwenhoujx commented Jun 18, 2019

Copy link
Copy Markdown
Contributor

add span benchmarks according to @carterkozak 's comments on #176
remove

Before this PR

After this PR

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@wenhoujx
wenhoujx requested a review from a team as a code ownerJune 18, 2019 16:42
@wenhoujxwenhoujx changed the title [improvement] add jmh benchmark[wip][improvement] add jmh benchmarkJun 18, 2019
@wenhoujx

Copy link
Copy Markdown
ContributorAuthor
Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 8.000 ± 1.116 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.007 ± 0.018 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2415.347 ± 343.585 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 6515.868 ± 952.898 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.002 ± 0.004 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 6657.981 ± 1158.048 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1554.165 ± 282.045 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.207 ± 0.415 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.048 ± 0.095 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 62.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.undecidedCallable avgt 5 2064.025 ± 496.632 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 6414.531 ± 1457.700 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1275.209 ± 0.080 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 6466.522 ± 2177.014 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1283.894 ± 176.306 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.250 ± 0.119 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.050 ± 0.018 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 2469.110 ± 552.636 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 5264.609 ± 1174.790 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.013 ± 0.097 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 5355.468 ± 847.513 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1272.001 ± 273.956 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.136 ± 0.215 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.032 ± 0.054 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 45.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 45.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 154163.541 ± 60469.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 7292.102 ± 2372.250 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108564.545 ± 13.229 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 7433.542 ± 2531.196 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110667.398 ± 10206.453 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.230 ± 0.175 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.490 ± 3.741 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 232746.583 ± 61347.557 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 4880.881 ± 1344.496 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108926.232 ± 9.732 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 5037.797 ± 2114.684 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 112203.221 ± 18934.702 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.080 ± 0.108 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 1.809 ± 2.714 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 39.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 45.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 172844.869 ± 47191.122 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 6543.852 ± 1775.645 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 108321.556 ± 11.003 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 6670.054 ± 2739.824 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110249.676 ± 20044.784 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.145 ± 0.086 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.396 ± 0.759 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 56.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 51.000 ms

@wenhoujxwenhoujx changed the title [wip][improvement] add jmh benchmark[improvement] add jmh benchmarkJun 18, 2019
Tracer.fastCompleteSpan();
}
};
blackhole.consume(callable.call());

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need to blackhole the null result from our callable, however we should blackhole the output, which in this case is a series of Span objects:

Tracer.subscribe("jmh", blackhole::consume);

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak thanks for CR, does it matter that every call of Tracer.startSpan("span"); starts a span with the same name?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Spans with the same name are totally fine, we have them in practice via recursive methods ;-)

@wenhoujxwenhoujxJun 18, 2019

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good example. do you want each span subscribed by blackhole::consume? which makes the precomputed Callable<Object> becomes a Function<BlackHole, Object> or even Consumer<BlackHole>

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We just need to set the subscriber at the beginning when we get the blackhole instance. Ideally we could configure that globally instead of for each benchmark method, but I’m not sure how. Note that tracing observer registration is a static per jvm, so concurrent measurements will reset the observer

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak can i use a UUID as the observer name? so that each invocation has different observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, you'll end up writing each span to N observers instead of the case we want to benchmark with a single observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd start with something along these lines:

@Fork(1)
@Threads(1)
@State(Scope.Benchmark)
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 3, time = 3)
publicclassSimpleBenchmark {
@Setuppublicvoidsetup(Blackholeblackhole) {
Tracer.subscribe("jmh", blackhole::consume);
Tracer.setSampler(AlwaysSampler.INSTANCE);
}
@TearDownpublicvoidtearDown() {
Tracer.unsubscribe("jmh");
}
@BenchmarkpublicvoidnestedSpans() {
for (inti = 0; i < 100; i++) {
Tracer.startSpan("span");
}
for (inti = 0; i < 100; i++) {
Tracer.fastCompleteSpan();
}
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The sampler can be parameterized so that we can write one benchmark and get results for both the sampled and unsampled cases using parameterized values in state, see the internal class I linked in a DM.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cool 👍

return NOOP_CALLABLE.call();
} finally {
Tracer.fastCompleteSpan();
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should precompute the callable wrappers.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

the three benchmarks has similar throughput and gc? i must be doing something wrong:

Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 7.038 ± 1.780 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.010 ± 0.024 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2044.400 ± 666.394 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 7716.063 ± 2366.255 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.001 ± 0.003 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 7824.897 ± 1877.372 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1543.332 ± 148.294 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.215 ± 0.295 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.042 ± 0.059 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 48.000 ms
TracingBenchmark.undecidedCallable avgt 5 1866.992 ± 143.168 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 7203.966 ± 614.308 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1276.788 ± 0.104 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 7253.810 ± 743.664 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1285.946 ± 145.356 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.249 ± 0.230 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.044 ± 0.043 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 66.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 1814.516 ± 187.818 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 7299.155 ± 860.457 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.001 ± 0.003 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 7375.237 ± 1013.081 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1261.238 ± 132.557 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.261 ± 0.217 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.045 ± 0.036 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 69.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 132066.752 ± 13804.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 8434.893 ± 861.115 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108771.325 ± 97.708 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8511.749 ± 1666.471 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109709.414 ± 11697.728 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.241 ± 0.212 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.108 ± 2.845 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 69.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 52.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 133724.771 ± 33937.147 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 8392.403 ± 1989.890 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 109025.207 ± 14.804 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8443.440 ± 1705.394 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109793.656 ± 15341.244 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.274 ± 0.169 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.569 ± 2.340 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 49.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 130368.665 ± 20251.780 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 8542.379 ± 1342.633 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108754.963 ± 6.620 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8682.420 ± 564.495 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110647.106 ± 14168.551 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.212 ± 0.182 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.698 ± 2.276 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 73.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 53.000 ms

Comment threadtracing-benchmarks/build.gradle Outdated
dependencies {
annotationProcessor 'org.openjdk.jmh:jmh-generator-annprocess'
compileOnly 'org.openjdk.jmh:jmh-generator-annprocess'
compile "org.immutables:value::annotations"

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about compileOnly + annotationProocessor?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.


> Task :tracing-benchmarks:compileJmhJava FAILED
warning: unknown enum constant ImplementationVisibility.PACKAGE
reason: class file for org.immutables.value.Value$Style$ImplementationVisibility not found
warning: unknown enum constant ImplementationVisibility.PACKAGE
error: warnings found and -Werror specified
1 error
2 warnings

the same

@carterkozak

Copy link
Copy Markdown
Contributor

Will take a look in a while.

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

new benchmark with parameters and Blackhole in @Setup method

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 25 19142.332 ± 446.597 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 25 1494.972 ± 34.335 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space SAMPLE avgt 25 1496.533 ± 34.313 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm SAMPLE avgt 25 31522.248 ± 216.732 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm SAMPLE avgt 25 0.109 ± 0.010 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 25 1161.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 25 857.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 25 20399.207 ± 1887.793 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 25 1420.130 ± 117.529 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space DO_NOT_SAMPLE avgt 25 1420.401 ± 116.523 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm DO_NOT_SAMPLE avgt 25 31500.468 ± 241.627 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen DO_NOT_SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm DO_NOT_SAMPLE avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 25 1051.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 25 867.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 25 19134.032 ± 618.860 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 25 1496.999 ± 48.254 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space UNDECIDED avgt 25 1500.946 ± 47.072 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm UNDECIDED avgt 25 31573.414 ± 185.387 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen UNDECIDED avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm UNDECIDED avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 25 1077.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 25 849.000 ms

@wenhoujx

wenhoujx commented Jun 19, 2019

Copy link
Copy Markdown
ContributorAuthor

new benchmark for commit 7d1d92f


Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@carterkozakcarterkozak left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, thanks!

@bulldozer-bot
bulldozer-botBot merged commit 42aafc8 into palantir:developJun 19, 2019
@schlosnaschlosna mentioned this pull request Jun 19, 2019
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

@wenhoujx@carterkozak@schlosna
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Auto-enable theater mode on YouTube\n(function() {\n function tryTheater() {\n var btn = document.querySelector('button[aria-label=\"Theater mode\"], ytd-player #player button[title=\"Theater mode\"]');\n if (btn && !btn.classList.contains('activated')) {\n btn.click();\n }\n }\n \n // Try immediately\n tryTheater();\n \n // Try after navigation (SPA)\n var lastUrl = location.href;\n setInterval(function() {\n if (location.href !== lastUrl) {\n lastUrl = location.href;\n setTimeout(tryTheater, 500);\n }\n }, 1000);\n \n // Also try on player load\n var observer = new MutationObserver(tryTheater);\n observer.observe(document.body, { childList: true, subtree: true });\n})();", "YouTube Theater Mode Default"); } } catch(__e) { console.warn('[Userscript:YouTube Theater Mode Default]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + '
Skip to content

[improvement] add jmh benchmark - #179

Merged
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh
Jun 19, 2019
Merged

[improvement] add jmh benchmark#179
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh

Conversation

@wenhoujx

@wenhoujxwenhoujx commented Jun 18, 2019

Copy link
Copy Markdown
Contributor

add span benchmarks according to @carterkozak 's comments on #176
remove

Before this PR

After this PR

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@wenhoujx
wenhoujx requested a review from a team as a code ownerJune 18, 2019 16:42
@wenhoujxwenhoujx changed the title [improvement] add jmh benchmark[wip][improvement] add jmh benchmarkJun 18, 2019
@wenhoujx

Copy link
Copy Markdown
ContributorAuthor
Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 8.000 ± 1.116 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.007 ± 0.018 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2415.347 ± 343.585 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 6515.868 ± 952.898 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.002 ± 0.004 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 6657.981 ± 1158.048 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1554.165 ± 282.045 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.207 ± 0.415 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.048 ± 0.095 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 62.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.undecidedCallable avgt 5 2064.025 ± 496.632 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 6414.531 ± 1457.700 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1275.209 ± 0.080 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 6466.522 ± 2177.014 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1283.894 ± 176.306 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.250 ± 0.119 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.050 ± 0.018 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 2469.110 ± 552.636 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 5264.609 ± 1174.790 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.013 ± 0.097 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 5355.468 ± 847.513 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1272.001 ± 273.956 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.136 ± 0.215 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.032 ± 0.054 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 45.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 45.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 154163.541 ± 60469.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 7292.102 ± 2372.250 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108564.545 ± 13.229 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 7433.542 ± 2531.196 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110667.398 ± 10206.453 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.230 ± 0.175 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.490 ± 3.741 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 232746.583 ± 61347.557 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 4880.881 ± 1344.496 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108926.232 ± 9.732 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 5037.797 ± 2114.684 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 112203.221 ± 18934.702 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.080 ± 0.108 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 1.809 ± 2.714 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 39.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 45.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 172844.869 ± 47191.122 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 6543.852 ± 1775.645 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 108321.556 ± 11.003 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 6670.054 ± 2739.824 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110249.676 ± 20044.784 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.145 ± 0.086 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.396 ± 0.759 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 56.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 51.000 ms

@wenhoujxwenhoujx changed the title [wip][improvement] add jmh benchmark[improvement] add jmh benchmarkJun 18, 2019
Tracer.fastCompleteSpan();
}
};
blackhole.consume(callable.call());

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need to blackhole the null result from our callable, however we should blackhole the output, which in this case is a series of Span objects:

Tracer.subscribe("jmh", blackhole::consume);

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak thanks for CR, does it matter that every call of Tracer.startSpan("span"); starts a span with the same name?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Spans with the same name are totally fine, we have them in practice via recursive methods ;-)

@wenhoujxwenhoujxJun 18, 2019

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good example. do you want each span subscribed by blackhole::consume? which makes the precomputed Callable<Object> becomes a Function<BlackHole, Object> or even Consumer<BlackHole>

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We just need to set the subscriber at the beginning when we get the blackhole instance. Ideally we could configure that globally instead of for each benchmark method, but I’m not sure how. Note that tracing observer registration is a static per jvm, so concurrent measurements will reset the observer

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak can i use a UUID as the observer name? so that each invocation has different observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, you'll end up writing each span to N observers instead of the case we want to benchmark with a single observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd start with something along these lines:

@Fork(1)
@Threads(1)
@State(Scope.Benchmark)
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 3, time = 3)
publicclassSimpleBenchmark {
@Setuppublicvoidsetup(Blackholeblackhole) {
Tracer.subscribe("jmh", blackhole::consume);
Tracer.setSampler(AlwaysSampler.INSTANCE);
}
@TearDownpublicvoidtearDown() {
Tracer.unsubscribe("jmh");
}
@BenchmarkpublicvoidnestedSpans() {
for (inti = 0; i < 100; i++) {
Tracer.startSpan("span");
}
for (inti = 0; i < 100; i++) {
Tracer.fastCompleteSpan();
}
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The sampler can be parameterized so that we can write one benchmark and get results for both the sampled and unsampled cases using parameterized values in state, see the internal class I linked in a DM.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cool 👍

return NOOP_CALLABLE.call();
} finally {
Tracer.fastCompleteSpan();
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should precompute the callable wrappers.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

the three benchmarks has similar throughput and gc? i must be doing something wrong:

Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 7.038 ± 1.780 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.010 ± 0.024 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2044.400 ± 666.394 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 7716.063 ± 2366.255 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.001 ± 0.003 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 7824.897 ± 1877.372 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1543.332 ± 148.294 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.215 ± 0.295 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.042 ± 0.059 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 48.000 ms
TracingBenchmark.undecidedCallable avgt 5 1866.992 ± 143.168 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 7203.966 ± 614.308 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1276.788 ± 0.104 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 7253.810 ± 743.664 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1285.946 ± 145.356 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.249 ± 0.230 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.044 ± 0.043 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 66.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 1814.516 ± 187.818 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 7299.155 ± 860.457 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.001 ± 0.003 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 7375.237 ± 1013.081 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1261.238 ± 132.557 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.261 ± 0.217 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.045 ± 0.036 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 69.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 132066.752 ± 13804.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 8434.893 ± 861.115 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108771.325 ± 97.708 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8511.749 ± 1666.471 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109709.414 ± 11697.728 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.241 ± 0.212 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.108 ± 2.845 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 69.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 52.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 133724.771 ± 33937.147 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 8392.403 ± 1989.890 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 109025.207 ± 14.804 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8443.440 ± 1705.394 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109793.656 ± 15341.244 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.274 ± 0.169 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.569 ± 2.340 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 49.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 130368.665 ± 20251.780 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 8542.379 ± 1342.633 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108754.963 ± 6.620 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8682.420 ± 564.495 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110647.106 ± 14168.551 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.212 ± 0.182 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.698 ± 2.276 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 73.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 53.000 ms

Comment threadtracing-benchmarks/build.gradle Outdated
dependencies {
annotationProcessor 'org.openjdk.jmh:jmh-generator-annprocess'
compileOnly 'org.openjdk.jmh:jmh-generator-annprocess'
compile "org.immutables:value::annotations"

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about compileOnly + annotationProocessor?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.


> Task :tracing-benchmarks:compileJmhJava FAILED
warning: unknown enum constant ImplementationVisibility.PACKAGE
reason: class file for org.immutables.value.Value$Style$ImplementationVisibility not found
warning: unknown enum constant ImplementationVisibility.PACKAGE
error: warnings found and -Werror specified
1 error
2 warnings

the same

@carterkozak

Copy link
Copy Markdown
Contributor

Will take a look in a while.

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

new benchmark with parameters and Blackhole in @Setup method

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 25 19142.332 ± 446.597 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 25 1494.972 ± 34.335 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space SAMPLE avgt 25 1496.533 ± 34.313 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm SAMPLE avgt 25 31522.248 ± 216.732 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm SAMPLE avgt 25 0.109 ± 0.010 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 25 1161.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 25 857.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 25 20399.207 ± 1887.793 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 25 1420.130 ± 117.529 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space DO_NOT_SAMPLE avgt 25 1420.401 ± 116.523 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm DO_NOT_SAMPLE avgt 25 31500.468 ± 241.627 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen DO_NOT_SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm DO_NOT_SAMPLE avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 25 1051.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 25 867.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 25 19134.032 ± 618.860 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 25 1496.999 ± 48.254 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space UNDECIDED avgt 25 1500.946 ± 47.072 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm UNDECIDED avgt 25 31573.414 ± 185.387 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen UNDECIDED avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm UNDECIDED avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 25 1077.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 25 849.000 ms

@wenhoujx

wenhoujx commented Jun 19, 2019

Copy link
Copy Markdown
ContributorAuthor

new benchmark for commit 7d1d92f


Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@carterkozakcarterkozak left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, thanks!

@bulldozer-bot
bulldozer-botBot merged commit 42aafc8 into palantir:developJun 19, 2019
@schlosnaschlosna mentioned this pull request Jun 19, 2019
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

@wenhoujx@carterkozak@schlosna
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Remove or un-stick sticky/fixed headers that block content\n(function() {\n function unstick() {\n document.querySelectorAll('header, nav, [role=\"banner\"], .header, .navbar, .sticky, .fixed-top, [style*=\"position: fixed\"], [style*=\"position:sticky\"]').forEach(function(el) {\n if (el.style.position === 'fixed' || el.style.position === 'sticky' || \n getComputedStyle(el).position === 'fixed' || getComputedStyle(el).position === 'sticky') {\n el.style.position = 'static';\n el.style.top = 'auto';\n el.style.zIndex = 'auto';\n }\n });\n }\n \n unstick();\n \n var observer = new MutationObserver(unstick);\n observer.observe(document.body, { childList: true, subtree: true, attributes: true, attributeFilter: ['style', 'class'] });\n})();", "Kill Sticky Headers"); } } catch(__e) { console.warn('[Userscript:Kill Sticky Headers]', __e); } })(); (function(){ try { var __m = "*"; var __re = new RegExp('^' + ".*" + '
Skip to content

[improvement] add jmh benchmark - #179

Merged
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh
Jun 19, 2019
Merged

[improvement] add jmh benchmark#179
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh

Conversation

@wenhoujx

@wenhoujxwenhoujx commented Jun 18, 2019

Copy link
Copy Markdown
Contributor

add span benchmarks according to @carterkozak 's comments on #176
remove

Before this PR

After this PR

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@wenhoujx
wenhoujx requested a review from a team as a code ownerJune 18, 2019 16:42
@wenhoujxwenhoujx changed the title [improvement] add jmh benchmark[wip][improvement] add jmh benchmarkJun 18, 2019
@wenhoujx

Copy link
Copy Markdown
ContributorAuthor
Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 8.000 ± 1.116 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.007 ± 0.018 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2415.347 ± 343.585 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 6515.868 ± 952.898 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.002 ± 0.004 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 6657.981 ± 1158.048 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1554.165 ± 282.045 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.207 ± 0.415 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.048 ± 0.095 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 62.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.undecidedCallable avgt 5 2064.025 ± 496.632 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 6414.531 ± 1457.700 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1275.209 ± 0.080 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 6466.522 ± 2177.014 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1283.894 ± 176.306 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.250 ± 0.119 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.050 ± 0.018 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 2469.110 ± 552.636 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 5264.609 ± 1174.790 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.013 ± 0.097 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 5355.468 ± 847.513 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1272.001 ± 273.956 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.136 ± 0.215 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.032 ± 0.054 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 45.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 45.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 154163.541 ± 60469.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 7292.102 ± 2372.250 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108564.545 ± 13.229 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 7433.542 ± 2531.196 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110667.398 ± 10206.453 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.230 ± 0.175 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.490 ± 3.741 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 232746.583 ± 61347.557 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 4880.881 ± 1344.496 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108926.232 ± 9.732 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 5037.797 ± 2114.684 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 112203.221 ± 18934.702 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.080 ± 0.108 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 1.809 ± 2.714 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 39.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 45.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 172844.869 ± 47191.122 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 6543.852 ± 1775.645 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 108321.556 ± 11.003 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 6670.054 ± 2739.824 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110249.676 ± 20044.784 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.145 ± 0.086 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.396 ± 0.759 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 56.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 51.000 ms

@wenhoujxwenhoujx changed the title [wip][improvement] add jmh benchmark[improvement] add jmh benchmarkJun 18, 2019
Tracer.fastCompleteSpan();
}
};
blackhole.consume(callable.call());

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need to blackhole the null result from our callable, however we should blackhole the output, which in this case is a series of Span objects:

Tracer.subscribe("jmh", blackhole::consume);

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak thanks for CR, does it matter that every call of Tracer.startSpan("span"); starts a span with the same name?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Spans with the same name are totally fine, we have them in practice via recursive methods ;-)

@wenhoujxwenhoujxJun 18, 2019

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good example. do you want each span subscribed by blackhole::consume? which makes the precomputed Callable<Object> becomes a Function<BlackHole, Object> or even Consumer<BlackHole>

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We just need to set the subscriber at the beginning when we get the blackhole instance. Ideally we could configure that globally instead of for each benchmark method, but I’m not sure how. Note that tracing observer registration is a static per jvm, so concurrent measurements will reset the observer

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak can i use a UUID as the observer name? so that each invocation has different observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, you'll end up writing each span to N observers instead of the case we want to benchmark with a single observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd start with something along these lines:

@Fork(1)
@Threads(1)
@State(Scope.Benchmark)
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 3, time = 3)
publicclassSimpleBenchmark {
@Setuppublicvoidsetup(Blackholeblackhole) {
Tracer.subscribe("jmh", blackhole::consume);
Tracer.setSampler(AlwaysSampler.INSTANCE);
}
@TearDownpublicvoidtearDown() {
Tracer.unsubscribe("jmh");
}
@BenchmarkpublicvoidnestedSpans() {
for (inti = 0; i < 100; i++) {
Tracer.startSpan("span");
}
for (inti = 0; i < 100; i++) {
Tracer.fastCompleteSpan();
}
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The sampler can be parameterized so that we can write one benchmark and get results for both the sampled and unsampled cases using parameterized values in state, see the internal class I linked in a DM.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cool 👍

return NOOP_CALLABLE.call();
} finally {
Tracer.fastCompleteSpan();
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should precompute the callable wrappers.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

the three benchmarks has similar throughput and gc? i must be doing something wrong:

Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 7.038 ± 1.780 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.010 ± 0.024 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2044.400 ± 666.394 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 7716.063 ± 2366.255 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.001 ± 0.003 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 7824.897 ± 1877.372 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1543.332 ± 148.294 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.215 ± 0.295 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.042 ± 0.059 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 48.000 ms
TracingBenchmark.undecidedCallable avgt 5 1866.992 ± 143.168 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 7203.966 ± 614.308 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1276.788 ± 0.104 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 7253.810 ± 743.664 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1285.946 ± 145.356 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.249 ± 0.230 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.044 ± 0.043 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 66.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 1814.516 ± 187.818 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 7299.155 ± 860.457 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.001 ± 0.003 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 7375.237 ± 1013.081 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1261.238 ± 132.557 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.261 ± 0.217 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.045 ± 0.036 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 69.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 132066.752 ± 13804.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 8434.893 ± 861.115 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108771.325 ± 97.708 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8511.749 ± 1666.471 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109709.414 ± 11697.728 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.241 ± 0.212 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.108 ± 2.845 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 69.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 52.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 133724.771 ± 33937.147 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 8392.403 ± 1989.890 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 109025.207 ± 14.804 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8443.440 ± 1705.394 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109793.656 ± 15341.244 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.274 ± 0.169 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.569 ± 2.340 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 49.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 130368.665 ± 20251.780 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 8542.379 ± 1342.633 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108754.963 ± 6.620 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8682.420 ± 564.495 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110647.106 ± 14168.551 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.212 ± 0.182 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.698 ± 2.276 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 73.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 53.000 ms

Comment threadtracing-benchmarks/build.gradle Outdated
dependencies {
annotationProcessor 'org.openjdk.jmh:jmh-generator-annprocess'
compileOnly 'org.openjdk.jmh:jmh-generator-annprocess'
compile "org.immutables:value::annotations"

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about compileOnly + annotationProocessor?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.


> Task :tracing-benchmarks:compileJmhJava FAILED
warning: unknown enum constant ImplementationVisibility.PACKAGE
reason: class file for org.immutables.value.Value$Style$ImplementationVisibility not found
warning: unknown enum constant ImplementationVisibility.PACKAGE
error: warnings found and -Werror specified
1 error
2 warnings

the same

@carterkozak

Copy link
Copy Markdown
Contributor

Will take a look in a while.

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

new benchmark with parameters and Blackhole in @Setup method

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 25 19142.332 ± 446.597 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 25 1494.972 ± 34.335 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space SAMPLE avgt 25 1496.533 ± 34.313 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm SAMPLE avgt 25 31522.248 ± 216.732 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm SAMPLE avgt 25 0.109 ± 0.010 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 25 1161.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 25 857.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 25 20399.207 ± 1887.793 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 25 1420.130 ± 117.529 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space DO_NOT_SAMPLE avgt 25 1420.401 ± 116.523 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm DO_NOT_SAMPLE avgt 25 31500.468 ± 241.627 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen DO_NOT_SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm DO_NOT_SAMPLE avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 25 1051.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 25 867.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 25 19134.032 ± 618.860 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 25 1496.999 ± 48.254 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space UNDECIDED avgt 25 1500.946 ± 47.072 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm UNDECIDED avgt 25 31573.414 ± 185.387 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen UNDECIDED avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm UNDECIDED avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 25 1077.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 25 849.000 ms

@wenhoujx

wenhoujx commented Jun 19, 2019

Copy link
Copy Markdown
ContributorAuthor

new benchmark for commit 7d1d92f


Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@carterkozakcarterkozak left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, thanks!

@bulldozer-bot
bulldozer-botBot merged commit 42aafc8 into palantir:developJun 19, 2019
@schlosnaschlosna mentioned this pull request Jun 19, 2019
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

@wenhoujx@carterkozak@schlosna
, 'i'); if (__m === '*' || __re.test(location.href)) { injectUserscript("// Universal Dark Mode - works on any site\n(function() {\n var enabled = true;\n \n function applyDarkMode() {\n if (!enabled) return;\n \n // Create style element if it doesn't exist\n var style = document.getElementById('universal-dark-mode-style');\n if (!style) {\n style = document.createElement('style');\n style.id = 'universal-dark-mode-style';\n document.head.appendChild(style);\n }\n \n // Dark mode CSS - inverts colors but preserves images/video\n style.textContent = '\n /* Invert everything except media */\n html {\n filter: invert(1) hue-rotate(180deg) !important;\n background: #1a1a2e !important;\n }\n \n /* Restore images, videos, iframes, canvas */\n img, video, iframe, canvas, svg, picture, [style*=\"background-image\"] {\n filter: invert(1) hue-rotate(180deg) !important;\n }\n \n /* Preserve specific elements that should not be inverted */\n .no-dark-mode, .no-dark-mode *,\n [data-theme=\"light\"], [data-theme=\"light\"],\n .ace_editor, .ace_editor *,\n .CodeMirror, .CodeMirror *,\n .monaco-editor, .monaco-editor *,\n .markdown-body pre, .markdown-body pre *,\n .highlight, .highlight *,\n pre code, pre code * {\n filter: none !important;\n }\n \n /* Fix common UI elements */\n .modal, .popup, .dropdown-menu, .tooltip, .popover {\n filter: invert(1) hue-rotate(180deg) !important;\n background: #2d2d44 !important;\n border-color: #444 !important;\n }\n \n /* Scrollbars */\n ::-webkit-scrollbar { background: #1a1a2e !important; }\n ::-webkit-scrollbar-thumb { background: #444 !important; }\n ::-webkit-scrollbar-thumb:hover { background: #555 !important; }\n \n /* Selection */\n ::selection { background: #4ecdc4 !important; color: #1a1a2e !important; }\n ::-moz-selection { background: #4ecdc4 !important; color: #1a1a2e !important; }\n ';\n }\n \n function removeDarkMode() {\n var style = document.getElementById('universal-dark-mode-style');\n if (style) style.remove();\n }\n \n // Toggle with Alt+Shift+D\n document.addEventListener('keydown', function(e) {\n if (e.altKey && e.shiftKey && e.key === 'D') {\n e.preventDefault();\n enabled = !enabled;\n if (enabled) {\n applyDarkMode();\n console.log('[Universal Dark Mode] Enabled');\n } else {\n removeDarkMode();\n console.log('[Universal Dark Mode] Disabled');\n }\n }\n });\n \n // Apply on load\n applyDarkMode();\n \n // Re-apply on dynamic content\n var observer = new MutationObserver(function(mutations) {\n if (enabled && !document.getElementById('universal-dark-mode-style')) {\n applyDarkMode();\n }\n });\n observer.observe(document.head, { childList: true });\n \n console.log('[Universal Dark Mode] Loaded - Press Alt+Shift+D to toggle');\n})();", "Universal Dark Mode"); } } catch(__e) { console.warn('[Userscript:Universal Dark Mode]', __e); } })(); })();
Skip to content

[improvement] add jmh benchmark - #179

Merged
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh
Jun 19, 2019
Merged

[improvement] add jmh benchmark#179
bulldozer-bot[bot] merged 10 commits into
palantir:developfrom
wenhoujx:ds/jmh

Conversation

@wenhoujx

@wenhoujxwenhoujx commented Jun 18, 2019

Copy link
Copy Markdown
Contributor

add span benchmarks according to @carterkozak 's comments on #176
remove

Before this PR

After this PR

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@wenhoujx
wenhoujx requested a review from a team as a code ownerJune 18, 2019 16:42
@wenhoujxwenhoujx changed the title [improvement] add jmh benchmark[wip][improvement] add jmh benchmarkJun 18, 2019
@wenhoujx

Copy link
Copy Markdown
ContributorAuthor
Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 8.000 ± 1.116 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.007 ± 0.018 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2415.347 ± 343.585 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 6515.868 ± 952.898 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.002 ± 0.004 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 6657.981 ± 1158.048 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1554.165 ± 282.045 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.207 ± 0.415 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.048 ± 0.095 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 62.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.undecidedCallable avgt 5 2064.025 ± 496.632 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 6414.531 ± 1457.700 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1275.209 ± 0.080 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 6466.522 ± 2177.014 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1283.894 ± 176.306 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.250 ± 0.119 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.050 ± 0.018 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 2469.110 ± 552.636 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 5264.609 ± 1174.790 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.013 ± 0.097 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 5355.468 ± 847.513 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1272.001 ± 273.956 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.136 ± 0.215 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.032 ± 0.054 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 45.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 45.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 154163.541 ± 60469.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 7292.102 ± 2372.250 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108564.545 ± 13.229 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 7433.542 ± 2531.196 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110667.398 ± 10206.453 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.230 ± 0.175 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.490 ± 3.741 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 232746.583 ± 61347.557 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 4880.881 ± 1344.496 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108926.232 ± 9.732 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 5037.797 ± 2114.684 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 112203.221 ± 18934.702 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.080 ± 0.108 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 1.809 ± 2.714 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 39.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 45.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 172844.869 ± 47191.122 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 6543.852 ± 1775.645 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 108321.556 ± 11.003 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 6670.054 ± 2739.824 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110249.676 ± 20044.784 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.145 ± 0.086 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.396 ± 0.759 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 56.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 51.000 ms

@wenhoujxwenhoujx changed the title [wip][improvement] add jmh benchmark[improvement] add jmh benchmarkJun 18, 2019
Tracer.fastCompleteSpan();
}
};
blackhole.consume(callable.call());

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We don't need to blackhole the null result from our callable, however we should blackhole the output, which in this case is a series of Span objects:

Tracer.subscribe("jmh", blackhole::consume);

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak thanks for CR, does it matter that every call of Tracer.startSpan("span"); starts a span with the same name?

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Spans with the same name are totally fine, we have them in practice via recursive methods ;-)

@wenhoujxwenhoujxJun 18, 2019

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good example. do you want each span subscribed by blackhole::consume? which makes the precomputed Callable<Object> becomes a Function<BlackHole, Object> or even Consumer<BlackHole>

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We just need to set the subscriber at the beginning when we get the blackhole instance. Ideally we could configure that globally instead of for each benchmark method, but I’m not sure how. Note that tracing observer registration is a static per jvm, so concurrent measurements will reset the observer

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carterkozak can i use a UUID as the observer name? so that each invocation has different observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, you'll end up writing each span to N observers instead of the case we want to benchmark with a single observer.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd start with something along these lines:

@Fork(1)
@Threads(1)
@State(Scope.Benchmark)
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 3, time = 3)
publicclassSimpleBenchmark {
@Setuppublicvoidsetup(Blackholeblackhole) {
Tracer.subscribe("jmh", blackhole::consume);
Tracer.setSampler(AlwaysSampler.INSTANCE);
}
@TearDownpublicvoidtearDown() {
Tracer.unsubscribe("jmh");
}
@BenchmarkpublicvoidnestedSpans() {
for (inti = 0; i < 100; i++) {
Tracer.startSpan("span");
}
for (inti = 0; i < 100; i++) {
Tracer.fastCompleteSpan();
}
}
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The sampler can be parameterized so that we can write one benchmark and get results for both the sampled and unsampled cases using parameterized values in state, see the internal class I linked in a DM.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cool 👍

return NOOP_CALLABLE.call();
} finally {
Tracer.fastCompleteSpan();
}

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should precompute the callable wrappers.

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

the three benchmarks has similar throughput and gc? i must be doing something wrong:

Benchmark Mode Cnt Score Error Units
TracingBenchmark.raw avgt 5 7.038 ± 1.780 ns/op
TracingBenchmark.raw:·gc.alloc.rate avgt 5 0.010 ± 0.024 MB/sec
TracingBenchmark.raw:·gc.alloc.rate.norm avgt 5 ≈ 10⁻⁵ B/op
TracingBenchmark.raw:·gc.count avgt 5 ≈ 0 counts
TracingBenchmark.sampledCallable avgt 5 2044.400 ± 666.394 ns/op
TracingBenchmark.sampledCallable:·gc.alloc.rate avgt 5 7716.063 ± 2366.255 MB/sec
TracingBenchmark.sampledCallable:·gc.alloc.rate.norm avgt 5 1520.001 ± 0.003 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space avgt 5 7824.897 ± 1877.372 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1543.332 ± 148.294 B/op
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.215 ± 0.295 MB/sec
TracingBenchmark.sampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.042 ± 0.059 B/op
TracingBenchmark.sampledCallable:·gc.count avgt 5 63.000 counts
TracingBenchmark.sampledCallable:·gc.time avgt 5 48.000 ms
TracingBenchmark.undecidedCallable avgt 5 1866.992 ± 143.168 ns/op
TracingBenchmark.undecidedCallable:·gc.alloc.rate avgt 5 7203.966 ± 614.308 MB/sec
TracingBenchmark.undecidedCallable:·gc.alloc.rate.norm avgt 5 1276.788 ± 0.104 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space avgt 5 7253.810 ± 743.664 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1285.946 ± 145.356 B/op
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space avgt 5 0.249 ± 0.230 MB/sec
TracingBenchmark.undecidedCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.044 ± 0.043 B/op
TracingBenchmark.undecidedCallable:·gc.count avgt 5 66.000 counts
TracingBenchmark.undecidedCallable:·gc.time avgt 5 50.000 ms
TracingBenchmark.unsampledCallable avgt 5 1814.516 ± 187.818 ns/op
TracingBenchmark.unsampledCallable:·gc.alloc.rate avgt 5 7299.155 ± 860.457 MB/sec
TracingBenchmark.unsampledCallable:·gc.alloc.rate.norm avgt 5 1248.001 ± 0.003 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space avgt 5 7375.237 ± 1013.081 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Eden_Space.norm avgt 5 1261.238 ± 132.557 B/op
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space avgt 5 0.261 ± 0.217 MB/sec
TracingBenchmark.unsampledCallable:·gc.churn.PS_Survivor_Space.norm avgt 5 0.045 ± 0.036 B/op
TracingBenchmark.unsampledCallable:·gc.count avgt 5 69.000 counts
TracingBenchmark.unsampledCallable:·gc.time avgt 5 49.000 ms
TracingBenchmark.sampledTracerSpan avgt 5 132066.752 ± 13804.233 ns/op
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate avgt 5 8434.893 ± 861.115 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.alloc.rate.norm avgt 5 108771.325 ± 97.708 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8511.749 ± 1666.471 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109709.414 ± 11697.728 B/op
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.241 ± 0.212 MB/sec
TracingBenchmark.sampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.108 ± 2.845 B/op
TracingBenchmark.sampledTracerSpan:·gc.count avgt 5 69.000 counts
TracingBenchmark.sampledTracerSpan:·gc.time avgt 5 52.000 ms
TracingBenchmark.undecidedTracerSpan avgt 5 133724.771 ± 33937.147 ns/op
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate avgt 5 8392.403 ± 1989.890 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.alloc.rate.norm avgt 5 109025.207 ± 14.804 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8443.440 ± 1705.394 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 109793.656 ± 15341.244 B/op
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.274 ± 0.169 MB/sec
TracingBenchmark.undecidedTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 3.569 ± 2.340 B/op
TracingBenchmark.undecidedTracerSpan:·gc.count avgt 5 64.000 counts
TracingBenchmark.undecidedTracerSpan:·gc.time avgt 5 49.000 ms
TracingBenchmark.unsampledTracerSpan avgt 5 130368.665 ± 20251.780 ns/op
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate avgt 5 8542.379 ± 1342.633 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.alloc.rate.norm avgt 5 108754.963 ± 6.620 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space avgt 5 8682.420 ± 564.495 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Eden_Space.norm avgt 5 110647.106 ± 14168.551 B/op
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space avgt 5 0.212 ± 0.182 MB/sec
TracingBenchmark.unsampledTracerSpan:·gc.churn.PS_Survivor_Space.norm avgt 5 2.698 ± 2.276 B/op
TracingBenchmark.unsampledTracerSpan:·gc.count avgt 5 73.000 counts
TracingBenchmark.unsampledTracerSpan:·gc.time avgt 5 53.000 ms

Comment threadtracing-benchmarks/build.gradle Outdated
dependencies {
annotationProcessor 'org.openjdk.jmh:jmh-generator-annprocess'
compileOnly 'org.openjdk.jmh:jmh-generator-annprocess'
compile "org.immutables:value::annotations"

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What about compileOnly + annotationProocessor?

Copy link
Copy Markdown
ContributorAuthor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.


> Task :tracing-benchmarks:compileJmhJava FAILED
warning: unknown enum constant ImplementationVisibility.PACKAGE
reason: class file for org.immutables.value.Value$Style$ImplementationVisibility not found
warning: unknown enum constant ImplementationVisibility.PACKAGE
error: warnings found and -Werror specified
1 error
2 warnings

the same

@carterkozak

Copy link
Copy Markdown
Contributor

Will take a look in a while.

@wenhoujx

Copy link
Copy Markdown
ContributorAuthor

new benchmark with parameters and Blackhole in @Setup method

Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 25 19142.332 ± 446.597 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 25 1494.972 ± 34.335 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space SAMPLE avgt 25 1496.533 ± 34.313 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm SAMPLE avgt 25 31522.248 ± 216.732 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm SAMPLE avgt 25 0.109 ± 0.010 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 25 1161.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 25 857.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 25 20399.207 ± 1887.793 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 25 1420.130 ± 117.529 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space DO_NOT_SAMPLE avgt 25 1420.401 ± 116.523 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm DO_NOT_SAMPLE avgt 25 31500.468 ± 241.627 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen DO_NOT_SAMPLE avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm DO_NOT_SAMPLE avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 25 1051.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 25 867.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 25 19134.032 ± 618.860 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 25 1496.999 ± 48.254 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 25 31488.001 ± 0.001 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space UNDECIDED avgt 25 1500.946 ± 47.072 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Eden_Space.norm UNDECIDED avgt 25 31573.414 ± 185.387 B/op
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen UNDECIDED avgt 25 0.005 ± 0.001 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.G1_Old_Gen.norm UNDECIDED avgt 25 0.108 ± 0.014 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 25 1077.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 25 849.000 ms

@wenhoujx

wenhoujx commented Jun 19, 2019

Copy link
Copy Markdown
ContributorAuthor

new benchmark for commit 7d1d92f


Benchmark (observability) Mode Cnt Score Error Units
TracingBenchmark.nestedSpans SAMPLE avgt 3 51266.154 ± 19461.304 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate SAMPLE avgt 3 2598.879 ± 978.792 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm SAMPLE avgt 3 40760.031 ± 1.141 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space SAMPLE avgt 3 2707.659 ± 1382.288 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm SAMPLE avgt 3 42470.187 ± 19619.815 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space SAMPLE avgt 3 0.056 ± 0.469 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm SAMPLE avgt 3 0.890 ± 7.573 B/op
TracingBenchmark.nestedSpans:·gc.count SAMPLE avgt 3 22.000 counts
TracingBenchmark.nestedSpans:·gc.time SAMPLE avgt 3 28.000 ms
TracingBenchmark.nestedSpans DO_NOT_SAMPLE avgt 3 26749.119 ± 17733.671 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate DO_NOT_SAMPLE avgt 3 2618.135 ± 1713.586 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm DO_NOT_SAMPLE avgt 3 21416.022 ± 0.539 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space DO_NOT_SAMPLE avgt 3 2664.780 ± 3436.299 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm DO_NOT_SAMPLE avgt 3 21780.010 ± 14872.970 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space DO_NOT_SAMPLE avgt 3 0.128 ± 1.580 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm DO_NOT_SAMPLE avgt 3 1.062 ± 13.821 B/op
TracingBenchmark.nestedSpans:·gc.count DO_NOT_SAMPLE avgt 3 65.000 counts
TracingBenchmark.nestedSpans:·gc.time DO_NOT_SAMPLE avgt 3 78.000 ms
TracingBenchmark.nestedSpans UNDECIDED avgt 3 30374.624 ± 7959.930 ns/op
TracingBenchmark.nestedSpans:·gc.alloc.rate UNDECIDED avgt 3 2442.989 ± 677.177 MB/sec
TracingBenchmark.nestedSpans:·gc.alloc.rate.norm UNDECIDED avgt 3 22713.026 ± 15.117 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space UNDECIDED avgt 3 2415.657 ± 1132.967 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Eden_Space.norm UNDECIDED avgt 3 22458.167 ± 7539.764 B/op
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space UNDECIDED avgt 3 0.160 ± 1.415 MB/sec
TracingBenchmark.nestedSpans:·gc.churn.PS_Survivor_Space.norm UNDECIDED avgt 3 1.498 ± 13.569 B/op
TracingBenchmark.nestedSpans:·gc.count UNDECIDED avgt 3 62.000 counts
TracingBenchmark.nestedSpans:·gc.time UNDECIDED avgt 3 69.000 ms

@carterkozakcarterkozak left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm, thanks!

@bulldozer-bot
bulldozer-botBot merged commit 42aafc8 into palantir:developJun 19, 2019
@schlosnaschlosna mentioned this pull request Jun 19, 2019
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants

@wenhoujx@carterkozak@schlosna