[
https://issues.apache.org/jira/browse/CASSANDRA-19632?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17849653#comment-17849653
]
Stefan Miklosovic commented on CASSANDRA-19632:
-----------------------------------------------
I have also changed the logging level to INFO and run the bench to see the
times as if trace was enabled (because it just logs on INFO by default)
Without wrapping it in isInfoEnabled, it takes around 41 microseconds to log.
With the check it takes around 46 microseconds. So the check takes around 5
microseconds and wrapping it makes it about 13% slower.
{noformat}
Result "org.apache.cassandra.test.microbench.LoggingBench.threeObjects":
N = 12306865
mean = 41340.392 ±(99.9%) 864.269 ns/op
Histogram, ns/op:
[ 0.000, 12500000.000) = 12305828
[ 12500000.000, 25000000.000) = 0
[ 25000000.000, 37500000.000) = 0
[ 37500000.000, 50000000.000) = 0
[ 50000000.000, 62500000.000) = 0
[ 62500000.000, 75000000.000) = 0
[ 75000000.000, 87500000.000) = 0
[ 87500000.000, 100000000.000) = 620
[100000000.000, 112500000.000) = 375
[112500000.000, 125000000.000) = 34
[125000000.000, 137500000.000) = 8
[137500000.000, 150000000.000) = 0
[150000000.000, 162500000.000) = 0
[162500000.000, 175000000.000) = 0
[175000000.000, 187500000.000) = 0
Percentiles, ns/op:
p(0.0000) = 6640.000 ns/op
p(50.0000) = 23648.000 ns/op
p(90.0000) = 69760.000 ns/op
p(95.0000) = 90496.000 ns/op
p(99.0000) = 151296.000 ns/op
p(99.9000) = 381440.000 ns/op
p(99.9900) = 1861632.000 ns/op
p(99.9990) = 102760448.000 ns/op
p(99.9999) = 117178368.000 ns/op
p(100.0000) = 127401984.000 ns/op
# Run complete. Total time: 00:02:04
REMEMBER: The numbers below are just data. To gain reusable insights, you need
to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design
factorial
experiments, perform baseline and negative tests that provide experimental
control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from
the domain experts.
Do not assume the numbers tell you what you want them to tell.
Benchmark Mode Cnt Score Error
Units
LoggingBench.threeObjects sample 12306865 41340.392 ± 864.269
ns/op
LoggingBench.threeObjects:p0.00 sample 6640.000
ns/op
LoggingBench.threeObjects:p0.50 sample 23648.000
ns/op
LoggingBench.threeObjects:p0.90 sample 69760.000
ns/op
LoggingBench.threeObjects:p0.95 sample 90496.000
ns/op
LoggingBench.threeObjects:p0.99 sample 151296.000
ns/op
LoggingBench.threeObjects:p0.999 sample 381440.000
ns/op
LoggingBench.threeObjects:p0.9999 sample 1861632.000
ns/op
LoggingBench.threeObjects:p1.00 sample 127401984.000
ns/op
Process finished with exit code 0
Result
"org.apache.cassandra.test.microbench.LoggingBench.threeObjectsWithCheck":
N = 11186868
mean = 46985.745 ±(99.9%) 1093.366 ns/op
Histogram, ns/op:
[ 0.000, 12500000.000) = 11185771
[ 12500000.000, 25000000.000) = 3
[ 25000000.000, 37500000.000) = 0
[ 37500000.000, 50000000.000) = 0
[ 50000000.000, 62500000.000) = 0
[ 62500000.000, 75000000.000) = 0
[ 75000000.000, 87500000.000) = 0
[ 87500000.000, 100000000.000) = 0
[100000000.000, 112500000.000) = 712
[112500000.000, 125000000.000) = 326
[125000000.000, 137500000.000) = 48
[137500000.000, 150000000.000) = 8
[150000000.000, 162500000.000) = 0
[162500000.000, 175000000.000) = 0
[175000000.000, 187500000.000) = 0
Percentiles, ns/op:
p(0.0000) = 6680.000 ns/op
p(50.0000) = 25952.000 ns/op
p(90.0000) = 77312.000 ns/op
p(95.0000) = 100608.000 ns/op
p(99.0000) = 171520.000 ns/op
p(99.9000) = 422400.000 ns/op
p(99.9900) = 5999162.162 ns/op
p(99.9990) = 117833728.000 ns/op
p(99.9999) = 131203072.000 ns/op
p(100.0000) = 138936320.000 ns/op
# Run complete. Total time: 00:02:04
REMEMBER: The numbers below are just data. To gain reusable insights, you need
to follow up on
why the numbers are the way they are. Use profilers (see -prof, -lprof), design
factorial
experiments, perform baseline and negative tests that provide experimental
control, make sure
the benchmarking environment is safe on JVM/OS/HW level, ask for reviews from
the domain experts.
Do not assume the numbers tell you what you want them to tell.
Benchmark Mode Cnt Score
Error Units
LoggingBench.threeObjectsWithCheck sample 11186868 46985.745 ±
1093.366 ns/op
LoggingBench.threeObjectsWithCheck:p0.00 sample 6680.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.50 sample 25952.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.90 sample 77312.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.95 sample 100608.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.99 sample 171520.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.999 sample 422400.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.9999 sample 5999162.162
ns/op
LoggingBench.threeObjectsWithCheck:p1.00 sample 138936320.000
ns/op
{noformat}
> wrap tracing logs in isTraceEnabled across the codebase
> -------------------------------------------------------
>
> Key: CASSANDRA-19632
> URL: https://issues.apache.org/jira/browse/CASSANDRA-19632
> Project: Cassandra
> Issue Type: Improvement
> Components: Legacy/Core
> Reporter: Stefan Miklosovic
> Assignee: Stefan Miklosovic
> Priority: Normal
> Fix For: 5.x
>
> Time Spent: 40m
> Remaining Estimate: 0h
>
> Our usage of logger.isTraceEnabled across the codebase is inconsistent. This
> would also fix issues similar in e.g. CASSANDRA-19429 as [~rustyrazorblade]
> suggested.
> We should fix this at least in trunk and 5.0 (not critical though) and
> probably come up with a checkstyle rule to prevent not calling isTraceEnabled
> while logging with TRACE level.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
