[
https://issues.apache.org/jira/browse/CASSANDRA-19632?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17849647#comment-17849647
]
Stefan Miklosovic commented on CASSANDRA-19632:
-----------------------------------------------
I tried to benchmark this, I was tracing three-param message with and without
isTraceEnabled check.
{noformat}
package org.apache.cassandra.test.microbench;
import java.util.concurrent.TimeUnit;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Fork;
import org.openjdk.jmh.annotations.Measurement;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.annotations.Threads;
import org.openjdk.jmh.annotations.Warmup;
@BenchmarkMode(Mode.SampleTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 3, time = 1)
@Measurement(iterations = 6, time = 20)
@Fork(value = 1, jvmArgsAppend = { "-Xmx256M", "-Djmh.executor=CUSTOM",
"-Djmh.executor.class=org.apache.cassandra.test.microbench.FastThreadExecutor"})
@Threads(8)
@State(Scope.Benchmark)
public class LoggingBench
{
private static final Logger logger =
LoggerFactory.getLogger(LoggingBench.class);
private static final MyObject myObject = new MyObject();
@Benchmark
public void threeObjects()
{
logger.trace("this is a message with one parameter {}, {}, {}",
myObject, myObject, myObject);
}
@Benchmark
public void threeObjectsWithCheck()
{
if (logger.isTraceEnabled())
logger.trace("this is a message with one parameter {}, {}, {}",
myObject, myObject, myObject);
}
public static class MyObject
{
@Override
public String toString()
{
return "MyObject{}";
}
}
}
{noformat}
Results:
{noformat}
# JMH version: 1.37
# VM version: JDK 11.0.12, OpenJDK 64-Bit Server VM, 11.0.12+7
# VM invoker: /home/fermat/.sdkman/candidates/java/11.0.12-open/bin/java
# VM options:
-javaagent:/home/fermat/.local/share/JetBrains/Toolbox/apps/IDEA-U/ch-0/233.15026.9/lib/idea_rt.jar=40847:/home/fermat/.local/share/JetBrains/Toolbox/apps/IDEA-U/ch-0/233.15026.9/bin
-Dfile.encoding=UTF-8 -Xmx256M -Djmh.executor=CUSTOM
-Djmh.executor.class=org.apache.cassandra.test.microbench.FastThreadExecutor
# Blackhole mode: full + dont-inline hint (auto-detected, use
-Djmh.blackhole.autoDetect=false to disable)
# Warmup: 3 iterations, 1 s each
# Measurement: 6 iterations, 20 s each
# Timeout: 10 min per iteration
# Threads: 8 threads, will synchronize iterations
# Benchmark mode: Sampling time
# Benchmark: org.apache.cassandra.test.microbench.LoggingBench.threeObjects
# Run progress: 0.00% complete, ETA 00:04:06
# Fork: 1 of 1
# Warmup Iteration 1: DEBUG [main] 2024-05-27 09:10:02,600
InternalLoggerFactory.java:63 - Using SLF4J as the default logging framework
44.788 ±(99.9%) 10.007 ns/op
# Warmup Iteration 2: 34.661 ±(99.9%) 1.355 ns/op
# Warmup Iteration 3: 26.908 ±(99.9%) 0.543 ns/op
Iteration 1: 26.945 ±(99.9%) 0.113 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 30.000 ns/op
p0.99: 31.000 ns/op
p0.999: 50.000 ns/op
p0.9999: 1857.329 ns/op
p1.00: 53312.000 ns/op
Iteration 2: 27.736 ±(99.9%) 0.136 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 30.000 ns/op
p0.99: 31.000 ns/op
p0.999: 50.000 ns/op
p0.9999: 2592.000 ns/op
p1.00: 29376.000 ns/op
Iteration 3: 28.188 ±(99.9%) 0.088 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 40.000 ns/op
p0.999: 60.000 ns/op
p0.9999: 170.000 ns/op
p1.00: 94720.000 ns/op
Iteration 4: 28.113 ±(99.9%) 0.099 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 31.000 ns/op
p0.999: 50.000 ns/op
p0.9999: 330.000 ns/op
p1.00: 41216.000 ns/op
Iteration 5: 28.349 ±(99.9%) 0.071 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 40.000 ns/op
p0.999: 60.000 ns/op
p0.9999: 181.000 ns/op
p1.00: 50496.000 ns/op
Iteration 6: 28.240 ±(99.9%) 0.067 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 31.000 ns/op
p0.999: 60.000 ns/op
p0.9999: 161.000 ns/op
p1.00: 34880.000 ns/op
Result "org.apache.cassandra.test.microbench.LoggingBench.threeObjects":
N = 29351102
mean = 28.026 ±(99.9%) 0.037 ns/op
Histogram, ns/op:
[ 0.000, 10000.000) = 29350855
[ 10000.000, 20000.000) = 220
[ 20000.000, 30000.000) = 15
[ 30000.000, 40000.000) = 7
[ 40000.000, 50000.000) = 1
[ 50000.000, 60000.000) = 2
[ 60000.000, 70000.000) = 0
[ 70000.000, 80000.000) = 0
[ 80000.000, 90000.000) = 1
Percentiles, ns/op:
p(0.0000) = 20.000 ns/op
p(50.0000) = 30.000 ns/op
p(90.0000) = 30.000 ns/op
p(95.0000) = 31.000 ns/op
p(99.0000) = 40.000 ns/op
p(99.9000) = 60.000 ns/op
p(99.9900) = 230.000 ns/op
p(99.9990) = 8114.853 ns/op
p(99.9999) = 19540.765 ns/op
p(100.0000) = 94720.000 ns/op
# JMH version: 1.37
# VM version: JDK 11.0.12, OpenJDK 64-Bit Server VM, 11.0.12+7
# VM invoker: /home/fermat/.sdkman/candidates/java/11.0.12-open/bin/java
# VM options:
-javaagent:/home/fermat/.local/share/JetBrains/Toolbox/apps/IDEA-U/ch-0/233.15026.9/lib/idea_rt.jar=40847:/home/fermat/.local/share/JetBrains/Toolbox/apps/IDEA-U/ch-0/233.15026.9/bin
-Dfile.encoding=UTF-8 -Xmx256M -Djmh.executor=CUSTOM
-Djmh.executor.class=org.apache.cassandra.test.microbench.FastThreadExecutor
# Blackhole mode: full + dont-inline hint (auto-detected, use
-Djmh.blackhole.autoDetect=false to disable)
# Warmup: 3 iterations, 1 s each
# Measurement: 6 iterations, 20 s each
# Timeout: 10 min per iteration
# Threads: 8 threads, will synchronize iterations
# Benchmark mode: Sampling time
# Benchmark:
org.apache.cassandra.test.microbench.LoggingBench.threeObjectsWithCheck
# Run progress: 50.00% complete, ETA 00:02:03
# Fork: 1 of 1
# Warmup Iteration 1: DEBUG [main] 2024-05-27 09:12:06,494
InternalLoggerFactory.java:63 - Using SLF4J as the default logging framework
38.000 ±(99.9%) 4.089 ns/op
# Warmup Iteration 2: 30.940 ±(99.9%) 1.331 ns/op
# Warmup Iteration 3: 28.966 ±(99.9%) 0.550 ns/op
Iteration 1: 28.565 ±(99.9%) 0.100 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 31.000 ns/op
p0.999: 50.000 ns/op
p0.9999: 2033.265 ns/op
p1.00: 21120.000 ns/op
Iteration 2: 28.646 ±(99.9%) 0.110 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 31.000 ns/op
p0.999: 50.000 ns/op
p0.9999: 2059.553 ns/op
p1.00: 29312.000 ns/op
Iteration 3: 28.963 ±(99.9%) 0.212 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 31.000 ns/op
p0.999: 60.000 ns/op
p0.9999: 2243.614 ns/op
p1.00: 109568.000 ns/op
Iteration 4: 28.838 ±(99.9%) 0.114 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 31.000 ns/op
p0.999: 51.000 ns/op
p0.9999: 411.000 ns/op
p1.00: 55872.000 ns/op
Iteration 5: 28.762 ±(99.9%) 0.091 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 31.000 ns/op
p0.999: 50.000 ns/op
p0.9999: 351.000 ns/op
p1.00: 29888.000 ns/op
Iteration 6: 28.918 ±(99.9%) 0.234 ns/op
p0.00: 20.000 ns/op
p0.50: 30.000 ns/op
p0.90: 30.000 ns/op
p0.95: 31.000 ns/op
p0.99: 31.000 ns/op
p0.999: 51.000 ns/op
p0.9999: 340.000 ns/op
p1.00: 229120.000 ns/op
Result
"org.apache.cassandra.test.microbench.LoggingBench.threeObjectsWithCheck":
N = 21348591
mean = 28.788 ±(99.9%) 0.064 ns/op
Histogram, ns/op:
[ 0.000, 25000.000) = 21348570
[ 25000.000, 50000.000) = 14
[ 50000.000, 75000.000) = 2
[ 75000.000, 100000.000) = 2
[100000.000, 125000.000) = 2
[125000.000, 150000.000) = 0
[150000.000, 175000.000) = 0
[175000.000, 200000.000) = 0
[200000.000, 225000.000) = 0
[225000.000, 250000.000) = 1
[250000.000, 275000.000) = 0
Percentiles, ns/op:
p(0.0000) = 20.000 ns/op
p(50.0000) = 30.000 ns/op
p(90.0000) = 30.000 ns/op
p(95.0000) = 31.000 ns/op
p(99.0000) = 31.000 ns/op
p(99.9000) = 51.000 ns/op
p(99.9900) = 381.000 ns/op
p(99.9990) = 8640.451 ns/op
p(99.9999) = 25033.690 ns/op
p(100.0000) = 229120.000 ns/op
# Run complete. Total time: 00:04:07
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 29351102 28.026 ±
0.037 ns/op
LoggingBench.threeObjects:p0.00 sample 20.000
ns/op
LoggingBench.threeObjects:p0.50 sample 30.000
ns/op
LoggingBench.threeObjects:p0.90 sample 30.000
ns/op
LoggingBench.threeObjects:p0.95 sample 31.000
ns/op
LoggingBench.threeObjects:p0.99 sample 40.000
ns/op
LoggingBench.threeObjects:p0.999 sample 60.000
ns/op
LoggingBench.threeObjects:p0.9999 sample 230.000
ns/op
LoggingBench.threeObjects:p1.00 sample 94720.000
ns/op
LoggingBench.threeObjectsWithCheck sample 21348591 28.788 ±
0.064 ns/op
LoggingBench.threeObjectsWithCheck:p0.00 sample 20.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.50 sample 30.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.90 sample 30.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.95 sample 31.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.99 sample 31.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.999 sample 51.000
ns/op
LoggingBench.threeObjectsWithCheck:p0.9999 sample 381.000
ns/op
LoggingBench.threeObjectsWithCheck:p1.00 sample 229120.000
ns/op
Process finished with exit code 0
{noformat}
I think the moral of the story is that wrapping it with isTraceEnabled yields
no practical results, the difference is negligable, around 1 nanosecond if I
interpret the results correctly. Wrapping simple log statements in
isTraceEnabled (no or few objects as params with no heavyweight string
evaluation) does not have any practical benefits, it is actually slightly
slower.
> 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]
