2018-02-28T17:50:49.252+0100 D COMMAND [conn8] run command dialo_dev.$cmd { find: "event", filter: { $where: "sleep(10)" }, maxTimeMS: 10.0, $db: "dialo_dev" }
|
2018-02-28T17:50:49.252+0100 D QUERY [js] SMScope 0x7f8efb4c9c00 registered for op 8133
|
2018-02-28T17:50:49.252+0100 D STORAGE [conn8] NamespaceUUIDCache: registered namespace dialo_dev.event with UUID c2727c1e-6b28-42f5-bc43-913029cf0d3d
|
2018-02-28T17:50:49.252+0100 D QUERY [conn8] Beginning planning...
|
=============================
|
Options = INDEX_INTERSECTION SPLIT_LIMITED_SORT CANNOT_TRIM_IXISECT
|
Canonical query:
|
ns=dialo_dev.eventTree: $where
|
code: sleep(10)
|
scope: {}
|
Sort: {}
|
Proj: {}
|
=============================
|
2018-02-28T17:50:49.252+0100 D QUERY [conn8] Index 0 is kp: { _id: 1 } unique name: '_id_' io: { v: 2, key: { _id: 1 }, name: "_id_", ns: "dialo_dev.event" }
|
2018-02-28T17:50:49.252+0100 D QUERY [conn8] Index 1 is kp: { _id.type: 1, computedData.idEvent: 1, computedData.bodyType: 1, computedData.engineLevel: 1 } name: 'event' io: { v: 2, key: { _id.type: 1, computedData.idEvent: 1, computedData.bodyType: 1, computedData.engineLevel: 1 }, name: "event", ns: "dialo_dev.event" }
|
2018-02-28T17:50:49.252+0100 D QUERY [conn8] Index 2 is kp: { _id.functionalId: 1 } name: '_id.functionalId_1' io: { v: 2, key: { _id.functionalId: 1 }, name: "_id.functionalId_1", ns: "dialo_dev.event" }
|
2018-02-28T17:50:49.252+0100 D QUERY [conn8] Index 3 is kp: { type: 1.0, computedData.idEvent: 1.0, computedData.bodyType: 1.0, computedData.engineLevel: 1.0 } name: 'type_1_computedData.idEvent_1_computedData.bodyType_1_computedData.engineLevel_1' io: { v: 2, key: { type: 1.0, computedData.idEvent: 1.0, computedData.bodyType: 1.0, computedData.engineLevel: 1.0 }, name: "type_1_computedData.idEvent_1_computedData.bodyType_1_computedData.engineLevel_1", ns: "dialo_dev.event" }
|
2018-02-28T17:50:49.252+0100 D QUERY [conn8] Rated tree:
|
$where
|
code: sleep(10)
|
scope: {}
|
2018-02-28T17:50:49.252+0100 D QUERY [conn8] Planner: outputted 0 indexed solutions.
|
2018-02-28T17:50:49.252+0100 D QUERY [js] SMScope 0x7f8f98d4a400 registered for op 8133
|
2018-02-28T17:50:49.252+0100 D QUERY [conn8] Planner: outputting a collscan:
|
COLLSCAN
|
---ns = dialo_dev.event
|
---filter = $where
|
code: sleep(10)
|
scope: {}
|
---fetched = 1
|
---sortedByDiskLoc = 0
|
---getSort = []
|
2018-02-28T17:50:49.252+0100 D QUERY [conn8] Only one plan is available; it will be run but will not be cached. query: { $where: "sleep(10)" } sort: {} projection: {}, planSummary: COLLSCAN
|
2018-02-28T17:50:49.252+0100 D STORAGE [conn8] WT begin_transaction for snapshot id 199717
|
2018-02-28T17:50:49.264+0100 D STORAGE [conn8] WT rollback_transaction for snapshot id 199717
|
2018-02-28T17:50:49.264+0100 D STORAGE [conn8] WT begin_transaction for snapshot id 199718
|
2018-02-28T17:50:49.274+0100 D STORAGE [WTJournalFlusher] flushed journal
|
2018-02-28T17:50:49.289+0100 E QUERY [conn8] Plan executor error during find command: DEAD, stats: { stage: "COLLSCAN", filter: { $where: CodeWScope( sleep(10), {}) }, nReturned: 0, executionTimeMillisEstimate: 34, works: 4, advanced: 0, needTime: 4, needYield: 0, saveState: 1, restoreState: 1, isEOF: 0, invalidates: 0, direction: "forward", docsExamined: 3 }
|
2018-02-28T17:50:49.289+0100 D QUERY [js] ImplScope 0x7f902eead640 unregistered for op 8133
|
2018-02-28T17:50:49.289+0100 D QUERY [js] ImplScope 0x7f902eead640 unregistered for op 8133
|
2018-02-28T17:50:49.289+0100 I QUERY [js] MozJS GC prologue heap stats - total: 1970175 limit: 1153433600
|
2018-02-28T17:50:49.290+0100 I QUERY [js] MozJS GC epilogue heap stats - total: 352887 limit: 1153433600
|
2018-02-28T17:50:49.290+0100 I QUERY [js] MozJS GC prologue heap stats - total: 244591 limit: 1153433600
|
2018-02-28T17:50:49.291+0100 I QUERY [js] MozJS GC epilogue heap stats - total: 61415 limit: 1153433600
|
2018-02-28T17:50:49.291+0100 D STORAGE [conn8] WT rollback_transaction for snapshot id 199718
|
2018-02-28T17:50:49.291+0100 I COMMAND [conn8] command dialo_dev.event appName: "MongoDB Shell" command: find { find: "event", filter: { $where: "sleep(10)" }, maxTimeMS: 10.0, $db: "dialo_dev" } planSummary: COLLSCAN numYields:1 reslen:159 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } protocol:op_msg 39ms
|
2018-02-28T17:50:49.293+0100 D COMMAND [conn8] run command dialo_dev.$cmd { isMaster: 1.0, forShell: 1.0, $db: "dialo_dev" }
|
2018-02-28T17:50:49.293+0100 D NETWORK [conn8] Starting server-side compression negotiation
|
2018-02-28T17:50:49.302+0100 D NETWORK [conn8] Compression negotiation not requested by client
|
2018-02-28T17:50:49.302+0100 I COMMAND [conn8] command dialo_dev.$cmd appName: "MongoDB Shell" command: isMaster { isMaster: 1.0, forShell: 1.0, $db: "dialo_dev" } numYields:0 reslen:208 locks:{} protocol:op_msg 8ms
|
2018-02-28T17:50:49.377+0100 D STORAGE [WTJournalFlusher] flushed journal
|
2018-02-28T17:50:49.481+0100 D STORAGE [WTJournalFlusher] flushed journal
|
2018-02-28T17:50:49.582+0100 D STORAGE [WTJournalFlusher] flushed journal
|
2018-02-28T17:50:49.686+0100 D STORAGE [WTJournalFlusher] flushed journal
|
2018-02-28T17:50:49.792+0100 D STORAGE [WTJournalFlusher] flushed journal
|
2018-02-28T17:50:49.796+0100 D COMMAND [conn8] run command dialo_dev.$cmd { find: "event", filter: { $where: "sleep(10)" }, maxTimeMS: 10.0, $db: "dialo_dev" }
|
2018-02-28T17:50:49.796+0100 D QUERY [js] SMScope 0x7f8f98d4a400 registered for op 8135
|
2018-02-28T17:50:49.796+0100 D STORAGE [conn8] NamespaceUUIDCache: registered namespace dialo_dev.event with UUID c2727c1e-6b28-42f5-bc43-913029cf0d3d
|
2018-02-28T17:50:49.796+0100 D QUERY [conn8] Beginning planning...
|
=============================
|
Options = INDEX_INTERSECTION SPLIT_LIMITED_SORT CANNOT_TRIM_IXISECT
|
Canonical query:
|
ns=dialo_dev.eventTree: $where
|
code: sleep(10)
|
scope: {}
|
Sort: {}
|
Proj: {}
|
=============================
|
2018-02-28T17:50:49.796+0100 D QUERY [conn8] Index 0 is kp: { _id: 1 } unique name: '_id_' io: { v: 2, key: { _id: 1 }, name: "_id_", ns: "dialo_dev.event" }
|
2018-02-28T17:50:49.796+0100 D QUERY [conn8] Index 1 is kp: { _id.type: 1, computedData.idEvent: 1, computedData.bodyType: 1, computedData.engineLevel: 1 } name: 'event' io: { v: 2, key: { _id.type: 1, computedData.idEvent: 1, computedData.bodyType: 1, computedData.engineLevel: 1 }, name: "event", ns: "dialo_dev.event" }
|
2018-02-28T17:50:49.796+0100 D QUERY [conn8] Index 2 is kp: { _id.functionalId: 1 } name: '_id.functionalId_1' io: { v: 2, key: { _id.functionalId: 1 }, name: "_id.functionalId_1", ns: "dialo_dev.event" }
|
2018-02-28T17:50:49.796+0100 D QUERY [conn8] Index 3 is kp: { type: 1.0, computedData.idEvent: 1.0, computedData.bodyType: 1.0, computedData.engineLevel: 1.0 } name: 'type_1_computedData.idEvent_1_computedData.bodyType_1_computedData.engineLevel_1' io: { v: 2, key: { type: 1.0, computedData.idEvent: 1.0, computedData.bodyType: 1.0, computedData.engineLevel: 1.0 }, name: "type_1_computedData.idEvent_1_computedData.bodyType_1_computedData.engineLevel_1", ns: "dialo_dev.event" }
|
2018-02-28T17:50:49.796+0100 D QUERY [conn8] Rated tree:
|
$where
|
code: sleep(10)
|
scope: {}
|
2018-02-28T17:50:49.796+0100 D QUERY [conn8] Planner: outputted 0 indexed solutions.
|
2018-02-28T17:50:49.843+0100 D QUERY [js] SMScope 0x7f8ed9924c00 registered for op 8135
|
2018-02-28T17:50:49.843+0100 D COMMAND [conn8] run command dialo_dev.$cmd { find: "system.js", $readPreference: { mode: "secondaryPreferred" }, $db: "dialo_dev" }
|
2018-02-28T17:50:49.843+0100 D - [conn8] User Assertion: 50:operation exceeded time limit src/mongo/db/operation_context.cpp 174
|
2018-02-28T17:50:49.843+0100 D COMMAND [conn8] assertion while executing command 'find' on database 'dialo_dev' with arguments '{ find: "system.js", $readPreference: { mode: "secondaryPreferred" }, $db: "dialo_dev" }': ExceededTimeLimit: operation exceeded time limit
|
2018-02-28T17:50:49.843+0100 I COMMAND [conn8] command dialo_dev.$cmd appName: "MongoDB Shell" command: find { find: "system.js", $readPreference: { mode: "secondaryPreferred" }, $db: "dialo_dev" } exception: operation exceeded time limit code:ExceededTimeLimit numYields:0 reslen:106 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_msg 0ms
|
2018-02-28T17:50:49.844+0100 D - [conn8] User Assertion: 50:operation exceeded time limit src/mongo/client/dbclientcursor.cpp 289
|
2018-02-28T17:50:49.844+0100 D QUERY [js] ImplScope 0x7f902eead640 unregistered for op 8135
|
2018-02-28T17:50:49.844+0100 D - [conn8] User Assertion: 50:operation exceeded time limit src/mongo/db/matcher/expression_where.cpp 117
|
2018-02-28T17:50:49.844+0100 D QUERY [js] ImplScope 0x7f902eead640 unregistered for op 8135
|
2018-02-28T17:50:49.844+0100 I QUERY [js] MozJS GC prologue heap stats - total: 1991428 limit: 1153433600
|
2018-02-28T17:50:49.845+0100 I QUERY [js] MozJS GC epilogue heap stats - total: 369068 limit: 1153433600
|
2018-02-28T17:50:49.845+0100 I QUERY [js] MozJS GC prologue heap stats - total: 260772 limit: 1153433600
|
2018-02-28T17:50:49.845+0100 I QUERY [js] MozJS GC epilogue heap stats - total: 77596 limit: 1153433600
|
2018-02-28T17:50:49.845+0100 D COMMAND [conn8] assertion while executing command 'find' on database 'dialo_dev' with arguments '{ find: "event", filter: { $where: "sleep(10)" }, maxTimeMS: 10.0, $db: "dialo_dev" }': ExceededTimeLimit: operation exceeded time limit
|
2018-02-28T17:50:49.845+0100 I COMMAND [conn8] command dialo_dev.event appName: "MongoDB Shell" command: find { find: "event", filter: { $where: "sleep(10)" }, maxTimeMS: 10.0, $db: "dialo_dev" } exception: operation exceeded time limit code:ExceededTimeLimit numYields:0 reslen:106 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_msg 49ms
|