[JAVA-1854] Driver tries to kill a cursor twice when limit is reached on the first batch Created: 10/Jun/15  Updated: 13/Apr/16  Resolved: 10/Jun/15

Status: Closed
Project: Java Driver
Component/s: Query Operations
Affects Version/s: 3.0.2
Fix Version/s: 3.0.3

Type: Bug Priority: Minor - P4
Reporter: Jean-Philippe Caruana Assignee: Jeffrey Yemin
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

linux Ubuntu 14.04.2 LTS


Attachments: File 2.13.0.log     File 3.0.2.log     Text File killCursor.txt    

 Description   

We have updated our java mongo driver from 2.13.0 to 3.0.2, and since then, we have tons of "killcursors: found 0 of 1" in logs on our secondary servers

Before the change, we had around 500 logs per hours of it :

$ sudo grep 2015-06-09T14 /var/log/mongodb/mongodb.log | grep -c killcursors
511

since the change, we have around 150 times more of this log :

sudo grep 2015-06-09T18 /var/log/mongodb/mongodb.log | grep -c killcursors
78043

After the rollback, these logs disapeared



 Comments   
Comment by Jeffrey Yemin [ 16/Jul/15 ]

Fix is now available in the 3.0.3 release.

Comment by Jean-Philippe Caruana [ 11/Jun/15 ]

Hi,

kill cursors doesn't seem to be that free:

2015-06-11T10:48:28.805+0200 I QUERY [conn471194] killcursors keyUpdates:0 writeConflicts:0 numYields:0 locks:{ Global: { acquireCount:

{ r: 1 }

}, Database: { acquireCount:

{ r: 1 }

}, Collection: { acquireCount:

{ r: 1 }

} } 769ms

Comment by Githook User [ 10/Jun/15 ]

Author:

{u'username': u'jyemin', u'name': u'Jeff Yemin', u'email': u'jeff.yemin@10gen.com'}

Message: Avoid redundant killing of the cursor by setting a flag indicating that it's already been killed.

JAVA-1854
Branch: 3.0.x
https://github.com/mongodb/mongo-java-driver/commit/1cb4b30368af4ca12a1a2e6e86f031a4cb82ebca

Comment by Githook User [ 10/Jun/15 ]

Author:

{u'username': u'jyemin', u'name': u'Jeff Yemin', u'email': u'jeff.yemin@10gen.com'}

Message: Avoid redundant killing of the cursor by setting a flag indicating that it's already been killed.

JAVA-1854
Branch: master
https://github.com/mongodb/mongo-java-driver/commit/e11b52d1691e490146446d2a1de8a883165558fa

Comment by Jeffrey Yemin [ 10/Jun/15 ]

OK, thanks. I'm going to edit the description to reflect what we know for sure, to avoid any confusion for anyone else looking at this issue.

Regards,
Jeff

Comment by Jean-Philippe Caruana [ 10/Jun/15 ]

You might be right: a lot of things happened at this time in production.

What we experienced is a much slower read rate, but I have nothing serious to prove this came from the new driver version. The best I can say is that we'll try the new driver version and see if we still have performance issues.

Comment by Jeffrey Yemin [ 10/Jun/15 ]

I have a strong feeling that this bug is not the cause of the performance degradation that you experienced, as a no-op kill cursor should not be a particularly expensive operation. Can you describe the symptoms of that degradation in some more detail?

Regards,
Jeff

Comment by Jean-Philippe Caruana [ 10/Jun/15 ]

Thanks Jeff

Comment by Jeffrey Yemin [ 10/Jun/15 ]

Hi Jean-Phillipe,

I found a bug that could be responsible for the increase in log messages that you have experienced. The bug would show up on queries where a limit is being set. I'll get a fix pushed out to a SNAPSHOT build as soon as possible.

Regards,
Jeff

Comment by Jean-Philippe Caruana [ 10/Jun/15 ]

Hi Jeff,

I attached server logs as you requested.

I sadly could not reproduce this in a non production env (it wouldn't have made it to production otherwise): logs look the same as in the 2.13.0.log attached file.

Regards

Comment by Jeffrey Yemin [ 10/Jun/15 ]

Hi Jean-Phillipe,

Can you attach the relevant sever logs please? One representative sample from when you were running with 2.13.0, and one with 3.0.2.

Are you able to reproduce this in a non-production environment? If so, we may be able to glean some more information by turning up the log level in the 3.0 driver, as all OP_KILL_CURSOR messages are logged at debug by a logger named "org.mongodb.driver.protocol.killcursor".

Regards,
Jeff

Comment by Jean-Philippe Caruana [ 10/Jun/15 ]

SECONDARY> db.version()
3.0.2

Generated at Thu Feb 08 08:55:40 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.