[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: |
|
| 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 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 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. |
| 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. |
| 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, |
| 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, |
| 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, |
| 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, |
| Comment by Jean-Philippe Caruana [ 10/Jun/15 ] |
|
SECONDARY> db.version() |