https://issues.apache.org/bugzilla/show_bug.cgi?id=54960
Bug ID: 54960
Summary: MongoDB Protocol. Slow performance on eval function.
Product: JMeter
Version: Nightly (Please specify date)
Hardware: All
OS: All
Status: NEW
Severity: major
Priority: P2
Component: Main
Assignee: [email protected]
Reporter: [email protected]
Classification: Unclassified
Created attachment 30278
--> https://issues.apache.org/bugzilla/attachment.cgi?id=30278&action=edit
testplan with MongoDB samplers
Hi!
I wrote a very simple test plan. I wanted to measure performance of MongoDB
increments:)
I installed mongodb 2.4, and created BSON-document like this:
> db.test.insert( { name: "[email protected]", cnt:0 } )
> db.test.find();
{ "_id" : ObjectId("518d7610f646b39cb7c84fc4"), "name" : "[email protected]",
"cnt" : 0 }
Check increments method:
> db.test.update( { '_id': ObjectId("518d7610f646b39cb7c84fc4")}, { $inc :
> {cnt: 1}})
> db.test.find();
{ "_id" : ObjectId("518d7610f646b39cb7c84fc4"), "name" : "[email protected]",
"cnt" : 1 }
Then i created test-plan mongodb-increment.jmx and run test
schizophrenia@tachikoma02:~/Documents/mongodb-incs$
~/bin/apache-jmeter-r1480854/bin/jmeter-tank -t mongodb-increment.jmx
-Jthreads=4 -n
Created the tree successfully using mongodb-increment.jmx
Starting the test @ Tue May 14 00:00:17 MSK 2013 (1368475217679)
Waiting for possible shutdown message on port 4445
#0 Threads: 1/4 Samples: 1 Latency: 1 Resp.Time: 81 Errors: 0
#1 Threads: 4/4 Samples: 307 Latency: 0 Resp.Time: 6 Errors: 0
#2 Threads: 4/4 Samples: 376 Latency: 0 Resp.Time: 10 Errors: 0
#3 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 9 Errors: 0
#4 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 9 Errors: 0
#5 Threads: 4/4 Samples: 400 Latency: 0 Resp.Time: 10 Errors: 0
#6 Threads: 4/4 Samples: 392 Latency: 0 Resp.Time: 9 Errors: 0
#7 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 10 Errors: 0
#8 Threads: 4/4 Samples: 399 Latency: 0 Resp.Time: 10 Errors: 0
#9 Threads: 4/4 Samples: 393 Latency: 0 Resp.Time: 10 Errors: 0
#10 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 9 Errors: 0
#11 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 9 Errors: 0
#12 Threads: 4/4 Samples: 408 Latency: 0 Resp.Time: 9 Errors: 0
#13 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 10 Errors: 0
#14 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 9 Errors: 0
#15 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 10 Errors: 0
#16 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 10 Errors: 0
#17 Threads: 4/4 Samples: 396 Latency: 0 Resp.Time: 10 Errors: 0
#18 Threads: 4/4 Samples: 408 Latency: 0 Resp.Time: 9 Errors: 0
#19 Threads: 4/4 Samples: 408 Latency: 0 Resp.Time: 9 Errors: 0
#20 Threads: 4/4 Samples: 420 Latency: 0 Resp.Time: 9 Errors: 0
I see throughput about 380rps. And MongoDB have a lock contention on db.
insert query update delete getmore command flushes mapped vsize res faults
locked db idx miss % qr|qw ar|aw netIn netOut conn time
*0 32 384 *0 0 386|0 0 160m 886m 60m 0
.:72.3% 0 0|0 0|1 61k 25k 4 23:22:07
*0 32 372 *0 0 373|0 0 160m 886m 60m 0
.:69.2% 0 0|0 0|1 59k 25k 4 23:22:08
*0 31 384 *0 0 386|0 0 160m 886m 60m 0
.:72.5% 0 0|0 0|1 61k 26k 4 23:22:09
*0 32 384 *0 0 385|0 0 160m 886m 60m 0
.:71.6% 0 0|0 0|1 61k 25k 4 23:22:10
*0 32 384 *0 0 385|0 0 160m 886m 60m 0
.:71.8% 0 0|0 0|1 61k 25k 4 23:22:11
*0 34 407 *0 0 407|0 0 160m 886m 60m 0
.:76.3% 0 0|0 0|1 65k 27k 4 23:22:12
*0 34 397 *0 0 399|0 0 160m 886m 60m 0
.:75.1% 0 0|0 0|1 64k 26k 4 23:22:13
*0 34 408 *0 0 410|0 0 160m 886m 60m 0
.:77.4% 0 0|0 0|1 65k 27k 4 23:22:14
*0 34 409 *0 0 409|0 0 160m 886m 60m 0
.:79.0% 0 0|0 0|0 65k 27k 4 23:22:15
*0 34 407 *0 0 409|0 0 160m 886m 60m 0
.:75.3% 0 0|0 0|1 65k 27k 4 23:22:16
lock db is very high. But throughput is very small for hardware (i5 (2cores +
ht) + ssd) and version (2.4.3). Whats the problem? In this table we seen
command and query method.
But in reality, we should not see them. I go to source code and found that:
https://github.com/apache/jmeter/blob/trunk/src/protocol/mongodb/org/apache/jmeter/protocol/mongodb/sampler/MongoScriptRunner.java#L54
>>Object result = db.eval(script);
Sorry, but eval-method it's very poor choice for performance testing. DB must
parse this js-command, but in reality this does not happen.
Okey, let's write this test without eval method with simple beanshell samplers
like this:
http://schiz.me/blog/2012/11/03/base64-mongodb-with-beanshell-in-jmeter/
New testplan is mongodb-increment-beanshell.jmx
schizophrenia@tachikoma02:~/Documents/mongodb-incs$
~/bin/apache-jmeter-r1480854/bin/jmeter-tank -t mongodb-increment-beanshell.jmx
-Jthreads=4 -Jconnections=4 -n
Created the tree successfully using mongodb-increment-beanshell.jmx
Starting the test @ Mon May 13 23:58:50 MSK 2013 (1368475130845)
Waiting for possible shutdown message on port 4445
#0 Threads: 1/4 Samples: 1 Latency: 0 Resp.Time: 264 Errors: 0
#1 Threads: 3/4 Samples: 381 Latency: 0 Resp.Time: 2 Errors: 0
#2 Threads: 4/4 Samples: 1339 Latency: 0 Resp.Time: 2 Errors: 0
#3 Threads: 4/4 Samples: 1493 Latency: 0 Resp.Time: 2 Errors: 0
#4 Threads: 4/4 Samples: 2062 Latency: 0 Resp.Time: 1 Errors: 0
#5 Threads: 4/4 Samples: 3104 Latency: 0 Resp.Time: 1 Errors: 0
#6 Threads: 4/4 Samples: 7796 Latency: 0 Resp.Time: 0 Errors: 0
#7 Threads: 4/4 Samples: 12378 Latency: 0 Resp.Time: 0 Errors: 0
#8 Threads: 4/4 Samples: 15405 Latency: 0 Resp.Time: 0 Errors: 0
#9 Threads: 4/4 Samples: 22729 Latency: 0 Resp.Time: 0 Errors: 0
#10 Threads: 4/4 Samples: 23044 Latency: 0 Resp.Time: 0 Errors:
0
#11 Threads: 4/4 Samples: 22872 Latency: 0 Resp.Time: 0 Errors:
0
#12 Threads: 4/4 Samples: 22447 Latency: 0 Resp.Time: 0 Errors:
0
#13 Threads: 4/4 Samples: 22509 Latency: 0 Resp.Time: 0 Errors:
0
#14 Threads: 4/4 Samples: 22839 Latency: 0 Resp.Time: 0 Errors:
0
#15 Threads: 4/4 Samples: 23165 Latency: 0 Resp.Time: 0 Errors:
0
#16 Threads: 4/4 Samples: 22679 Latency: 0 Resp.Time: 0 Errors:
0
#17 Threads: 4/4 Samples: 22851 Latency: 0 Resp.Time: 0 Errors:
0
#18 Threads: 4/4 Samples: 22849 Latency: 0 Resp.Time: 0 Errors:
0
#19 Threads: 4/4 Samples: 22686 Latency: 0 Resp.Time: 0 Errors:
0
#20 Threads: 4/4 Samples: 22295 Latency: 0 Resp.Time: 0 Errors:
0
#21 Threads: 4/4 Samples: 18992 Latency: 0 Resp.Time: 0 Errors:
0
And mongostat:
insert query update delete getmore command flushes mapped vsize res faults
locked db idx miss % qr|qw ar|aw netIn netOut conn time
*0 *0 6571 *0 0 1|0 0 160m 339m 59m 0
test:15.8% 0 0|0 0|0 532k 2k 5 00:01:54
*0 *0 11211 *0 0 1|0 0 160m 339m 59m 0
test:19.7% 0 0|0 0|0 908k 2k 5 00:01:55
*0 *0 21182 *0 0 1|0 0 160m 339m 59m 0
test:32.0% 0 0|0 0|0 1m 2k 5 00:01:56
*0 *0 22699 *0 0 1|0 0 160m 339m 59m 0
test:34.9% 0 0|0 0|1 1m 2k 5 00:01:57
*0 *0 21367 *0 0 1|0 0 160m 339m 59m 0
test:33.4% 0 1|0 0|0 1m 2k 5 00:01:58
*0 *0 21169 *0 0 1|0 0 160m 339m 59m 0
test:32.7% 0 0|0 0|1 1m 2k 5 00:01:59
*0 *0 19775 *0 0 1|0 0 160m 339m 59m 0
test:31.2% 0 0|0 0|0 1m 2k 5 00:02:00
*0 *0 23328 *0 0 1|0 0 160m 339m 59m 0
test:35.8% 0 0|0 0|0 1m 2k 5 00:02:01
*0 *0 21248 *0 0 1|0 0 160m 339m 59m 0
test:32.9% 0 1|0 0|0 1m 2k 5 00:02:02
*0 *0 23005 *0 0 1|0 0 160m 339m 59m 0
test:35.5% 0 2|0 0|0 1m 2k 5 00:02:03
insert query update delete getmore command flushes mapped vsize res faults
locked db idx miss % qr|qw ar|aw netIn netOut conn time
*0 *0 23249 *0 0 1|0 0 160m 339m 59m 0
test:35.7% 0 1|0 0|1 1m 2k 5 00:02:04
*0 *0 23555 *0 0 1|0 0 160m 339m 59m 0
test:36.3% 0 0|0 0|0 1m 2k 5 00:02:05
*0 *0 23589 *0 0 1|0 0 160m 339m 59m 0
test:36.0% 0 1|0 0|1 1m 2k 5 00:02:06
*0 *0 22073 *0 0 1|0 0 160m 339m 59m 0
test:34.0% 0 1|0 0|1 1m 2k 5 00:02:07
*0 *0 22554 *0 0 1|0 0 160m 339m 59m 0
test:34.7% 0 0|0 0|1 1m 2k 5 00:02:08
*0 *0 20692 *0 0 1|0 0 160m 339m 59m 0
test:32.5% 0 0|0 0|1 1m 2k 5 00:02:09
*0 *0 20153 *0 0 1|0 0 160m 339m 59m 0
test:31.5% 0 0|0 0|1 1m 2k 5 00:02:10
*0 *0 19480 *0 0 1|0 0 160m 339m 59m 0
test:30.7% 0 0|0 0|0 1m 2k 5 00:02:11
*0 *0 21118 *0 0 1|0 0 160m 339m 59m 0
test:33.0% 0 0|0 0|1 1m 2k 5 00:02:12
*0 *0 20639 *0 0 1|0 0 160m 339m 59m 0
test:32.2% 0 0|0 0|0 1m 2k 5 00:02:13
I just use native-method instead very poor db.eval.
Soo, I can't offer good solution, but with this we need to do something.
In fact, i have 60X boost. And now my test valid, it shows the reality of life
--
You are receiving this mail because:
You are the assignee for the bug.
