You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@aurora.apache.org by Stephan Erb <se...@apache.org> on 2017/05/07 17:49:19 UTC
Re: Review Request 55071: Disable H2 logging via SLF4J.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/55071/#review174130
-----------------------------------------------------------
David, would you mind giving this a try in your performance test cluster? I believe it should help with gc pressure as it will reduce the (logging/tracing) garbage produced by h2. If it turns out to be true we can think about how to adopt the change properly .
- Stephan Erb
On Mai 7, 2017, 7:46 nachm., Stephan Erb wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/55071/
> -----------------------------------------------------------
>
> (Updated Mai 7, 2017, 7:46 nachm.)
>
>
> Review request for Aurora, David McLaughlin, Mehrdad Nurolahzade, and Zameer Manji.
>
>
> Repository: aurora
>
>
> Description
> -------
>
> Sending H2 log messages to SLF4J is expensive as the messages will be assembled in memory, only to be discarded by logback afterwards. With this change H2 errors will be printed to stdout instead. In this case H2 is clever enough to only assemble debug messages when necessary.
>
> I have never seen H2 error messages in the wild, so I believe the change is safe. If one of you is using H2 logging regularly, we could consider exposing the trace level as a commandline flag.
>
> On the performance side, we gain about a factor 2-3 in our micro benchmarks (excluding the TaskStoreBenchmarks which are skewed by caching).
>
> Before the change:
> ```
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 10000 thrpt 5 61431.706 ± 13049.185 ops/s
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 50000 thrpt 5 30442.256 ± 19143.475 ops/s
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 100000 thrpt 5 0.087 ± 0.022 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 1000 N/A N/A thrpt 5 151.684 ± 77.845 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 5000 N/A N/A thrpt 5 39.098 ± 3.030 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 10000 N/A N/A thrpt 5 20.233 ± 2.385 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 1 N/A N/A N/A thrpt 5 39.556 ± 13.071 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 10 N/A N/A N/A thrpt 5 39.307 ± 9.991 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 100 N/A N/A N/A thrpt 5 24.029 ± 5.149 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 1000 N/A N/A N/A thrpt 5 17.671 ± 6.065 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 10 N/A thrpt 5 37.791 ± 13.941 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 100 N/A thrpt 5 37.189 ± 26.962 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 1000 N/A thrpt 5 26.881 ± 15.143 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 10000 N/A thrpt 5 13.874 ± 4.928 ops/s
> ```
>
> With this change:
> ```
> Benchmark (instanceOverrides) (instances) (metadata) (numTasks) Mode Cnt Score Error Units
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 10000 thrpt 5 64510.645 ± 11207.229 ops/s
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 50000 thrpt 5 53270.516 ± 21560.208 ops/s
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 100000 thrpt 5 40471.488 ± 36196.208 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 1000 N/A N/A thrpt 5 471.175 ± 436.428 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 5000 N/A N/A thrpt 5 120.241 ± 113.142 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 10000 N/A N/A thrpt 5 67.512 ± 28.800 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 1 N/A N/A N/A thrpt 5 129.110 ± 50.366 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 10 N/A N/A N/A thrpt 5 137.847 ± 18.581 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 100 N/A N/A N/A thrpt 5 90.551 ± 61.773 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 1000 N/A N/A N/A thrpt 5 52.958 ± 3.552 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 10 N/A thrpt 5 127.873 ± 83.669 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 100 N/A thrpt 5 119.673 ± 66.301 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 1000 N/A thrpt 5 76.271 ± 42.117 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 10000 N/A thrpt 5 41.306 ± 10.706 ops/s
> ```
>
>
> Diffs
> -----
>
> src/main/java/org/apache/aurora/scheduler/storage/db/DbModule.java d1a196419b67108ee2bb778f83a2993e2e5ee83b
> src/main/resources/logback.xml f4a8fa1d5184e6e246ae0742193d66cad7e0d58d
>
>
> Diff: https://reviews.apache.org/r/55071/diff/1/
>
>
> Testing
> -------
>
> ./gradlew jmh -Pbenchmarks='TaskStoreBenchmarks.DBFetchTasksBenchmark|UpdateStoreBenchmarks.*'
> ./gradlew -Pq build
>
>
> Thanks,
>
> Stephan Erb
>
>
Re: Review Request 55071: Disable H2 logging via SLF4J.
Posted by David McLaughlin <da...@dmclaughlin.com>.
> On May 7, 2017, 5:49 p.m., Stephan Erb wrote:
> > David, would you mind giving this a try in your performance test cluster? I believe it should help with gc pressure as it will reduce the (logging/tracing) garbage produced by h2. If it turns out to be true we can think about how to adopt the change properly .
Sure. Running ReviewBot to make sure it merges cleanly still.
- David
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/55071/#review174130
-----------------------------------------------------------
On May 7, 2017, 5:46 p.m., Stephan Erb wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/55071/
> -----------------------------------------------------------
>
> (Updated May 7, 2017, 5:46 p.m.)
>
>
> Review request for Aurora, David McLaughlin, Mehrdad Nurolahzade, and Zameer Manji.
>
>
> Repository: aurora
>
>
> Description
> -------
>
> Sending H2 log messages to SLF4J is expensive as the messages will be assembled in memory, only to be discarded by logback afterwards. With this change H2 errors will be printed to stdout instead. In this case H2 is clever enough to only assemble debug messages when necessary.
>
> I have never seen H2 error messages in the wild, so I believe the change is safe. If one of you is using H2 logging regularly, we could consider exposing the trace level as a commandline flag.
>
> On the performance side, we gain about a factor 2-3 in our micro benchmarks (excluding the TaskStoreBenchmarks which are skewed by caching).
>
> Before the change:
> ```
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 10000 thrpt 5 61431.706 ± 13049.185 ops/s
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 50000 thrpt 5 30442.256 ± 19143.475 ops/s
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 100000 thrpt 5 0.087 ± 0.022 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 1000 N/A N/A thrpt 5 151.684 ± 77.845 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 5000 N/A N/A thrpt 5 39.098 ± 3.030 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 10000 N/A N/A thrpt 5 20.233 ± 2.385 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 1 N/A N/A N/A thrpt 5 39.556 ± 13.071 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 10 N/A N/A N/A thrpt 5 39.307 ± 9.991 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 100 N/A N/A N/A thrpt 5 24.029 ± 5.149 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 1000 N/A N/A N/A thrpt 5 17.671 ± 6.065 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 10 N/A thrpt 5 37.791 ± 13.941 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 100 N/A thrpt 5 37.189 ± 26.962 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 1000 N/A thrpt 5 26.881 ± 15.143 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 10000 N/A thrpt 5 13.874 ± 4.928 ops/s
> ```
>
> With this change:
> ```
> Benchmark (instanceOverrides) (instances) (metadata) (numTasks) Mode Cnt Score Error Units
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 10000 thrpt 5 64510.645 ± 11207.229 ops/s
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 50000 thrpt 5 53270.516 ± 21560.208 ops/s
> TaskStoreBenchmarks.DBFetchTasksBenchmark.run N/A N/A N/A 100000 thrpt 5 40471.488 ± 36196.208 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 1000 N/A N/A thrpt 5 471.175 ± 436.428 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 5000 N/A N/A thrpt 5 120.241 ± 113.142 ops/s
> UpdateStoreBenchmarks.JobDetailsBenchmark.run N/A 10000 N/A N/A thrpt 5 67.512 ± 28.800 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 1 N/A N/A N/A thrpt 5 129.110 ± 50.366 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 10 N/A N/A N/A thrpt 5 137.847 ± 18.581 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 100 N/A N/A N/A thrpt 5 90.551 ± 61.773 ops/s
> UpdateStoreBenchmarks.JobInstructionsBenchmark.run 1000 N/A N/A N/A thrpt 5 52.958 ± 3.552 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 10 N/A thrpt 5 127.873 ± 83.669 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 100 N/A thrpt 5 119.673 ± 66.301 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 1000 N/A thrpt 5 76.271 ± 42.117 ops/s
> UpdateStoreBenchmarks.JobUpdateMetadataBenchmark.run N/A N/A 10000 N/A thrpt 5 41.306 ± 10.706 ops/s
> ```
>
>
> Diffs
> -----
>
> src/main/java/org/apache/aurora/scheduler/storage/db/DbModule.java d1a196419b67108ee2bb778f83a2993e2e5ee83b
> src/main/resources/logback.xml f4a8fa1d5184e6e246ae0742193d66cad7e0d58d
>
>
> Diff: https://reviews.apache.org/r/55071/diff/1/
>
>
> Testing
> -------
>
> ./gradlew jmh -Pbenchmarks='TaskStoreBenchmarks.DBFetchTasksBenchmark|UpdateStoreBenchmarks.*'
> ./gradlew -Pq build
>
>
> Thanks,
>
> Stephan Erb
>
>