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 2016/12/28 11:28:36 UTC
Review Request 55071: Disable H2 logging via SLF4J.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/55071/
-----------------------------------------------------------
Review request for Aurora, 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/
Testing
-------
./gradlew jmh -Pbenchmarks='TaskStoreBenchmarks.DBFetchTasksBenchmark|UpdateStoreBenchmarks.*'
./gradlew -Pq build
Thanks,
Stephan Erb
Re: Review Request 55071: Disable H2 logging via SLF4J.
Posted by Joshua Cohen <jc...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/55071/#review161954
-----------------------------------------------------------
Ship it!
Ship It!
- Joshua Cohen
On Dec. 28, 2016, 11:28 a.m., Stephan Erb wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/55071/
> -----------------------------------------------------------
>
> (Updated Dec. 28, 2016, 11:28 a.m.)
>
>
> Review request for Aurora, 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/
>
>
> Testing
> -------
>
> ./gradlew jmh -Pbenchmarks='TaskStoreBenchmarks.DBFetchTasksBenchmark|UpdateStoreBenchmarks.*'
> ./gradlew -Pq build
>
>
> Thanks,
>
> Stephan Erb
>
>
Re: Review Request 55071: Disable H2 logging via SLF4J.
Posted by Stephan Erb <se...@apache.org>.
> On Jan. 18, 2017, 12:03 a.m., Zameer Manji wrote:
> > I'm not a huge fan of this.
> >
> > I think piping logs to stdout is an operational change (by default everything went to stderr) and plus it is nice to use the logback.xml configuration.
> >
> > Have we considered filing a ticket upstream? H2 can fix this integration bug.
I have filed https://github.com/h2database/h2database/issues/438.
- Stephan
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/55071/#review161986
-----------------------------------------------------------
On Dec. 28, 2016, 12:28 p.m., Stephan Erb wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/55071/
> -----------------------------------------------------------
>
> (Updated Dec. 28, 2016, 12:28 p.m.)
>
>
> Review request for Aurora, 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/
>
>
> Testing
> -------
>
> ./gradlew jmh -Pbenchmarks='TaskStoreBenchmarks.DBFetchTasksBenchmark|UpdateStoreBenchmarks.*'
> ./gradlew -Pq build
>
>
> Thanks,
>
> Stephan Erb
>
>
Re: Review Request 55071: Disable H2 logging via SLF4J.
Posted by Zameer Manji <zm...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/55071/#review161986
-----------------------------------------------------------
I'm not a huge fan of this.
I think piping logs to stdout is an operational change (by default everything went to stderr) and plus it is nice to use the logback.xml configuration.
Have we considered filing a ticket upstream? H2 can fix this integration bug.
- Zameer Manji
On Dec. 28, 2016, 3:28 a.m., Stephan Erb wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/55071/
> -----------------------------------------------------------
>
> (Updated Dec. 28, 2016, 3:28 a.m.)
>
>
> Review request for Aurora, 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/
>
>
> Testing
> -------
>
> ./gradlew jmh -Pbenchmarks='TaskStoreBenchmarks.DBFetchTasksBenchmark|UpdateStoreBenchmarks.*'
> ./gradlew -Pq build
>
>
> Thanks,
>
> Stephan Erb
>
>
Re: Review Request 55071: Disable H2 logging via SLF4J.
Posted by Mehrdad Nurolahzade <me...@nurolahzade.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/55071/#review160237
-----------------------------------------------------------
Ship it!
We are not internally using H2 trace files.
Logging errors to stdout sounds good.
- Mehrdad Nurolahzade
On Dec. 28, 2016, 3:28 a.m., Stephan Erb wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/55071/
> -----------------------------------------------------------
>
> (Updated Dec. 28, 2016, 3:28 a.m.)
>
>
> Review request for Aurora, 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/
>
>
> Testing
> -------
>
> ./gradlew jmh -Pbenchmarks='TaskStoreBenchmarks.DBFetchTasksBenchmark|UpdateStoreBenchmarks.*'
> ./gradlew -Pq build
>
>
> Thanks,
>
> Stephan Erb
>
>
Re: Review Request 55071: Disable H2 logging via SLF4J.
Posted by Aurora ReviewBot <wf...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/55071/#review160222
-----------------------------------------------------------
Master (21ad18e) is green with this patch.
./build-support/jenkins/build.sh
However, it appears that it might lack test coverage.
I will refresh this build result if you post a review containing "@ReviewBot retry"
- Aurora ReviewBot
On Dec. 28, 2016, 11:28 a.m., Stephan Erb wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/55071/
> -----------------------------------------------------------
>
> (Updated Dec. 28, 2016, 11:28 a.m.)
>
>
> Review request for Aurora, 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/
>
>
> Testing
> -------
>
> ./gradlew jmh -Pbenchmarks='TaskStoreBenchmarks.DBFetchTasksBenchmark|UpdateStoreBenchmarks.*'
> ./gradlew -Pq build
>
>
> Thanks,
>
> Stephan Erb
>
>