noTimeOut cursor option: will the cursor really last forever?
137 views
Skip to first unread message
Shi Shei
Apr 16, 2012, 12:47:37 PM4/16/12
to mongodb-user
What happens when an application creates a noTimeOut cursor without
ever closing it?
Does mongo terminate the cursor/query after a certain time (perhaps
even unintentionally)?
After having logged slow queries (>3 sec) I observed very few queries
which took about 1271303044 ms (+- 5000 ms).
Could it be that these queries were executed with a noTimeOut option,
so they would live "forever" (max ~1271303044 ms) on the mongo server?
Could it be an (unintentional) overflow of some mongo counter which
results in termination after around 1271303044 ms?
ever closing it?
Does mongo terminate the cursor/query after a certain time (perhaps
even unintentionally)?
After having logged slow queries (>3 sec) I observed very few queries
which took about 1271303044 ms (+- 5000 ms).
Could it be that these queries were executed with a noTimeOut option,
so they would live "forever" (max ~1271303044 ms) on the mongo server?
Could it be an (unintentional) overflow of some mongo counter which
results in termination after around 1271303044 ms?
Randolph Tan
Apr 16, 2012, 4:18:53 PM4/16/12
to mongod...@googlegroups.com
No, the server will never close the cursor if noTimeOut is set (there is a bug in mongos that could make it timeout, SERVER-5624). Accumulating many unused cursors is generally a bad idea since it is a waste of memory and the cursor cleanup thread will iterate over all unclosed cursors (and the more cursors you have, the slower it will get).
Shi Shei
Apr 16, 2012, 5:44:43 PM4/16/12
to mongodb-user
In the last 10 days of logging slow queries, I got only round about 20
queries of 1271303044 ms (+- 5000 ms) execution time.
Even if these few queries are not (yet) a problem for me, I'm
wondering HOW these queries could last for so long and WHY they were
all terminated after nearly the same duration.
Some of these queries query only _id, which would normally take only a
few milliseconds. What could explain these long and nearly identical
execution times?
I'm using the noTimeOut option to circumvent SERVER-4680 issue. So, if
SERVER-5624 is really true, I don't understand why my workaround for
SERVER-4680 did the job a the time.
queries of 1271303044 ms (+- 5000 ms) execution time.
Even if these few queries are not (yet) a problem for me, I'm
wondering HOW these queries could last for so long and WHY they were
all terminated after nearly the same duration.
Some of these queries query only _id, which would normally take only a
few milliseconds. What could explain these long and nearly identical
execution times?
I'm using the noTimeOut option to circumvent SERVER-4680 issue. So, if
SERVER-5624 is really true, I don't understand why my workaround for
SERVER-4680 did the job a the time.
Randolph Tan
Apr 16, 2012, 6:06:27 PM4/16/12
to mongod...@googlegroups.com
Do you have these machines in MMS? And do you know the approximate time for the slow queries?
Shi Shei
Apr 17, 2012, 4:45:37 AM4/17/12
to mongodb-user
Yes, they are all in MMS. The group name is idealo.
The host name of one of the mongos is sx210:27018 which points to the
4 shards going from offerstore to offerStoreDE4.
I wrote a script to copy system.profile collections from every mongod
into one profiling collection.
I added to each document its mongod connection point to know on which
node run the query.
Here are some of these slow queries with their exact timestamps sorted
by field "millis":
connecting to: sx210:27018/offerStore
{
"_id" : ObjectId("4f86a14b559a218a4d77d715"),
"ts" : "2012-04-12T02:24:08Z",
"op" : "getmore",
"ns" : "offerStore.offer",
"query" : {
"missingSince" : null,
"shopId" : 5040
},
"cursorid" : NumberLong("8729879979467156165"),
"nreturned" : 30675,
"responseLength" : 1748495,
"millis" : 1271309663,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s117.ipx:27018"
}
{
"_id" : ObjectId("4f844705559a774c0f1f1700"),
"ts" : "2012-04-10T14:10:09Z",
"op" : "query",
"ns" : "offerStore.offer",
"query" : {
"_id" : 858680314
},
"idhack" : true,
"responseLength" : 1393,
"millis" : 1271309469,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s132.ipx:27018"
}
{
"_id" : ObjectId("4f8446fc559a774c0f1f0693"),
"ts" : "2012-04-05T14:24:59Z",
"op" : "getmore",
"ns" : "offerStore.offer",
"query" : {
"missingSince" : null,
"shopId" : 5040
},
"cursorid" : NumberLong("1817499255547817100"),
"nreturned" : 68132,
"responseLength" : 3883544,
"millis" : 1271309097,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s143.ipx:27018"
}
{
"_id" : ObjectId("4f8446fa559a774c0f1f053d"),
"ts" : "2012-04-08T02:08:08Z",
"op" : "query",
"ns" : "offerStore.offer",
"query" : {
"missingSince" : null,
"categoryBokey" : "212795:StGQqkQ8AV45NElQbaFNfw"
},
"responseLength" : 20,
"millis" : 1271308447,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s126.ipx:27018"
}
{
"_id" : ObjectId("4f8446fb559a774c0f1f0644"),
"ts" : "2012-04-09T02:08:03Z",
"op" : "query",
"ns" : "offerStore.offer",
"query" : {
"missingSince" : null,
"categoryBokey" : "207283:07ofhAIn/kJWFuKDIlQYXQ"
},
"nscanned" : 8,
"nreturned" : 8,
"responseLength" : 514,
"millis" : 1271303702,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s131.ipx:27018"
}
{
"_id" : ObjectId("4f844701559a774c0f1f10d7"),
"ts" : "2012-04-08T02:04:02Z",
"op" : "getmore",
"ns" : "offerStore.offer",
"query" : {
"shopId" : 22307
},
"cursorid" : NumberLong("7522793855964665641"),
"nreturned" : 35053,
"responseLength" : 2303689,
"millis" : 1271303044,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s115.ipx:27018"
}
Thank you for having a look at it!
The host name of one of the mongos is sx210:27018 which points to the
4 shards going from offerstore to offerStoreDE4.
I wrote a script to copy system.profile collections from every mongod
into one profiling collection.
I added to each document its mongod connection point to know on which
node run the query.
Here are some of these slow queries with their exact timestamps sorted
by field "millis":
connecting to: sx210:27018/offerStore
{
"_id" : ObjectId("4f86a14b559a218a4d77d715"),
"ts" : "2012-04-12T02:24:08Z",
"op" : "getmore",
"ns" : "offerStore.offer",
"query" : {
"missingSince" : null,
"shopId" : 5040
},
"cursorid" : NumberLong("8729879979467156165"),
"nreturned" : 30675,
"responseLength" : 1748495,
"millis" : 1271309663,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s117.ipx:27018"
}
{
"_id" : ObjectId("4f844705559a774c0f1f1700"),
"ts" : "2012-04-10T14:10:09Z",
"op" : "query",
"ns" : "offerStore.offer",
"query" : {
"_id" : 858680314
},
"idhack" : true,
"responseLength" : 1393,
"millis" : 1271309469,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s132.ipx:27018"
}
{
"_id" : ObjectId("4f8446fc559a774c0f1f0693"),
"ts" : "2012-04-05T14:24:59Z",
"op" : "getmore",
"ns" : "offerStore.offer",
"query" : {
"missingSince" : null,
"shopId" : 5040
},
"cursorid" : NumberLong("1817499255547817100"),
"nreturned" : 68132,
"responseLength" : 3883544,
"millis" : 1271309097,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s143.ipx:27018"
}
{
"_id" : ObjectId("4f8446fa559a774c0f1f053d"),
"ts" : "2012-04-08T02:08:08Z",
"op" : "query",
"ns" : "offerStore.offer",
"query" : {
"missingSince" : null,
"categoryBokey" : "212795:StGQqkQ8AV45NElQbaFNfw"
},
"responseLength" : 20,
"millis" : 1271308447,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s126.ipx:27018"
}
{
"_id" : ObjectId("4f8446fb559a774c0f1f0644"),
"ts" : "2012-04-09T02:08:03Z",
"op" : "query",
"ns" : "offerStore.offer",
"query" : {
"missingSince" : null,
"categoryBokey" : "207283:07ofhAIn/kJWFuKDIlQYXQ"
},
"nscanned" : 8,
"nreturned" : 8,
"responseLength" : 514,
"millis" : 1271303702,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s131.ipx:27018"
}
{
"_id" : ObjectId("4f844701559a774c0f1f10d7"),
"ts" : "2012-04-08T02:04:02Z",
"op" : "getmore",
"ns" : "offerStore.offer",
"query" : {
"shopId" : 22307
},
"cursorid" : NumberLong("7522793855964665641"),
"nreturned" : 35053,
"responseLength" : 2303689,
"millis" : 1271303044,
"client" : "#.#.#.#",
"user" : "",
"mongod" : "s115.ipx:27018"
}
Thank you for having a look at it!
Randolph Tan
Apr 17, 2012, 1:55:30 PM4/17/12
to mongod...@googlegroups.com
Apart from the frequent primary <-> secondary state changes in offerStoreDE4, your mms graphs looks relatively healthy. Query on _id with index shouldn't take that long. What operating system and what is the kernel version of your setup?
Thanks!
Thanks!
Shi Shei
Apr 18, 2012, 5:28:21 AM4/18/12
to mongodb-user
This are the OS'es and kernel versions of our mongods:
s131:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
s118:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-35squeeze2)
(da...@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Fri
Sep 9 20:23:16 UTC 2011
s126:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
s120:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41squeeze2)
(da...@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Thu
Mar 22 17:26:33 UTC 2012
s127:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41squeeze2)
(da...@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Thu
Mar 22 17:26:33 UTC 2012
s209:~$ cat /proc/version
Linux version 2.6.26-2-amd64 (Debian 2.6.26-25lenny1)
(da...@debian.org) (gcc version 4.1.3 20080704 (prerelease) (Debian
4.1.2-25)) #1 SMP Thu Sep 16 15:56:38 UTC 2010
s117:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-35) (da...@debian.org)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Tue Jun 14 09:42:28 UTC
2011
s124:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41squeeze2)
(da...@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Thu
Mar 22 17:26:33 UTC 2012
s129:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-35) (da...@debian.org)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Tue Jun 14 09:42:28 UTC
2011
s115:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
s125:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
s132:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
The Lenny's will be updated to Squeeze soon to match 10gen's
production recommandations.
http://www.mongodb.org/display/DOCS/Production+Notes
Could the Lenny's be the resaon for those super long queries?
s131:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
s118:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-35squeeze2)
(da...@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Fri
Sep 9 20:23:16 UTC 2011
s126:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
s120:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41squeeze2)
(da...@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Thu
Mar 22 17:26:33 UTC 2012
s127:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41squeeze2)
(da...@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Thu
Mar 22 17:26:33 UTC 2012
s209:~$ cat /proc/version
Linux version 2.6.26-2-amd64 (Debian 2.6.26-25lenny1)
(da...@debian.org) (gcc version 4.1.3 20080704 (prerelease) (Debian
4.1.2-25)) #1 SMP Thu Sep 16 15:56:38 UTC 2010
s117:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-35) (da...@debian.org)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Tue Jun 14 09:42:28 UTC
2011
s124:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41squeeze2)
(da...@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Thu
Mar 22 17:26:33 UTC 2012
s129:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-35) (da...@debian.org)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Tue Jun 14 09:42:28 UTC
2011
s115:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
s125:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
s132:~$ cat /proc/version
Linux version 2.6.32-5-amd64 (Debian 2.6.32-41) (b...@decadent.org.uk)
(gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Mon Jan 16 16:22:28 UTC
2012
The Lenny's will be updated to Squeeze soon to match 10gen's
production recommandations.
http://www.mongodb.org/display/DOCS/Production+Notes
Could the Lenny's be the resaon for those super long queries?
Shi Shei
Apr 23, 2012, 5:26:20 AM4/23/12
to mongodb-user
Randolph, or anybody else please?
I'm profiling still these 14 days queries that I can't expalin why
they last so long.
This thread is related but not yet answered too:
http://groups.google.com/group/mongodb-user/browse_thread/thread/7378a4610f1c9bf2
It would be great to shed some light on this issue. Thank you!
> production recommandations.http://www.mongodb.org/display/DOCS/Production+Notes
I'm profiling still these 14 days queries that I can't expalin why
they last so long.
This thread is related but not yet answered too:
http://groups.google.com/group/mongodb-user/browse_thread/thread/7378a4610f1c9bf2
It would be great to shed some light on this issue. Thank you!
Barrie
May 1, 2012, 5:28:52 PM5/1/12
to mongod...@googlegroups.com
As Mathias suggested in the ticket linked above, can you please file a ticket for this in the Core Server project in Jira? It can be done at https://jira.mongodb.org. Thank you!
Shi Shei
May 2, 2012, 12:11:10 PM5/2/12
to mongodb-user
Done: https://jira.mongodb.org/browse/SERVER-5745
On May 1, 11:28 pm, Barrie <bar...@10gen.com> wrote:
> As Mathias suggested in the ticket linked above, can you please file a
> ticket for this in the Core Server project in Jira? It can be done
> athttps://jira.mongodb.org. Thank you!
> ...
>
> read more »
On May 1, 11:28 pm, Barrie <bar...@10gen.com> wrote:
> As Mathias suggested in the ticket linked above, can you please file a
> ticket for this in the Core Server project in Jira? It can be done
>
>
>
>
>
>
>
> On Monday, April 23, 2012 5:26:20 AM UTC-4, Shi Shei wrote:
>
> > Randolph, or anybody else please?
>
> > I'm profiling still these 14 days queries that I can't expalin why
> > they last so long.
>
> > This thread is related but not yet answered too:
>
> >http://groups.google.com/group/mongodb-user/browse_thread/thread/7378...
>
>
>
>
>
>
> On Monday, April 23, 2012 5:26:20 AM UTC-4, Shi Shei wrote:
>
> > Randolph, or anybody else please?
>
> > I'm profiling still these 14 days queries that I can't expalin why
> > they last so long.
>
> > This thread is related but not yet answered too:
>
>
> read more »
Reply all
Reply to author
Forward
0 new messages