Bug 54777 - Improve Performance of default ResultCollector
Improve Performance of default ResultCollector
Status: RESOLVED FIXED
Product: JMeter
Classification: Unclassified
Component: Main
2.9
All All
: P2 enhancement (vote)
: ---
Assigned To: JMeter issues mailing list
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2013-03-31 10:40 UTC by Mikhail Epikhin
Modified: 2013-04-04 19:31 UTC (History)
2 users (show)



Attachments
Updated patch (4.22 KB, patch)
2013-03-31 22:42 UTC, Philippe Mouawad
Details | Diff
Test Plan used (5.00 KB, application/xml)
2013-04-01 14:17 UTC, Philippe Mouawad
Details
Test-plan for benchmarking WritebackPrintWriter (4.90 KB, application/xml)
2013-04-01 14:55 UTC, Mikhail Epikhin
Details
Test Plan for test without external dependencies (5.00 KB, application/xml)
2013-04-01 19:37 UTC, Philippe Mouawad
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Mikhail Epikhin 2013-03-31 10:40:08 UTC
Hello! I'm use Apache JMeter for hit-based load testing apache cassandra with netflix plugins. But, default logging of ResultCollector is really too slow. I have lock artefacts at throughtput about 35krps with simple csv settings. In thread dump i see many block threads on java.io.PrintWriter.println(). I write writeback cache for PrintWriter and have more performant solution.

I showed it Phillipe M. and his patched my code:)

Performance comparsion of solutions: https://docs.google.com/spreadsheet/oimg?key=0Au50JydZm7UjdDlzWkhzMTJoMllxS3BWMGd2bXd6SUE&oid=4&zx=cjjfchh72va2

My first patch is https://gist.github.com/sch1z0phren1a/5190889
Second patch with Phillipe M. changes is https://gist.github.com/sch1z0phren1a/6bf25227b63a4d9e05f3

I tested it with simple Dummy Sampler from jmeter-plugins.
Test Plan is here https://gist.github.com/sch1z0phren1a/b65bf49de6a6f90efa18


So, what about include it into Apache JMeter? :)

Phillipe, thanks you!:)
Comment 1 Mikhail Epikhin 2013-03-31 10:53:32 UTC
Sorry, for my misprints, Philippe:)
Comment 2 Sebb 2013-03-31 17:34:20 UTC
Thanks for the suggested patch. I'm not clear why the code should be better than PrintWriter.println() - this ought to be explained in the Javadoc.

There are some problems with the code as it stands:

The field lineSeparator cannot be fixed as '\n', as that is not portable.

Constructors should not start threads - there is no guarantee that the class will have been fully constructed before the thread tries accessing it.

A couple of minor style issues: we don't generally allow multiple statements per line.
Aslo we always use blocks in conditional statements.
Comment 3 Mikhail Epikhin 2013-03-31 18:03:23 UTC
(In reply to comment #2)
> Thanks for the suggested patch. I'm not clear why the code should be better
> than PrintWriter.println() - this ought to be explained in the Javadoc.

1. Because real write is "async" opertation by Sampler, which running it in my code.

With simple autoFlush=true, everytime when you use println(), you alse call flush-ethod.

Just look at OpenJDK 1.7

println(String s) (http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/7-b147/java/io/PrintWriter.java?av=f
) 
  |                  \
  v                   v
print(String s)       println() (http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/7-b147/java/io/PrintWriter.java#PrintWriter.println%28%29)
                        |
                        v
                     newLine() -> out.flush() (http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/7-b147/java/io/PrintWriter.java#PrintWriter.newLine%28%29)


Soo, when you use autoFlush=true, println(), and many threads, u also have very poor performance.

Single flush method make context switch to kernel-thread, and his make real write-method. This is blocking operation. 
If i separate println() operation from Sampler Thread and flush() method to another thread, it make better performance. Sample Thread don't wait real flush on disk. He just do him-self job. Not write to log.

2. Decrease flush operation counts

> There are some problems with the code as it stands:
> 
> The field lineSeparator cannot be fixed as '\n', as that is not portable.
> 

Sorry, i look at PrintWriter.lineSeparator by OpenJDK and did it as well http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/7-b147/java/io/PrintWriter.java#PrintWriter.0lineSeparator

Any solutions for portable?

> Constructors should not start threads - there is no guarantee that the class
> will have been fully constructed before the thread tries accessing it.

If fluhs-thread not started, real buffer in super() will be constructured and another threads make println() operations, but in real, without flush, while flush-thread not started.

> A couple of minor style issues: we don't generally allow multiple statements
> per line.
> Aslo we always use blocks in conditional statements.

Okey, it's not a problem.
Comment 4 Sebb 2013-03-31 18:23:41 UTC
(In reply to comment #3)
> (In reply to comment #2)
> > Thanks for the suggested patch. I'm not clear why the code should be better
> > than PrintWriter.println() - this ought to be explained in the Javadoc.
> 
> 1. Because real write is "async" opertation by Sampler, which running it in
> my code.
> 
> With simple autoFlush=true, everytime when you use println(), you alse call
> flush-ethod.

OK, then this needs to be documented in the code.

Since the only function of the thread seems to be to run flush every so often, I wonder if a separate thread is really needed?

Perhaps a simple decorator would suffice.
That would solve the issue of how to start the thread safely.

> > There are some problems with the code as it stands:
> > 
> > The field lineSeparator cannot be fixed as '\n', as that is not portable.
> > 
> 
> Sorry, i look at PrintWriter.lineSeparator by OpenJDK and did it as well
> http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/7-
> b147/java/io/PrintWriter.java#PrintWriter.0lineSeparator

No, it does not.

It does not fix lineSeparator as the single char '\n'.
 
> Any solutions for portable?

Use the value of the property "line.separator" which is a String (e.g. it might be \r\n")

> > Constructors should not start threads - there is no guarantee that the class
> > will have been fully constructed before the thread tries accessing it.
> 
> If fluhs-thread not started, real buffer in super() will be constructured
> and another threads make println() operations, but in real, without flush,
> while flush-thread not started.

Yes, but the ctor still must not start a thread.
You need to find a way to start the thread after construction.
Comment 5 Mikhail Epikhin 2013-03-31 18:32:45 UTC
(In reply to comment #4)
> (In reply to comment #3)
> > (In reply to comment #2)
> > > Thanks for the suggested patch. I'm not clear why the code should be better
> > > than PrintWriter.println() - this ought to be explained in the Javadoc.
> > 
> > 1. Because real write is "async" opertation by Sampler, which running it in
> > my code.
> > 
> > With simple autoFlush=true, everytime when you use println(), you alse call
> > flush-ethod.
> 
> OK, then this needs to be documented in the code.
> 
> Since the only function of the thread seems to be to run flush every so
> often, I wonder if a separate thread is really needed?
> 
> Perhaps a simple decorator would suffice.
> That would solve the issue of how to start the thread safely.

My generic idea is writeback module. Yeah, decorator it's good idea. But one of the samplers would doing flush-method, and his will be wait response from kernel. But maybe it doesn't matter?

> > > There are some problems with the code as it stands:
> > > 
> > > The field lineSeparator cannot be fixed as '\n', as that is not portable.
> > > 
> > 
> > Sorry, i look at PrintWriter.lineSeparator by OpenJDK and did it as well
> > http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/7-
> > b147/java/io/PrintWriter.java#PrintWriter.0lineSeparator
> 
> No, it does not.
> 
> It does not fix lineSeparator as the single char '\n'.
>  
> > Any solutions for portable?
> 
> Use the value of the property "line.separator" which is a String (e.g. it
> might be \r\n")

Okey, but it not good pratice.
> 
> > > Constructors should not start threads - there is no guarantee that the class
> > > will have been fully constructed before the thread tries accessing it.
> > 
> > If fluhs-thread not started, real buffer in super() will be constructured
> > and another threads make println() operations, but in real, without flush,
> > while flush-thread not started.
> 
> Yes, but the ctor still must not start a thread.
> You need to find a way to start the thread after construction.

Okey, lets play with decorator:)
Comment 6 Mikhail Epikhin 2013-03-31 18:58:27 UTC
Hmm. If i not use Runnable, then last buffer may not flushed on disk. Its bad.
Comment 8 Philippe Mouawad 2013-03-31 22:42:08 UTC
Created attachment 30124 [details]
Updated patch

Modified a little:
- removed useless close at parent close also flush

I still wonder if synchronized(this) blocks are useful
Comment 9 Philippe Mouawad 2013-04-01 14:09:08 UTC
Hello Mikhail,
In fact looking at new patch I don't think it improves performances.

I made some new tests which I hadn't make before and:
1) I don't have the same improvements as yours, see attached test plan, I have a 0.4% improvement on number of Samples done in 5 minutes. What do you graph exactly ? and what is your properties files configuration ?
2) I wonder if the only change to be done should not be to switch off AutoFlush and nothing more

Because In fact with AutoFlush false, IO and flush will be controlled by the BufferedOutputStream over which printWriter is built.
Comment 10 Philippe Mouawad 2013-04-01 14:17:08 UTC
Created attachment 30127 [details]
Test Plan used
Comment 11 Mikhail Epikhin 2013-04-01 14:52:19 UTC
(In reply to comment #9)
> Hello Mikhail,
> In fact looking at new patch I don't think it improves performances.
> 
> I made some new tests which I hadn't make before and:
> 1) I don't have the same improvements as yours, see attached test plan, I
> have a 0.4% improvement on number of Samples done in 5 minutes. What do you
> graph exactly ? and what is your properties files configuration ?

Your test is not for measure performance of PrintWriter.
You use sleep on Sampler and thread don't create new SamplerResult objects. Test without sleeps, or sleep ~1ms.

I using Jmeter as hit-based load tool whis load >50krps. Last test with Apache Cassandra with single instance of Jmeter gives me about 95krps. And bottleneck is net throughput (1Gbit/s). At this speed standart PrintWriter is too slow. Because every SampleResult on println() call flush(), beacuse many threads of Samplers have high concurreny on PrintWriter. With this patch, at throughput over 30krps i have stable logging csv/xml. Now, i haven't Samplers Thread locks on java.io.PrintWriter.println().

This patch for high-throughput tests, over 30krps. Your test have throughtput less then 1krps. It not your case for improvment

> 2) I wonder if the only change to be done should not be to switch off
> AutoFlush and nothing more
> 
> Because In fact with AutoFlush false, IO and flush will be controlled by the
> BufferedOutputStream over which printWriter is built.

Look at tests. Look at profiling and thread dumps. If you really need tests with speed over 30krps, you also needed this patch.
Comment 12 Mikhail Epikhin 2013-04-01 14:54:26 UTC
For benchmark i use test plan with Dummy Sampler. Without sleeps.
Comment 13 Mikhail Epikhin 2013-04-01 14:55:27 UTC
Created attachment 30128 [details]
Test-plan for benchmarking WritebackPrintWriter
Comment 14 Philippe Mouawad 2013-04-01 19:37:48 UTC
Created attachment 30131 [details]
Test Plan for test without external dependencies
Comment 15 Philippe Mouawad 2013-04-01 19:39:11 UTC
You are right, my test plan is not fine, I forgot Java Sampler made a sleep.
I updated it.

Can you do on your side a Test with just autoflush set to false and no use of PrintbackWriter ?
Comment 16 Philippe Mouawad 2013-04-01 19:56:17 UTC
Results on my side:

AutoFlush = true
summary = 12061027 in   300s = 40204.4/s Avg:     0 Min:     0 Max:    13 Err:     0 (0.00%)
1.35 go written

AutoFlush = false
summary = 18362979 in   300s = 61210.7/s Avg:     0 Min:     0 Max:    61 Err:     0 (0.00%)Err:     0 (0.00%)
2.05 go written

Last Patch (Decorator):
summary = 17959888 in   300s = 59867.7/s Avg:     0 Min:     0 Max:    31 Err:     0 (0.00%)
2.01 go written
Comment 17 Philippe Mouawad 2013-04-01 20:06:10 UTC
Date: Mon Apr  1 20:05:33 2013
New Revision: 1463274

URL: http://svn.apache.org/r1463274
Log:
Bug 54777 - Improve Performance of default ResultCollector
Bugzilla Id: 54777

Modified:
    jmeter/trunk/src/core/org/apache/jmeter/reporters/ResultCollector.java
    jmeter/trunk/xdocs/changes.xml
Comment 18 Philippe Mouawad 2013-04-01 20:08:09 UTC
Thanks Mikhail for this improvement to JMeter core.
Comment 19 Mikhail Epikhin 2013-04-01 20:32:14 UTC
Sebb, what do you think about it? I don't think this is good idea to change autoFlush to false value.


My performance comparsion: https://docs.google.com/spreadsheet/oimg?key=0Au50JydZm7UjdDlzWkhzMTJoMllxS3BWMGd2bXd6SUE&oid=5&zx=j8es9dwce7m2
Comment 20 Philippe Mouawad 2013-04-01 20:37:24 UTC
Why do you think it's not a good idea ?
Comment 21 Mikhail Epikhin 2013-04-01 20:38:21 UTC
Using PrintWriter with autoFlush=false and without flush()-methods.
Comment 22 Mikhail Epikhin 2013-04-01 21:36:21 UTC
Hmmm. PrintWriter use BufferedWriter as OutputWriter. And his already have a buffer. It's good idea. Philippe, thank you. But be careful. If you forget close()-method or fd-leak, you have been a wonderful artefacts with lose of data.
Comment 23 Philippe Mouawad 2013-04-04 14:52:12 UTC
Date: Thu Apr  4 14:51:30 2013
New Revision: 1464580

URL: http://svn.apache.org/r1464580
Log:
Bug 54777 - Improve Performance of default ResultCollector
Add saving.autoflush
Bugzilla Id: 54777

Modified:
    jmeter/trunk/bin/jmeter.properties
    jmeter/trunk/src/core/org/apache/jmeter/reporters/ResultCollector.java
    jmeter/trunk/xdocs/changes.xml
Comment 24 Philippe Mouawad 2013-04-04 19:31:30 UTC
Date: Thu Apr  4 19:30:29 2013
New Revision: 1464689

URL: http://svn.apache.org/r1464689
Log:
Bug 54777 - Improve Performance of default ResultCollector
Bugzilla Id: 54777

Modified:
    jmeter/trunk/bin/jmeter.properties
    jmeter/trunk/src/core/org/apache/jmeter/reporters/ResultCollector.java
    jmeter/trunk/xdocs/changes.xml