Thanks again, Remko. After you detailed explanation everything makes sense
now.
I am using an i7 machine with Ubuntu.
-Becky
On Sat, Mar 29, 2014 at 8:49 PM, Remko Popma remko.po...@gmail.com wrote:
When you run PerfTest with these options below you get the same as the
first test run by PerfTestDriver Log4j2: Loggers all async (single thread)
:
-Dlog4j.configurationFile=perf3PlainNoLoc.xml
-DLog4jContextSelector=org.apache.logging.log4j.core.async.
AsyncLoggerContextSelector
PerfTestDriver runs each test 5 times and averages the result in the last
report line.
(When running PerfTestDriver you don't need to specify the above system
properties; it will start a new process for each test and specify the
correct system properties for each child process.)
How to read the report line results:
PerfTest format:
avg=1250 99%=2048 99.99%=16384 sampleCount=500
2587352 operations/second
The first line is latency test results. It measured 5,000,000 calls to
logger.info, with a 1 microsec busy-spin pause in between each
measurement.
All these measurements (in nanosecs) were added to a Histogram that was set
up with buckets that are powers of two (2, 4. 8, 16, ... until 2^31). The
Histogram then reported that the average time taken by each call was 1250
nanos. 99% of the measurements took less than 2048 nanos, and 99.99% of the
measurements took less than 16,384 nanos. This is to give some idea of the
outliers (which is what you are most interested in when measuring latency).
Ideally you want to print the whole Histogram, so you know exactly how many
measurements each bucket had. This would give you a diagram similar to the
Async Logging Latency Histogram (at xx threads) diagram on the Async
Logger page (http://logging.apache.org/log4j/2.x/manual/async.html ). If
you want to do that you will need to modify the source code of
PerfTest#createSamplingReport to loop over the buckets in Histogram.
Histogram#getUpperBoundAt(index) gives the max number that goes into that
bucket (the power of 2), and Histogram#getCountAt(index) gives the number
of measurements for that bucket.
The PerfTestDriver final report line averages the result of 5 test runs.
For throughput this is okay, but for latency that is taking the average of
an average which is not a good idea (I should change that...).
Still, the PerfTestDriver also reports the individual PerfTest results, so
you get 5 latency reports which should give you some indication.
About the difference in the resulting numbers:
I've noticed that there can be large variation between runs. This can be
caused by many things.
I recommend running each test at least 3-5 times (this is why
PerfTestDriver will run PerfTest 5 times, so I can see if there is much
variation between runs). Also, try to not have any other processes running
at the same time as you are running the test. If unavoidable, try to have a
consistent load...
I would run the PerfTest a few more times and see if you get similar
results each time or whether the results become more similar to what we see
when this test is kicked off by the PerfTestDriver.
Just out of interest, what hardware/OS are you on?
On Sat, Mar 29, 2014 at 10:46 PM, Rebecca Ahlvarsson
rahlvars...@gmail.comwrote:
Thank you very much, Remko. So I ran both tests on my machine and got the
numbers below. I am interested in the latency numbers and throughput when
we have one (i.e. threadCount 1 ?) asynchronous logger thread using
disruptor. Can you point me out to these numbers on my results below? Not
sure what I am getting when I run RunLog4j2 because the average is much
higher than when I run PerfTestDriver. Also what is the difference
between
the five runs on PerfTestDriver? Are they the same thing executed 5
times?
java -Dlog4j.configurationFile=perf3PlainNoLoc.xml
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
-cp
target/classes:target/test-classes:lib/disruptor-3.2.1.jar:../log4j-api/target/classes
org.apache.logging.log4j.core.async.perftest.PerfTest
org.apache.logging.log4j.core.async.perftest.RunLog4j2 blah blah.log 1
-verbose
Starting PerfTest blah (1)...
Warming up the JVM...
Warmup complete in 24.1 seconds
Waiting 10 seconds for buffers to drain warmup data...
Starting the main test...
avg=1250 99%=2048 99.99%=16384 sampleCount=500
2587352 operations/second
java -Dlog4j.configurationFile=perf3PlainNoLoc.xml
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
-cp
target/classes:target/test-classes:lib/disruptor-3.2.1.jar:../log4j-api/target/classes
org.apache.logging.log4j.core.async.perftest.PerfTestDriver
Log4j2: Loggers all async (single thread) (1/5)... (2/5)... (3/5)...
(4/5)... (5/5)... took 319.3 seconds
avg=102 99%=256 99.99%=1024 sampleCount=500
4080781 operations/second
avg=168 99%=256 99.99%=1024
