[SERVER-10603] Absurd query times in log Created: 22/Aug/13  Updated: 10/Dec/14  Resolved: 24/Aug/13

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 2.2.2
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Roy Smith Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Linux log.songza.com 3.2.0-34-virtual #53-Ubuntu SMP Thu Nov 15 11:08:40 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux


Issue Links:
Duplicate
duplicates SERVER-4740 Use monotonic clock sources for Timer Closed
Operating System: Linux
Participants:

 Description   

This looks like a regression of SERVER-2682. We're seeing some queries in the mongo log reporting absurd query times. They all appear to be 1271310xxx ms.

2013-08-22T01:56:31+00:00 db1c.songza.com mongodb: Thu Aug 22 01:56:29 [conn159116] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914746583131357226) }

} cursorid:2398167976845590873 ntoreturn:0 keyUpdates:0 locks(micros) r:194 nreturned:1 reslen:2030 1271310198ms
2013-08-22T01:56:31+00:00 db1c.songza.com mongodb: Thu Aug 22 01:56:29 [conn158753] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914746265303777379) }

} cursorid:1639945840662945807 ntoreturn:0 keyUpdates:0 locks(micros) r:314 nreturned:1 reslen:2030 1271310192ms
2013-08-22T01:56:31+00:00 db1c.songza.com mongodb: Thu Aug 22 01:56:29 [conn159117] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914746583131357227) }

} cursorid:4140665680898376041 ntoreturn:0 keyUpdates:0 locks(micros) r:491 nreturned:1 reslen:37 1271310190ms
2013-08-22T01:56:31+00:00 db1c.songza.com mongodb: Thu Aug 22 01:56:29 [conn158754] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914746265303777380) }

} cursorid:5305976336498040876 ntoreturn:0 keyUpdates:0 locks(micros) r:610 nreturned:1 reslen:37 1271310191ms
2013-08-22T02:40:17+00:00 db1c.songza.com mongodb: Thu Aug 22 02:40:10 [conn162856] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914766894031699993) }

} cursorid:585520490347587676 ntoreturn:0 keyUpdates:0 numYields: 1 locks(micros) r:199 nreturned:1 reslen:37 1271310318ms
2013-08-22T03:22:13+00:00 db1c.songza.com mongodb: Thu Aug 22 03:22:11 [conn162854] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914766894031699992) }

} cursorid:3852382124466333776 ntoreturn:0 keyUpdates:0 locks(micros) r:32 nreturned:1 reslen:162 1271310129ms
2013-08-22T03:22:13+00:00 db1c.songza.com mongodb: Thu Aug 22 03:22:11 [conn162853] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914766894031699992) }

} cursorid:6409769810449754192 ntoreturn:0 keyUpdates:0 locks(micros) r:132 nreturned:2 reslen:2583 1271310133ms
2013-08-22T03:22:13+00:00 db1c.songza.com mongodb: Thu Aug 22 03:22:11 [conn162855] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914766894031699993) }

} cursorid:1422189998033168468 ntoreturn:0 keyUpdates:0 locks(micros) r:326 nreturned:2 reslen:54 1271310137ms
2013-08-22T03:22:13+00:00 db1c.songza.com mongodb: Thu Aug 22 03:22:11 [conn162394] query songza.stations query: { station_id:

{ $in: [ 1399681, 1399685, 764225, 1395850, 1472493, 1485714, 1397907, 1389339, 1485084, 1396895, 1396896, 1396902, 1409578, 1396011, 1489325, 1398965, 1399098, 1393994, 1393726, 1486176, 1402818, 1524419, 1012165, 1535430, 1399111, 1400394, 1382736, 1391062, 1383003, 1410012, 1597406, 1163360, 1386723, 1396068, 1530476, 1401453, 1709679, 1408222, 1527681, 1401460, 1709818 ] }

} ntoreturn:0 ntoskip:0 nscanned:80 keyUpdates:0 locks(micros) r:18446743880112 nreturned:41 reslen:2567 1271310126ms
2013-08-22T03:42:39+00:00 db1d.songza.com mongodb: Thu Aug 22 03:42:31 [conn149161] query songza.songs query:

{ song_id: 18332448 }

ntoreturn:2 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:18446743882009 nreturned:1 reslen:296 1271310127ms
2013-08-22T04:01:49+00:00 db1c.songza.com mongodb: Thu Aug 22 04:01:40 [conn165148] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:3086258180470172342 ntoreturn:0 keyUpdates:0 locks(micros) r:101 nreturned:2 reslen:616 1271310171ms
2013-08-22T04:39:54+00:00 db1c.songza.com mongodb: Thu Aug 22 04:39:46 [conn165148] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:3086258180470172342 ntoreturn:0 keyUpdates:0 locks(micros) r:32 nreturned:4 reslen:1122 1271310155ms
2013-08-22T04:39:54+00:00 db1c.songza.com mongodb: Thu Aug 22 04:39:46 [conn166287] query songza.situations query: { $or: [ { active: true, search_only: false, time_periods: { $elemMatch:

{ day: 3, period: 4 }

}, site: "songza" },

{ active: true, search_only: false, time_periods: null, site: "songza" }

] } ntoreturn:0 ntoskip:0 nscanned:127 keyUpdates:0 locks(micros) r:18446743901121 nreturned:13 reslen:21239 1271310147ms
2013-08-22T04:39:54+00:00 db1c.songza.com mongodb: Thu Aug 22 04:39:46 [conn165151] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:4850560011850574528 ntoreturn:0 keyUpdates:0 locks(micros) r:158 nreturned:4 reslen:88 1271310157ms
2013-08-22T04:39:54+00:00 db1c.songza.com mongodb: Thu Aug 22 04:39:46 [conn165147] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:2696542481642777267 ntoreturn:0 keyUpdates:0 numYields: 1 locks(micros) r:456 nreturned:1 reslen:157 1271310317ms
2013-08-22T05:15:29+00:00 db1c.songza.com mongodb: Thu Aug 22 05:15:22 [conn165148] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:3086258180470172342 ntoreturn:0 keyUpdates:0 locks(micros) r:31 nreturned:1 reslen:1835 1271310176ms
2013-08-22T05:15:29+00:00 db1c.songza.com mongodb: Thu Aug 22 05:15:22 [conn165151] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:4850560011850574528 ntoreturn:0 keyUpdates:0 locks(micros) r:31 nreturned:1 reslen:37 1271310176ms
2013-08-22T05:15:29+00:00 db1c.songza.com mongodb: Thu Aug 22 05:15:22 [conn165147] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:2696542481642777267 ntoreturn:0 keyUpdates:0 locks(micros) r:153 nreturned:1 reslen:1835 1271310176ms
2013-08-22T05:15:29+00:00 db1c.songza.com mongodb: Thu Aug 22 05:15:22 [conn165150] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:7175745758469122750 ntoreturn:0 keyUpdates:0 locks(micros) r:125 nreturned:2 reslen:54 1271310182ms
2013-08-22T05:23:20+00:00 db1c.songza.com mongodb: Thu Aug 22 05:23:19 [conn164631] query songza.stations query:

{ station_id: 1403209 }

ntoreturn:2 keyUpdates:0 locks(micros) r:101 nreturned:1 reslen:1018 1271310135ms
2013-08-22T05:23:20+00:00 db1c.songza.com mongodb: Thu Aug 22 05:23:19 [conn165147] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:2696542481642777267 ntoreturn:0 keyUpdates:0 locks(micros) r:44 nreturned:1 reslen:157 1271310141ms
2013-08-22T05:23:20+00:00 db1c.songza.com mongodb: Thu Aug 22 05:23:19 [conn165151] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:4850560011850574528 ntoreturn:0 keyUpdates:0 locks(micros) r:36 nreturned:1 reslen:37 1271310140ms
2013-08-22T05:23:20+00:00 db1c.songza.com mongodb: Thu Aug 22 05:23:19 [conn165148] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:3086258180470172342 ntoreturn:0 keyUpdates:0 locks(micros) r:42 nreturned:1 reslen:157 1271310145ms
2013-08-22T05:23:20+00:00 db1c.songza.com mongodb: Thu Aug 22 05:23:19 [conn165150] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:7175745758469122750 ntoreturn:0 keyUpdates:0 locks(micros) r:61 nreturned:1 reslen:37 1271310144ms
2013-08-22T06:00:15+00:00 db1c.songza.com mongodb: Thu Aug 22 06:00:12 [conn165148] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:3086258180470172342 ntoreturn:0 keyUpdates:0 locks(micros) r:30 nreturned:1 reslen:463 1271310200ms
2013-08-22T06:00:15+00:00 db1c.songza.com mongodb: Thu Aug 22 06:00:12 [conn165147] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:2696542481642777267 ntoreturn:0 keyUpdates:0 locks(micros) r:30 nreturned:1 reslen:463 1271310199ms
2013-08-22T06:00:15+00:00 db1c.songza.com mongodb: Thu Aug 22 06:00:12 [conn165151] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:4850560011850574528 ntoreturn:0 keyUpdates:0 locks(micros) r:36 nreturned:1 reslen:37 1271310198ms
2013-08-22T06:03:15+00:00 db1c.songza.com mongodb: Thu Aug 22 06:03:12 [conn165147] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:2696542481642777267 ntoreturn:0 keyUpdates:0 locks(micros) r:115 nreturned:1 reslen:230 1271310227ms
2013-08-22T06:03:15+00:00 db1c.songza.com mongodb: Thu Aug 22 06:03:12 [conn165151] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:4850560011850574528 ntoreturn:0 keyUpdates:0 locks(micros) r:129 nreturned:1 reslen:37 1271310221ms
2013-08-22T06:03:15+00:00 db1c.songza.com mongodb: Thu Aug 22 06:03:12 [conn165148] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:3086258180470172342 ntoreturn:0 keyUpdates:0 locks(micros) r:235 nreturned:1 reslen:230 1271310228ms
2013-08-22T06:42:10+00:00 db1c.songza.com mongodb: Thu Aug 22 06:42:04 [conn165150] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:7175745758469122750 ntoreturn:0 keyUpdates:0 locks(micros) r:84 nreturned:2 reslen:54 1271310188ms
2013-08-22T06:42:10+00:00 db1c.songza.com mongodb: Thu Aug 22 06:42:04 [conn165151] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:4850560011850574528 ntoreturn:0 keyUpdates:0 locks(micros) r:46 nreturned:3 reslen:71 1271310197ms
2013-08-22T06:42:10+00:00 db1c.songza.com mongodb: Thu Aug 22 06:42:04 [conn165148] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:3086258180470172342 ntoreturn:0 keyUpdates:0 locks(micros) r:32 nreturned:2 reslen:623 1271310188ms
2013-08-22T06:42:10+00:00 db1c.songza.com mongodb: Thu Aug 22 06:42:04 [conn165147] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:2696542481642777267 ntoreturn:0 keyUpdates:0 locks(micros) r:56 nreturned:1 reslen:171 1271310188ms
2013-08-22T06:56:06+00:00 db1b.songza.com mongodb: ...", query: { date:

{ $gte: new Date(1377043200000), $lt: new Date(1377129600000) }

, ctx.dev: "iphone" }, out:

{ inline: 1 }

} ntoreturn:1 keyUpdates:0 numYields: 37333 locks(micros) r:1730774754 reslen:9082859 3102077ms
2013-08-22T07:23:10+00:00 db1c.songza.com mongodb: Thu Aug 22 07:23:05 [conn164810] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:6408388806668535195 ntoreturn:0 keyUpdates:0 locks(micros) r:42 nreturned:1 reslen:37 1271310147ms
2013-08-22T07:23:10+00:00 db1c.songza.com mongodb: Thu Aug 22 07:23:05 [conn165148] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:3086258180470172342 ntoreturn:0 keyUpdates:0 locks(micros) r:471 nreturned:1 reslen:16554 1271310179ms
2013-08-22T07:23:10+00:00 db1c.songza.com mongodb: Thu Aug 22 07:23:05 [conn165151] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:4850560011850574528 ntoreturn:0 keyUpdates:0 locks(micros) r:531 nreturned:1 reslen:37 1271310176ms
2013-08-22T07:23:10+00:00 db1c.songza.com mongodb: Thu Aug 22 07:23:05 [conn165147] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813276) }

} cursorid:2696542481642777267 ntoreturn:0 keyUpdates:0 locks(micros) r:628 nreturned:1 reslen:16554 1271310178ms
2013-08-22T07:23:10+00:00 db1c.songza.com mongodb: Thu Aug 22 07:23:05 [conn165150] getmore local.oplog.rs query: { ts:

{ $gte: new Date(5914780405998813277) }

} cursorid:7175745758469122750 ntoreturn:0 keyUpdates:0 locks(micros) r:752 nreturned:1 reslen:37 1271310179ms



 Comments   
Comment by Daniel Pasette (Inactive) [ 24/Aug/13 ]

This is a result of SERVER-4740.

Comment by Roy Smith [ 22/Aug/13 ]

Note: we're running a mix of 2.2.2, 2.2.3 and 2.2.5 servers.

Generated at Thu Feb 08 03:23:35 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.