mongodb query gets slow after 'local.oplog.rs'

Viewed 92

mongodb version: 4.0.18

this mongodb has Tens of thousands collections,

and all query block in schemalock when'local.oplog.rs' occurs

2021-12-16T09:55:07.397+0800 I NETWORK  [listener] connection accepted from 192.168.0.63:7854 #91651814 (4122 connections now open)
2021-12-16T09:55:07.399+0800 I NETWORK  [listener] connection accepted from 10.201.65.59:40866 #91651815 (4123 connections now open)
2021-12-16T09:55:07.400+0800 I NETWORK  [conn91651813] end connection 192.168.0.63:7846 (4122 connections now open)
2021-12-16T09:55:07.403+0800 I NETWORK  [conn91651814] end connection 192.168.0.63:7854 (4121 connections now open)
2021-12-16T09:55:07.417+0800 I NETWORK  [listener] connection accepted from 192.168.0.63:7874 #91651816 (4122 connections now open)
2021-12-16T09:55:07.427+0800 I NETWORK  [conn91651816] end connection 192.168.0.63:7874 (4121 connections now open)
2021-12-16T09:55:07.429+0800 I NETWORK  [conn91649244] end connection 10.201.65.51:60560 (4120 connections now open)
2021-12-16T09:55:07.431+0800 I NETWORK  [listener] connection accepted from 192.168.0.63:7890 #91651817 (4121 connections now open)
2021-12-16T09:55:07.433+0800 I NETWORK  [conn91651079] end connection 10.201.65.43:56512 (4120 connections now open)
2021-12-16T09:55:07.442+0800 I NETWORK  [conn91647959] end connection 10.201.65.55:57142 (4119 connections now open)
2021-12-16T09:55:07.450+0800 I NETWORK  [listener] connection accepted from 192.168.210.215:1279 #91651818 (4120 connections now open)
2021-12-16T09:55:07.463+0800 I NETWORK  [listener] connection accepted from 10.201.65.43:42988 #91651819 (4121 connections now open)
2021-12-16T09:55:07.475+0800 I NETWORK  [listener] connection accepted from 10.201.66.2:36786 #91651820 (4122 connections now open)
2021-12-16T09:55:07.477+0800 I NETWORK  [listener] connection accepted from 192.168.0.63:7930 #91651821 (4123 connections now open)
2021-12-16T09:55:07.482+0800 I NETWORK  [conn91648752] end connection 10.201.65.43:52070 (4122 connections now open)
2021-12-16T09:55:07.488+0800 I NETWORK  [conn91651821] end connection 192.168.0.63:7930 (4121 connections now open)
2021-12-16T09:55:07.490+0800 I NETWORK  [conn91651817] end connection 192.168.0.63:7890 (4120 connections now open)
2021-12-16T09:55:07.506+0800 I NETWORK  [listener] connection accepted from 10.201.65.51:51506 #91651822 (4121 connections now open)
2021-12-16T09:55:07.519+0800 I NETWORK  [listener] connection accepted from 10.201.65.55:40106 #91651823 (4122 connections now open)
2021-12-16T09:55:07.521+0800 I NETWORK  [conn91651822] end connection 10.201.65.51:51506 (4121 connections now open)
2021-12-16T09:55:07.526+0800 I COMMAND  [conn91651252] command local.oplog.rs command: collStats { collStats: "oplog.rs", $readPreference: { mode: "secondaryPreferred" }, $db: "local" } numYields:0 reslen:7143 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 } }, oplog: { acquireCount: { r: 1 } } } storage:{ data: { bytesRead: 6492142 } } protocol:op_query 6493ms
2021-12-16T09:55:07.527+0800 I COMMAND  [conn91650786] query scc.l600856 command: { find: "l600856", filter: {}, ntoreturn: 100, sort: { _id: -1 } } planSummary: IXSCAN { _id: 1 } cursorid:98799974222835 ntoreturn:100 ntoskip:0 keysExamined:100 docsExamined:100 numYields:1 nreturned:100 reslen:172815 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 12090, timeReadingMicros: 27 }, timeWaitingMicros: { handleLock: 61, schemaLock: 14751313 } } 14753ms
2021-12-16T09:55:07.527+0800 I COMMAND  [conn91650804] query sr.l600654 command: { find: "l600654", filter: {}, ntoreturn: 10, sort: { ctime: -1 } } planSummary: COLLSCAN, COLLSCAN cursorid:328438028343927 ntoreturn:10 ntoskip:0 keysExamined:0 docsExamined:15 hasSortStage:1 numYields:1 nreturned:10 reslen:8554 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 12983, timeReadingMicros: 42 }, timeWaitingMicros: { schemaLock: 14492462 } } 14493ms
2021-12-16T09:55:07.528+0800 I COMMAND  [conn91650787] query sn.l300274 command: { find: "l300274", filter: {}, ntoreturn: 200, sort: { ctime: -1 } } planSummary: IXSCAN { ctime: -1 } cursorid:274703843790329 ntoreturn:200 ntoskip:0 keysExamined:200 docsExamined:200 numYields:2 nreturned:200 reslen:244603 locks:{ Global: { acquireCount: { r: 3 } }, Database: { acquireCount: { r: 3 } }, Collection: { acquireCount: { r: 3 } } } storage:{ data: { bytesRead: 52464, timeReadingMicros: 75 }, timeWaitingMicros: { schemaLock: 14698981 } } 14700ms
2021-12-16T09:55:07.530+0800 I NETWORK  [conn91651252] end connection 127.0.0.1:30132 (4120 connections now open)
2021-12-16T09:55:07.531+0800 I COMMAND  [conn91650944] query sn.l600903 command: { find: "l600903", filter: {}, ntoreturn: 200, sort: { ctime: -1 } } planSummary: IXSCAN { ctime: -1 } cursorid:286330779052467 ntoreturn:200 ntoskip:0 keysExamined:200 docsExamined:200 numYields:2 nreturned:200 reslen:253735 locks:{ Global: { acquireCount: { r: 3 } }, Database: { acquireCount: { r: 3 } }, Collection: { acquireCount: { r: 3 } } } storage:{ data: { bytesRead: 290870, timeReadingMicros: 373 }, timeWaitingMicros: { handleLock: 7, schemaLock: 12673166 } } 12676ms
2021-12-16T09:55:07.531+0800 I NETWORK  [listener] connection accepted from 192.168.210.116:20083 #91651824 (4121 connections now open)
2021-12-16T09:55:07.531+0800 I COMMAND  [conn91650859] query sr.l002946 command: { find: "l002946", filter: {}, ntoreturn: 100, sort: { ctime: -1 } } planSummary: COLLSCAN, COLLSCAN ntoreturn:100 ntoskip:0 keysExamined:0 docsExamined:164 hasSortStage:1 cursorExhausted:1 numYields:3 nreturned:82 reslen:118588 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 4 } }, Collection: { acquireCount: { r: 4 } } } storage:{ data: { bytesRead: 119314, timeReadingMicros: 266 }, timeWaitingMicros: { handleLock: 22, schemaLock: 13703719 } } 13707ms
2021-12-16T09:55:07.532+0800 I COMMAND  [conn91651076] query scc.l603603 command: { find: "l603603", filter: {}, ntoreturn: 100, sort: { _id: -1 } } planSummary: IXSCAN { _id: 1 } cursorid:101487024652413 ntoreturn:100 ntoskip:0 keysExamined:100 docsExamined:100 numYields:1 nreturned:100 reslen:189067 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 215690, timeReadingMicros: 638 }, timeWaitingMicros: { schemaLock: 10294097 } } 10295ms
2021-12-16T09:55:07.533+0800 I COMMAND  [conn91650972] query sn.l000751 command: { find: "l000751", filter: {}, ntoreturn: 200, sort: { ctime: -1 } } planSummary: IXSCAN { ctime: -1 } cursorid:106124558488648 ntoreturn:200 ntoskip:0 keysExamined:200 docsExamined:200 numYields:2 nreturned:200 reslen:245151 locks:{ Global: { acquireCount: { r: 3 } }, Database: { acquireCount: { r: 3 } }, Collection: { acquireCount: { r: 3 } } } storage:{ data: { bytesRead: 301260, timeReadingMicros: 948 }, timeWaitingMicros: { handleLock: 37, schemaLock: 12266441 } } 12269ms

what happend when 'local.oplog.rs' ? this command will acquire schema lock ?

0 Answers
Related