You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@jmeter.apache.org by bu...@apache.org on 2016/11/16 15:08:44 UTC
[Bug 60382] New: DBCP2 - JDBC Sample became very slow since 3.0
https://bz.apache.org/bugzilla/show_bug.cgi?id=60382
Bug ID: 60382
Summary: DBCP2 - JDBC Sample became very slow since 3.0
Product: JMeter
Version: 3.0
Hardware: PC
Status: NEW
Severity: regression
Priority: P2
Component: Main
Assignee: issues@jmeter.apache.org
Reporter: thomas.peyrard@outlook.com
Target Milestone: ---
Created attachment 34454
--> https://bz.apache.org/bugzilla/attachment.cgi?id=34454&action=edit
JMX file to benchmark insertion throughput of SQL Databases
Hi,
I update from JMeter 2.11 to JMeter 3.0 and faced issues with the JDBC Sampler.
I execute as many insertion queries as possible against different databases to
measure their throughput. Switching to JMeter 3 decreased the throughput by 2
on different databases.
For example, on H2, I had 7000 inserts/sec; now I'm around 3500 i/s.
In the bug 58786, there is a discussion about performance regression but the
patch has been merged, so I guess there is a workaround, but I didn't find it.
I attached a jmx file. You can notice that I set the poolMax to 1 instead of
10, but it does not solve the problem.
How can work around this issue?
Regards
--
You are receiving this mail because:
You are the assignee for the bug.
[Bug 60382] DBCP2 - JDBC Sample became very slow since 3.0
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60382
Philippe Mouawad <p....@ubik-ingenierie.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |p.mouawad@ubik-ingenierie.c
| |om
--- Comment #7 from Philippe Mouawad <p....@ubik-ingenierie.com> ---
Hello,
Can we close this bug or do you have more things in mind ?
Thanks
--
You are receiving this mail because:
You are the assignee for the bug.
[Bug 60382] DBCP2 - JDBC Sample became very slow since 3.0
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60382
thomas.peyrard@outlook.com changed:
What |Removed |Added
----------------------------------------------------------------------------
OS| |All
--- Comment #1 from thomas.peyrard@outlook.com ---
I also noticed big issues with logging. Some runs might need more Xmx to avoid
issues.
Below is a stack trace of a run of 10 minutes where executing the query takes
1% (not shown) and logging 36,47% and closing connection 43,64%!
__________________________________________________________________________________________________________________________________________________________________________________
Stack Trace Sample Count Percentage(%)
java.lang.Thread.run() 3 658 98,972
org.apache.jmeter.threads.JMeterThread.run() 3 658 98,972
org.apache.jmeter.threads.JMeterThread.processSampler(Sampler, Sampler,
JMeterContext) 3 541 95,806
org.apache.jmeter.threads.JMeterThread.executeSamplePackage(Sampler,
TransactionSampler, SamplePackage, JMeterContext) 3 541 95,806
org.apache.jmeter.threads.JMeterThread.runPreProcessors(List)
1 889 51,109
org.apache.jmeter.protocol.jdbc.processor.JDBCPreProcessor.process() 1 736
46,97
org.apache.jmeter.protocol.jdbc.processor.AbstractJDBCProcessor.process() 1
736 46,97
org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(Connection) 1
613 43,642
org.apache.commons.dbcp2.PoolingDataSource$PoolGuardConnectionWrapper.close()
1 613 43,642
org.apache.commons.dbcp2.DelegatingConnection.close() 1 613 43,642
org.apache.commons.dbcp2.DelegatingConnection.closeInternal() 1 612
43,615
org.apache.commons.dbcp2.PoolableConnection.close() 1 611 43,588
org.apache.commons.pool2.impl.GenericObjectPool.returnObject(Object) 1
607 43,479
org.apache.commons.pool2.impl.BaseGenericObjectPool.swallowException(Exception)
1 348 36,472
org.apache.commons.dbcp2.SwallowedExceptionLogger.onSwallowException(Exception)
1 348 36,472
org.apache.commons.logging.impl.LogKitLogger.warn(Object, Throwable) 1
333 36,066
org.apache.log.Logger.warn(String, Throwable) 1 333 36,066
org.apache.log.Logger.output(Priority, String, Throwable) 1 332 36,039
org.apache.log.Logger.output(LogEvent) 1 327 35,904
org.apache.log.Logger.fireEvent(LogEvent, LogTarget[]) 1 327 35,904
org.apache.log.output.AbstractTarget.processEvent(LogEvent) 1 327 35,904
org.apache.log.output.AbstractOutputTarget.doProcessEvent(LogEvent) 1 327
35,904
org.apache.log.output.io.WriterTarget.write(String) 753 20,373
java.io.Writer.write(String) 732 19,805
java.io.OutputStreamWriter.write(String, int, int) 732 19,805
sun.nio.cs.StreamEncoder.write(String, int, int) 732 19,805
sun.nio.cs.StreamEncoder.write(char[], int, int) 673 18,209
sun.nio.cs.StreamEncoder.implWrite(char[], int, int) 668 18,074
java.nio.charset.CharsetEncoder.encode(CharBuffer, ByteBuffer, boolean)
666 18,019
sun.nio.cs.SingleByte$Encoder.encodeLoop(CharBuffer, ByteBuffer) 666
18,019
sun.nio.cs.SingleByte$Encoder.encodeArrayLoop(CharBuffer, ByteBuffer)
655 17,722
sun.nio.cs.SingleByte.access$000(CoderResult, Buffer, int, Buffer,
int) 1 0,027
_____________________________________________________________________________________________________________________________________________________________________________________
Looking at the logkit.xml file, I can see it still references excalibur, is
expected?
...
<factory type="file"
class="org.apache.avalon.excalibur.logger.factory.FileTargetFactory"/>
...
--
You are receiving this mail because:
You are the assignee for the bug.
[Bug 60382] DBCP2 - JDBC Sample became very slow since 3.0
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60382
thomas.peyrard@outlook.com changed:
What |Removed |Added
----------------------------------------------------------------------------
Resolution|--- |FIXED
Status|NEEDINFO |RESOLVED
--- Comment #8 from thomas.peyrard@outlook.com ---
yes we can close it.
--
You are receiving this mail because:
You are the assignee for the bug.
[Bug 60382] DBCP2 - JDBC Sample became very slow since 3.0
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60382
--- Comment #5 from Felix Schumacher <fe...@internetallee.de> ---
Created attachment 34460
--> https://bz.apache.org/bugzilla/attachment.cgi?id=34460&action=edit
Create sample data to be used with the testplan
The testplan needs input data. I have guessed, what the data should look like
and created a perl script, that generates that data (probably a bit too much).
With that data and profiling with jmc (with oracle java 8) by using:
export JVM_ARGS="-XX:+UnlockCommercialFeatures -XX:+FlightRecorder
-XX:StartFlightRecording=duration=60s,filename=recordings_v2_13.jfr"
/bin/jmeter -t /tmp/dbcp2-test/test-dbcp2.jmx -l
/tmp/dbcp2-test/test-dbcp2_v3_1.jtl -j /tmp/dbcp2-test/test-dbcp2_v3_1.log -n
-Jdb_url="jdbc:h2:mem:" -Jdb_class=org.h2.Driver
-Jclient_data_dir=/tmp/dbcp-test2
I created a bit of profiling data and looking at it, saw that you are suffering
from the removal of the prepared statement cache. H2 will spent 20% of the
whole cpu cycles parsing the prepared statements.
Modern jdbc driver should be able to cache those statements on their own. Are
you using H2 in production as well? Could you test whether you have the same
problems with your production db?
--
You are receiving this mail because:
You are the assignee for the bug.
[Bug 60382] DBCP2 - JDBC Sample became very slow since 3.0
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60382
--- Comment #6 from thomas.peyrard@outlook.com ---
Thanks for the test and profiling.
I got the same results when profiling H2 driver. I don't use H2 in production,
it's used in our benchmark/monitoring framework to spot regression either of
client or the database or out framework.
Our users cache prepared statements in their application, so we are the only
one to face regression with JMeter 3.1 :)
I'll either change H2 for another DB or try another driver.
For information, data / queries come from TPC-H.
Regards,
Thomas
--
You are receiving this mail because:
You are the assignee for the bug.
[Bug 60382] DBCP2 - JDBC Sample became very slow since 3.0
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60382
Felix Schumacher <fe...@internetallee.de> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |NEEDINFO
--- Comment #2 from Felix Schumacher <fe...@internetallee.de> ---
Please retry with current nightly (or 3.1 RC3). 3.0 had a problem with caching
the connections from the pool.
You might also try (with current nightly or RC) to set an empty validation
query and see if that helps a bit further.
--
You are receiving this mail because:
You are the assignee for the bug.
[Bug 60382] DBCP2 - JDBC Sample became very slow since 3.0
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60382
--- Comment #3 from thomas.peyrard@outlook.com ---
I built from the code and give it a try. It seems better.
I'll run all my tests during the night.
--
You are receiving this mail because:
You are the assignee for the bug.
[Bug 60382] DBCP2 - JDBC Sample became very slow since 3.0
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60382
--- Comment #4 from thomas.peyrard@outlook.com ---
JMeter 3.1 as of HEAD of 16th of November solved my issue on my dev machine (12
cores) but did not at all on my VM Server (4 cores).
I don't see any error in JMeter logs.
I'll try to attach a profiler to see where the difference could from. But the
dbcp2 pool seems to behave really differently from Excalibur and involves some
issue on my side :/
--
You are receiving this mail because:
You are the assignee for the bug.