Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-10603

Absurd query times in log

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Minor - P4 Minor - P4
    • None
    • Affects Version/s: 2.2.2
    • Component/s: None
    • None
    • 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
    • Linux

      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

            Assignee:
            Unassigned Unassigned
            Reporter:
            roysmith Roy Smith
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: