Bug 54960

Summary: MongoDB Protocol. Slow performance of MongoDB Sampler due to eval function usage
Product: JMeter - Now in Github Reporter: Mikhail Epikhin <epikhinm>
Component: MainAssignee: JMeter issues mailing list <issues>
Status: RESOLVED DUPLICATE    
Severity: major CC: epikhinm, janpaulettles, p.mouawad, philippe.mouawad
Priority: P2    
Version: Nightly (Please specify date)   
Target Milestone: ---   
Hardware: All   
OS: All   
Attachments: testplan with MongoDB samplers
Testplan with beanshell mongodb samplers
insert/find/findOne samplers for mongodb

Description Mikhail Epikhin 2013-05-13 20:08:41 UTC 
Created attachment 30278 [details]
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: "zloy@spamer.com", cnt:0 } )
> db.test.find();
{ "_id" : ObjectId("518d7610f646b39cb7c84fc4"), "name" : "zloy@spamer.com", "cnt" : 0 }

Check increments method:

> db.test.update( { '_id':  ObjectId("518d7610f646b39cb7c84fc4")}, { $inc : {cnt: 1}})
> db.test.find();
{ "_id" : ObjectId("518d7610f646b39cb7c84fc4"), "name" : "zloy@spamer.com", "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
Comment 1 Mikhail Epikhin 2013-05-13 20:10:17 UTC 
Created attachment 30279 [details]
Testplan with beanshell mongodb samplers
Comment 3 Jan 2013-05-14 19:41:40 UTC 
Thanks for showing interest in mongometer http://exceptionallyexceptionalexceptions.blogspot.co.uk/2013/01/mongometer-v20.html which I donated to the project a few months back.

This 'project' was initially a hack so I could quick and consistently compare the _relative_ performance of multiple mongodb scripts that were attempting to achieve the same outcome.  It was never about the performance of the plugin itself, the plugin was the vehicle to compare scripts.

I'm more than happy for changes to be made that will improve the usability of the plugin - I'd suggest that the jmeter project owners moderate the changes to the code as they see fit; I'm not precious about it in any way.

You can also access the original source on github https://github.com/JanPaulEttles/mongometer

With regards to the return prior to the finally clause; what's your issue? The finally clause will always be called prior to the return.
Comment 4 Mikhail Epikhin 2013-05-14 20:04:54 UTC 
Okey, Jan, do you understand, the all of people, who need test mongodb with this plugin have  incorrect and not valid results? This is major reason to not include this into JMeter 2.10 or talk about performance testing mongodb for more simple methods like find/update/delete and anything else. And a lot of people didn't know about it. Please, warning your audience of users.


>>With regards to the return prior to the finally clause; what's your issue? The finally clause will always be called prior to the return.

Thank you, I did not know this
Comment 5 Philippe Mouawad 2013-06-11 21:15:19 UTC 
Thanks Mikhail for analysis.
Based on your analysis and further investigation, I propose to mark this code as ALPHA for now if we decide to release a version.

Maybe we should just keep MongoDB Source Config and let users use Beanshell or JSR223 (Groovy) code to do what the want with it as it can be hard to express through GUI what the API can do.
Comment 6 Mikhail Epikhin 2013-06-12 07:53:02 UTC 
I released three samplers for MongoDB with support this into core for operations: insert, find and findOne.

All this samplers give a json, convert to bson and works with mongodb fine on high throughput. For exmaple, insert works cool on 20krps throughput.

But, i have a problem. In json's objects a haven't support operators. Like $inc, $gt, and other. It's a big problem.

We can include simple samplers insert/find/findOne if you want. 

Source code: https://github.com/sch1z0phren1a/ApacheJMeter-mongodb-extensions/tree/master/src/main/java/me

Example testplan in attachment:)
Comment 7 Mikhail Epikhin 2013-06-12 07:54:15 UTC 
Created attachment 30427 [details]
insert/find/findOne samplers for mongodb
Comment 8 Philippe Mouawad 2013-06-15 19:03:13 UTC 
Hello Mikhail,
Thanks for feedback, could you attach them as a patch ?

I vote for their inclusion but waiting for other commiters opinion.
Comment 9 Jan 2013-06-16 12:45:33 UTC 
Good luck with this approach.  Apart from violating the DRY principle, this approach is rather messy architecturally.  Are you planning on having a separate sampler for every API call?  

The original intention for mongometer was to enable a scratch pad, an area where you were not bound to any predifined interfaces, an area where you can experiment with your mongo scripts to compare their performance in a relative manner.  What this, per sampler approach does it to limit the user to the defined samplers.

Look, I don't really care what you guys do with mongometer, I've donated it, I'm not looking for any credit and I'm not looking to support anything; you guys asked for it, so I gave it to you.

The last thing I'd add on this is, you'd be better off keeping the free text area/scratch pad area, sticking to a single sampler and creating a script-to-java layer.  You don't open a separate mongo shell for each type of query, so why should you have to with jmeter?  The script to java mapping layer not only allows you to adhere to the DRY principle, it also allows for better unit test coverage, and reduces the number of separate samplers that have to be written and maintained.

My 2p.
Comment 10 Philippe Mouawad 2013-06-16 13:04:05 UTC 
Hello Jean-Paul,
Thanks for your comment.
We are still investigating on the best approach so your contribution is an interesting one. 
What is sure is that we need to have an efficient sampler and eval is clearly not recommended by MongoDB even if it clearly solved this issue.

As you can see for now we keep the Source element and will see how to have the best from PERFORMANCE and usability.
Comment 11 Mikhail Epikhin 2013-06-17 08:02:38 UTC 
to Jean-Paul,
>>Good luck with this approach.  Apart from violating the DRY principle, this approach is rather messy architecturally.  Are you planning on having a separate sampler for every API call?  

I just wrote this samplers for my coworkers. They want performance testing simple operations like insert and find. I not created it for apache jmeter and anything opensource project. Just for me, just for my coworkers. I understanding DRY principle, and as you, i want to create simple and good architecture.

>>The original intention for mongometer was to enable a scratch pad, an area where you were not bound to any predifined interfaces, an area where you can experiment with your mongo scripts to compare their performance in a relative manner.  What this, per sampler approach does it to limit the user to the defined samplers

Okey, it's very good idea and MongoDB Java Driver have this eval-call, but it's very slow. And with this method you lock db on throughput ~500rps. What if you script have better performance? How you test it?

to Philippe,
>>Thanks for feedback, could you attach them as a patch ?

>>I vote for their inclusion but waiting for other commiters opinion.

It's good idea, but this samplers have a very slow functionality. I think, we can create samper with scripting text area (BeanShell/JSR223). In text area we can describe BSON-object or query for database.
It would be more functionality, but something difficult for users.

I can opensource it, but i agree with Jean-Paul. We need more functionality and simplify archetecture:)
Comment 12 Philippe Mouawad 2013-09-09 20:07:46 UTC 
Fixed by introduction of MongoDBHolder and documentation of this limitation, ie only use for functional testing.

*** This bug has been marked as a duplicate of bug 54584 ***
Comment 13 The ASF infrastructure team 2022-09-24 20:37:53 UTC 
This issue has been migrated to GitHub: https://github.com/apache/jmeter/issues/3122