[JAVA-3077] Java driver upgrade causing slowness to some calls Created: 08/Nov/18 Updated: 11/Sep/19 Resolved: 12/Nov/18 |
|
| Status: | Closed |
| Project: | Java Driver |
| Component/s: | Performance, Query Operations |
| Affects Version/s: | 3.4.2 |
| Fix Version/s: | None |
| Type: | Task | Priority: | Major - P3 |
| Reporter: | Manan Shah | Assignee: | Unassigned |
| Resolution: | Duplicate | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||||||||||
| Description |
|
We are in process of upgrading java driver from version 2.14 to 3.4.2. The MongoDB server ver is at 3.2.19 and the goal is to upgrade server version to 3.4 once driver has been successfully upgraded. We are experiencing slowness to some calls on the new driver interacting with server version 3.2. Although I won't be able to link the app code, here's some comparison details between old and new driver. These are all findAll() queries.
We added more timing information around different calls and compared between the Old and new driver. Extracting some info here. Old Driver:
New Driver:
Looking at that data, we noticed:
Looking for insight if you're aware of any bug in the new driver version that could possibly cause this behavior? Any help would be great for us to proceed with upgrading our mongoDB server versions across the board. |
| Comments |
| Comment by bfink13 [ 12/Nov/18 ] | ||||||||||||||||
|
Thanks Ross - I also just found | ||||||||||||||||
| Comment by Ross Lawley [ 12/Nov/18 ] | ||||||||||||||||
|
Hi bfink13, My apologies, I was incorrect, it is lazy like in 3.x - so hasNext() will cause the first call to the database to get the initial batch. There are two main differences between the driver versions that we believe account for the speed difference: 1) The differences between the wire protocol used between the versions and how MongoDB handles those paths: OP_QUERY v's OP_COMMAND. There is another ticket open for checking / analyzing the performance differences between the driver versions: Ross | ||||||||||||||||
| Comment by bfink13 [ 09/Nov/18 ] | ||||||||||||||||
|
Hey Ross, I appreciate the quick response. (edit: apparently I can't tag people) The reason we're going to 3.4.2 is because we got about 80% done with it over a year ago but had to put it on pause and now are finally picking it back up again. We'll be going to 3.8 and beyond soon Here's a snippet of the code in question:
You can see example values of "queryObj" in the ticket description. When you say "with 2.x the initial results are populated in the constructor", can you elaborate? Looking at the DBCursor implementation in 2.14.3, it looks like it only sets fields on the DBCursor object and doesn't perform any other work. Regardless, we'll wrap some timing around the collection.find() call and see if there is any performance difference there. Let me know if you need more info. | ||||||||||||||||
| Comment by Ross Lawley [ 09/Nov/18 ] | ||||||||||||||||
|
Hi manan@indeed.com & bfink13, Thanks for the ticket, out of interest why upgrade to driver version 3.4.2? Just to let you know the latest 3.4.x version is 3.4.3 and the latest Java driver release is the 3.9.0. Could you provide some example code so that the tests can be replicated?
This is surprising as both issue a count command to the database. Its unclear as what is the cause of the extra time given the command listener reports the command took 1ms. There is some post processing of the result from the server but that shouldn't account for 98ms. I'd expect the cost of the post processing to be consistent. The test code may provide more insight to cause of the pause - it is possible that the call coincided with garbage collection.
There is a slight difference between the driver versions as to when the initial batch of results from the server is requested. With 2.x the initial results are populated in the constructor, in the 3.x they are populated in the first hasNext() call. The timing would need to include the creation of the DBCursor and the first call to DBCursor#hasNext to reflect the differences between the two driver versions.
After the driver has been constructed in 2.x or the first hasNext() call in 3.x the initial batch of results are available - so calls to next() should have similar / the same performance. I hope that provides some insight. Ross | ||||||||||||||||
| Comment by bfink13 [ 08/Nov/18 ] | ||||||||||||||||
|
I'm a coworker of Manan's. If it wasn't already clear, the ThreadLocalCommandListener logs shown above are emitted from a simple implementation of the CommandListener interface. In the "new driver" example, you can see that count() took only 1ms from the driver's perspective, but the wrapped DBCursor#size call took 99ms. |