logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Rebecca Ahlvarsson <rahlvars...@gmail.com>
Subject Re: Running disruptor async performance tests
Date Sun, 30 Mar 2014 23:05:56 GMT
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.popma@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=5000000
> 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
> <rahlvarsson@gmail.com>wrote:
>
> > 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=5000000
> > 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=5000000
> > 4080781 operations/second
> > avg=168 99%=256 99.99%=1024 sampleCount=5000000
> > 3376301 operations/second
> > avg=103 99%=256 99.99%=2048 sampleCount=5000000
> > 8383943 operations/second
> > avg=102 99%=256 99.99%=2048 sampleCount=5000000
> > 3500849 operations/second
> > avg=65 99%=256 99.99%=2048 sampleCount=5000000
> > 3143970 operations/second
> > throughput: 4,497,168 ops/sec. latency(ns): avg=108.0 99% < 256.0 99.99%
> <
> > 1638.4 (25000000 samples)
> > -----
> > Log4j2: Loggers mixed sync/async (single thread) (1/5)... (2/5)...
> (3/5)...
> > (4/5)... (5/5)... took 322.6 seconds
> > avg=214 99%=512 99.99%=2048 sampleCount=5000000
> > 4257812 operations/second
> > avg=217 99%=256 99.99%=2048 sampleCount=5000000
> > 3027177 operations/second
> > avg=271 99%=512 99.99%=2048 sampleCount=5000000
> > 4304127 operations/second
> > avg=217 99%=512 99.99%=2048 sampleCount=5000000
> > 3008435 operations/second
> > avg=223 99%=512 99.99%=2048 sampleCount=5000000
> > 5430000 operations/second
> > throughput: 4,005,510 ops/sec. latency(ns): avg=228.4 99% < 460.8 99.99%
> <
> > 2048.0 (25000000 samples)
> > -----
> >
> >
> >
> > On Sat, Mar 29, 2014 at 3:46 AM, Remko Popma <remko.popma@gmail.com>
> > wrote:
> >
> > > Hi Becky,
> > >
> > > The performance test code is a bit messy. Apologies for that.
> > >
> > > To answer your questions: I used the longer message for throughput
> tests,
> > > and the shorter message for latency tests.
> > > PerfTest parameters:
> > > [0] = runner class (like org.apache.logging.log4j.core.
> > > async.perftest.RunLog4j2)
> > > [1] = (blah) is the test name (like "Loggers all async") printed to the
> > > console when a test is started.
> > > [2] = file name to write results to
> > > [3] = thread count (default=3)
> > > followed by optional parameters -verbose and -throughput.
> > >
> > > The current implementation of PerfTest runs one throughput and one
> > latency
> > > test, regardless of whether -throughput is specified.
> > >
> > > The PerfTestDriver class is the start point for all tests. It sets up
> > > various things like classpath, and system properties to control various
> > > things for different tests. If you use the PerfTest class directly you
> > need
> > > to set up these parameters manually:
> > > -Dlog4j.configurationFile=perf3PlainNoLoc.xml
> > >
> > >
> >
> -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
> > >
> > > The  perf3PlainNoLoc.xml config determines the log file.
> > > The PerfTestDriver would automatically delete this file after each run,
> > you
> > > probably want to do this manually.
> > >
> > > Hope this helps,
> > > Remko
> > >
> > >
> > >
> > > On Sat, Mar 29, 2014 at 12:03 PM, Rebecca Ahlvarsson
> > > <rahlvarsson@gmail.com>wrote:
> > >
> > > > I am trying to run the async performance tests described on the link
> > > below
> > > > on my machine.
> > > >
> > > >
> > > >
> > >
> >
> http://logging.apache.org/log4j/2.x/manual/async.html#Asynchronous_Logging_Performance
> > > >
> > > > I am not an expert with log4j, so here is how far I got after
> building
> > > > log4j with maven:
> > > >
> > > > java -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
> > > >
> > > > Then I get this in the output:
> > > >
> > > > avg=17 99%=32 99.99%=64 sampleCount=5000000
> > > > 9962247 operations/second
> > > >
> > > > The questions I have are:
> > > >
> > > > 1. It looks like the source code IPerfTestRunner uses a much shorter
> > > > message "Short Msg" instead of the 500 characters message stated in
> the
> > > > link above. Is that intentional or is it a bug? Do we want to test
> the
> > > > latency with the 500-character message or just a short message?
> > > >
> > > > 2. I notice that my logs are NOT going to any file. I am probably
> > > > misconfiguring something with log4j. How do I generate a file with
> the
> > > > messages from the performance test?
> > > >
> > > > 3. I just want to test with one asynchronous logging thread, so I am
> > > > passing threadCount 1 above. What does the second parameter 'blah'
> > mean?
> > > >
> > > > 4. Not sure why I get operations/seconds if I am not passing
> > -throughput
> > > in
> > > > the command-line. I just want to get the latency numbers for now.
> After
> > > > that I will worry about throughput.
> > > >
> > > > So basically I just want to run the same test you run to see those
> > great
> > > > numbers on my production machine.
> > > >
> > > > Thanks for the help!
> > > >
> > > > -Becky
> > > >
> > >
> >
> >
> >
> > --
> > -Becky
> >
>



-- 
-Becky

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message