|
Author:
{'name': 'Yuhong Zhang', 'email': 'danielzhangyh@gmail.com', 'username': 'YuhongZhang98'}
Message: SERVER-51806 Disable incompatible jstest for single phase index builds
Branch: v4.4
https://github.com/mongodb/mongo/commit/2f4f893adbabdb182bc19e08e07d745de44748ea
|
|
Author:
{'name': 'Yuhong Zhang', 'email': 'danielzhangyh@gmail.com', 'username': 'YuhongZhang98'}
Message: SERVER-51806 Enable lock yielding during the bulk load phase of index builds
(cherry picked from commit 935bd19)
SERVER-59190 IndexAccessMethod can be destructed during index build bulk load yield
(cherry picked from commit 50cc968)
Branch: v4.4
https://github.com/mongodb/mongo/commit/37df0008f516c595d6c413a151e69b9ec00f7437
|
|
Author:
{'name': 'Yuhong Zhang', 'email': 'danielzhangyh@gmail.com', 'username': 'YuhongZhang98'}
Message: SERVER-51806 bulk key insertion phase of index build holds IX lock without yielding
(cherry picked from commit 935bd194b9ff3cd871470d2e6fe036ee288f17f2)
Branch: v5.0
https://github.com/mongodb/mongo/commit/60faa8ed58c6b86e4e5bf5d3de4d2b4638f483f8
|
|
Author:
{'name': 'Yuhong Zhang', 'email': 'danielzhangyh@gmail.com', 'username': 'YuhongZhang98'}
Message: SERVER-51806 bulk key insertion phase of index build holds IX lock without yielding
Branch: master
https://github.com/mongodb/mongo/commit/935bd194b9ff3cd871470d2e6fe036ee288f17f2
|
|
There will be a workaround available for this issue available in the next 4.4 release that prevents the profile operation from blocking index builds. See SERVER-55034 for details.
|
|
amanda.brosig, this affects all versions of 4.2 and 4.4.
|
|
Can anyone confirm if this same bug exists in v4.4?
|
|
The key insertion phase of a hybrid index build seems to hold and not yield an IX (w) lock. Any single command with an S (R) lock can block all operations during that time. In this case the offending command seems to be the read-only profile command (profile: -1)
mongodb key insertion is write operation,so it holds IX(w) lock, so it block S lock, it is ok.
profile: -1 is it hold IS(r) lock. rather than hold S (R) lock
|
|
hi:
1、i find
{profile: -1}
to get current settings,this command executed by mongo not me。
i see it from doc.
profile Changed in version 4.0: The command can be run on mongos with profile level:
0 to set the slowms and sampleRate for the system log; i.e. you cannot enable the profiler on a mongos.
-1 to read the current settings.
2、How often does this command execute and trigger conditions?
i see 10-22 one day,profile:-1 executed from 00:00 to 21:15:19.
2020-10-22T00:00:19.597+0800 I COMMAND [conn993781] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603296019, 1166), signature: { hash: BinData(0, 356764A28D0C8DED53D9AACA08F951613B387793), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 137497 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 137ms
|
2020-10-22T00:21:19.904+0800 I COMMAND [conn993781] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603297279, 1097), signature: { hash: BinData(0, A343F8473F97535F9E994775041E541F1348236D), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 418730 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 419ms
|
2020-10-22T08:21:19.646+0800 I COMMAND [conn997203] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603326079, 2984), signature: { hash: BinData(0, A304633A5D5A8DD57FFC89CB5832F87FCEE6F68B), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 118882 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 119ms
|
2020-10-22T10:04:28.325+0800 I COMMAND [conn998027] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603332259, 4739), signature: { hash: BinData(0, 08169BF64EE3CDF6CEF359A8733914D5E3C02152), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 8781646 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 8782ms
|
2020-10-22T10:07:27.047+0800 I COMMAND [conn998206] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603332439, 1637), signature: { hash: BinData(0, DACFB13DB9C13F162AED8F039B25DFEAEB48FFA0), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 7516195 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 7517ms
|
2020-10-22T10:08:19.761+0800 I COMMAND [conn998027] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603332499, 5149), signature: { hash: BinData(0, 487103B37E43D1763B1ED8AE26643CD3ECDD6872), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 110318 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 110ms
|
2020-10-22T12:28:10.871+0800 I COMMAND [conn1005022] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603340778, 1), signature: { hash: BinData(0, 4835199DFC366CF648820EBED7C6FC2F0DDA1E8E), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 111325056 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 111325ms
|
2020-10-22T12:28:10.871+0800 I COMMAND [conn1005251] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603340839, 26), signature: { hash: BinData(0, C73486F8FB0AF4EF9610EF9E7B35A8EE33BB513C), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 51140763 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 51140ms
|
2020-10-22T12:28:10.872+0800 I COMMAND [conn1004828] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603340718, 1), signature: { hash: BinData(0, F6E27F35CFCF27C982C9F761224F142F7AE8DC14), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 171096737 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 171097ms
|
2020-10-22T12:49:19.641+0800 I COMMAND [conn1005455] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603342159, 3409), signature: { hash: BinData(0, 6C2272583614011BC3078BF0425E3354E7D9DF7A), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 106047 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 106ms
|
2020-10-22T13:03:19.742+0800 I COMMAND [conn1006651] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603342999, 3763), signature: { hash: BinData(0, C965FAF80DC396D4A0A15412560603FAD97C0288), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 166112 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 166ms
|
2020-10-22T16:37:20.123+0800 I COMMAND [conn1013065] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603355839, 6148), signature: { hash: BinData(0, BA20C801EC1FF2FCFFC987706128C844F7F81976), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 558182 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 558ms
|
2020-10-22T21:15:19.700+0800 I COMMAND [conn1017680] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603372519, 8000), signature: { hash: BinData(0, 5791949A9D96BC21394EAF1A139FE4237DF5EACF), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 101372 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 101ms
|
3、this profile command need to shard lock.how to block this command?
i find external sorter into index:op_time:319s this hold w
profile:-1:op_time:219s. this need R lock
lock: external sorter into index block profile:-1,profile:-1 block other update.
connections:from 103 to 1000.so this 391s connections not relese.
from logs:2020-10-22T12:23:00 to 2020-10-22T12:28:09,there is no update or select .
t think:profile:-1 is blocked by index,after profile:-1 block other all update.
so profile:-1 This command doesn't make sense. how to disable it?
2020-10-22T12:23:00.001+0800 I - [conn997955] Index Build: inserting keys from external sorter into index: 8411900/439497660 1%
|
2020-10-22T12:28:09.819+0800 I INDEX [conn997955] index build: inserted 439497660 keys from external sorter into index in 319 seconds
|
2020-10-22T12:28:10.247+0800 I NETWORK [listener] connection accepted from 10.5.130.54:54632 #1005589 (1042 connections now open)
|
2020-10-22T12:28:10.853+0800 I COMMAND [conn1004028] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603340599, 25), signature: { hash: BinData(0, A6629B4A02DAC651DF672778E73312F2EA74749E), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 291292837 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 291293ms
|
so i need to set profilelevel=0,so this command does not get current settings?
how to disable this command?
4、mongod db profileStatus:
shard1:PRIMARY> db.getProfilingStatus();{ "was" : 1, "slowms" : 100, "sampleRate" : 1, "$gleStats" : { "lastOpTime" : Timestamp(0, 0), "electionId" : ObjectId("7fffffff0000000000000005") }, "lastCommittedOpTime" : Timestamp(1605863816, 6506), "$configServerState" : { "opTime" : { "ts" : Timestamp(1605863815, 5381), "t" : NumberLong(1) } }, "$clusterTime" : { "clusterTime" : Timestamp(1605863816, 6539), "signature" : { "hash" : BinData(0,"ztX6+flrG6FrQXVENsfn3tg39mM="), "keyId" : NumberLong("6844800181754396704") } }, "operationTime" : Timestamp(1605863816, 6539)}
|
|
|
|
Hi 601290552@qq.com,
Thanks for your patience. What we see happening is that a database lock is being taken during the "key insertion" phase of the index build, during the period covered by these log lines:
2020-10-22T12:22:50.791+0800 I INDEX [conn997955] index build: collection scan done. scanned 439497660 total records in 8679 seconds
|
2020-10-22T12:22:57.001+0800 I - [conn997955] Index Build: inserting keys from external sorter into index: 3930000/439497660 0%
|
2020-10-22T12:28:09.001+0800 I - [conn997955] Index Build: inserting keys from external sorter into index: 438294000/439497660 99%
|
2020-10-22T12:28:09.819+0800 I INDEX [conn997955] index build: inserted 439497660 keys from external sorter into index in 319 seconds
|
During that time, the database lock is preventing lock acquisition by profile commands:
2020-10-22T12:28:10.853+0800 I COMMAND [conn1004028] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603340599, 25), signature: { hash: BinData(0, A6629B4A02DAC651DF672778E73312F2EA74749E), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 291292837 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 291293ms
|
2020-10-22T12:28:10.871+0800 I COMMAND [conn1004431] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603340658, 1), signature: { hash: BinData(0, CA4139178AC1DBD30A3698F87B4ED78A2D9F4A0B), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 231316757 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 231316ms
|
2020-10-22T12:28:10.871+0800 I COMMAND [conn1005022] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603340778, 1), signature: { hash: BinData(0, 4835199DFC366CF648820EBED7C6FC2F0DDA1E8E), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 111325056 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 111325ms
|
2020-10-22T12:28:10.871+0800 I COMMAND [conn1005251] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603340839, 26), signature: { hash: BinData(0, C73486F8FB0AF4EF9610EF9E7B35A8EE33BB513C), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 51140763 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 51140ms
|
2020-10-22T12:28:10.872+0800 I COMMAND [conn1004828] command expMonitordb.$cmd command: profile { profile: -1, $clusterTime: { clusterTime: Timestamp(1603340718, 1), signature: { hash: BinData(0, F6E27F35CFCF27C982C9F761224F142F7AE8DC14), keyId: 6844800181754396704 } }, $db: "expMonitordb", $readPreference: { mode: "primaryPreferred" } } numYields:0 reslen:354 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 1 } }, ReplicationStateTransition: { acquireCount: { w: 1 } }, Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { R: 1 }, acquireWaitCount: { R: 1 }, timeAcquiringMicros: { R: 171096737 } }, Mutex: { acquireCount: { r: 1 } } } protocol:op_msg 171097ms
|
Since these operations require a lock that blocks other operations, all other operations are blocked on these. So you may be able to avoid blocking all updates by avoiding these repeated profile commands (which appear to be noops since they are all setting a profile level of -1).
|
|
hi:
the complete create index log:
2020-10-22T09:58:11.342+0800 I INDEX [conn997955] index build: starting on expMonitordb.monitorIn properties: { v: 2, key: { org: 1.0, et: 1.0, pbOrg: 1.0 }, name: "org_1_et_1_pbOrg_1", ns: "expMonitordb.monitorIn" } using method: Hybrid
|
2020-10-22T09:58:11.342+0800 I INDEX [conn997955] build may temporarily use up to 200 megabytes of RAM
|
2020-10-22T09:58:14.000+0800 I - [conn997955] Index Build: scanning collection: 444500/438835262 0%
|
2020-10-22T12:22:48.001+0800 I - [conn997955] Index Build: scanning collection: 438989200/438794149 100%
|
2020-10-22T12:22:50.791+0800 I INDEX [conn997955] index build: collection scan done. scanned 439497660 total records in 8679 seconds
|
2020-10-22T12:22:57.001+0800 I - [conn997955] Index Build: inserting keys from external sorter into index: 3930000/439497660 0%
|
2020-10-22T12:28:09.001+0800 I - [conn997955] Index Build: inserting keys from external sorter into index: 438294000/439497660 99%
|
2020-10-22T12:28:09.819+0800 I INDEX [conn997955] index build: inserted 439497660 keys from external sorter into index in 319 seconds
|
2020-10-22T12:28:13.104+0800 I - [conn997955] Index Build: draining writes received during build: 19000/1428254 1%
|
2020-10-22T12:28:49.018+0800 I - [conn997955] Index Build: draining writes received during build: 1309000/1444293 90%
|
2020-10-22T12:28:51.106+0800 I INDEX [conn997955] index build: drain applied 1444434 side writes (inserted: 694530, deleted: 749904) for 'org_1_et_1_pbOrg_1' in 40458 ms
|
2020-10-22T12:28:51.109+0800 I INDEX [conn997955] index build: done building index org_1_et_1_pbOrg_1 on ns expMonitordb.monitorIn
|
2020-10-22T12:28:51.133+0800 I COMMAND [conn997955] command expMonitordb.monitorIn appName: "MongoDB Shell" command: createIndexes { createIndexes: "monitorIn", indexes: [ { key: { org: 1.0, et: 1.0, pbOrg: 1.0 }, name: "org_1_et_1_pbOrg_1" } ], allowImplicitCollectio
|
nCreation: false, lsid: { id: UUID("6b1368d9-beec-41c4-ae80-1d751b2c264a"), uid: BinData(0, 3B408CB48548B5037822C10EB0976B3CBF2CEE3BF9C708796BF03941FBECD80F) }, $clusterTime: { clusterTime: Timestamp(1603331891, 974), signature: { hash: BinData(0, 77EDCB6E8F0CD34729DB9B
|
51B23ED53E36B45D74), keyId: 6844800181754396704 } }, $audit: { $impersonatedUsers: [ { user: "admin", db: "admin" } ], $impersonatedRoles: [ { role: "root", db: "admin" } ] }, $client: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client",
|
version: "4.2.8" }, os: { type: "Linux", name: "CentOS Linux release 7.6.1810 (Core) ", architecture: "x86_64", version: "Kernel 3.10.0-957.el7.x86_64" }, mongos: { host: "srvdb6.yto.cloud:21051", client: "127.0.0.1:57948", version: "4.2.8" } }, $configServerState: { op
|
Time: { ts: Timestamp(1603331890, 3311), t: 1 } }, $db: "expMonitordb" } numYields:3447957 reslen:409 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 3447959 } }, ReplicationStateTransition: { acquireCount: { w: 3447960 } }, Global: { acquireCount: { r: 1, w: 3447
|
959 } }, Database: { acquireCount: { r: 1, w: 3447959 }, acquireWaitCount: { w: 136 }, timeAcquiringMicros: { w: 164847 } }, Collection: { acquireCount: { r: 3447959, w: 1, R: 1, W: 2 } }, Mutex: { acquireCount: { r: 4 } } } flowControl:{ acquireCount: 3447958, timeAcqu
|
iringMicros: 1215115 } storage:{ data: { bytesRead: 580449277358, bytesWritten: 2598814, timeReadingMicros: 4797651363, timeWritingMicros: 1985 } } protocol:op_msg 9039886ms
|
|
|
why mongodb auto create index for system.sessions.another i create index for monitorIn from 09:58.so They are not related,the system begin slow from 10:00,config.$cmd command: createIndexes from 11:23.
2020-10-22T11:23:35.956+0800 I COMMAND [conn1000118] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], allowImplicitCollectionCreation: false, $clusterTime: { clusterTime: Timestamp(1603337013, 9), signature: { hash: BinData(0, 4C51EDBABAE3332C5329CA971C5C84D7085BDCBD), keyId: 6844800181754396704 } }, $configServerState: { opTime: { ts: Timestamp(1603337013, 9), t: 1 } }, $db: "config" } numYields:0 reslen:412 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 2 } }, ReplicationStateTransition: { acquireCount: { w: 2 } }, Global: { acquireCount: { w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 1 } }, Mutex: { acquireCount: { r: 1 } } } flowControl:{ acquireCount: 1 } protocol:op_msg 1682ms
|
2020-10-22T12:28:10.890+0800 I COMMAND [conn1004100] command config.$cmd command: createIndexes { createIndexes: "system.sessions", indexes: [ { key: { lastUse: 1 }, name: "lsidTTLIndex", expireAfterSeconds: 1800 } ], allowImplicitCollectionCreation: false, $clusterTime: { clusterTime: Timestamp(1603340735, 45), signature: { hash: BinData(0, 391B4D5FFCC8F50FD773E00F8797B52B50C30F8B), keyId: 6844800181754396704 } }, $configServerState: { opTime: { ts: Timestamp(1603340735, 45), t: 1 } }, $db: "config" } numYields:0 reslen:412 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 2 } }, ReplicationStateTransition: { acquireCount: { w: 2 } }, Global: { acquireCount: { w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 1 } }, Mutex: { acquireCount: { r: 1 } } } flowControl:{ acquireCount: 1 } protocol:op_msg 154678ms
|
|
|
hi:
thank you for very much,but i have some problem for it:
1、from 09:58 to 10:30,update slow than before. 2020-10-22T10:04:20.249+080 - (Not pictured) The first "Detected blocked worker threads" line in the provided logs,online ddl why blocking?
2、why 2020-10-22T12:23:19 to 2020-10-22T12:28:10.906 ,blocking all thread?
so it is a bug for online ddl ?
3、why it need so long for Database.timeAcquiringMicros?because online ddl for index?
An update to expMonitordb.monitorIn completes after 291318ms (with Database.timeAcquiringMicros.w: 291264650)
4、from shard1.log about create index:
2020-10-22T09:58:11.342+0800 I INDEX [conn997955] index build: starting on expMonitordb.monitorIn properties: { v: 2, key: { org: 1.0, et: 1.0, pbOrg: 1.0 }, name: "org_1_et_1_pbOrg_1", ns: "expMonitordb.monitorIn" } using method: Hybrid
|
2020-10-22T09:58:11.342+0800 I INDEX [conn997955] build may temporarily use up to 200 megabytes of RAM
|
|
2020-10-22T12:28:51.133+0800 I COMMAND [conn997955] command expMonitordb.monitorIn appName: "MongoDB Shell" command: createIndexes { createIndexes: "monitorIn", indexes: [ { key: { org: 1.0, et: 1.0, pbOrg: 1.0 }, name: "org_1_et_1_pbOrg_1" } ], allowImplicitCollectionCreation: false, lsid: { id: UUID("6b1368d9-beec-41c4-ae80-1d751b2c264a"), uid: BinData(0, 3B408CB48548B5037822C10EB0976B3CBF2CEE3BF9C708796BF03941FBECD80F) }, $clusterTime: { clusterTime: Timestamp(1603331891, 974), signature: { hash: BinData(0, 77EDCB6E8F0CD34729DB9B51B23ED53E36B45D74), keyId: 6844800181754396704 } }, $audit: { $impersonatedUsers: [ { user: "admin", db: "admin" } ], $impersonatedRoles: [ { role: "root", db: "admin" } ] }, $client: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "4.2.8" }, os: { type: "Linux", name: "CentOS Linux release 7.6.1810 (Core) ", architecture: "x86_64", version: "Kernel 3.10.0-957.el7.x86_64" }, mongos: { host: "srvdb6.yto.cloud:21051", client: "127.0.0.1:57948", version: "4.2.8" } }, $configServerState: { opTime: { ts: Timestamp(1603331890, 3311), t: 1 } }, $db: "expMonitordb" } numYields:3447957 reslen:409 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 3447959 } }, ReplicationStateTransition: { acquireCount: { w: 3447960 } }, Global: { acquireCount: { r: 1, w: 3447959 } }, Database: { acquireCount: { r: 1, w: 3447959 }, acquireWaitCount: { w: 136 }, timeAcquiringMicros: { w: 164847 } }, Collection: { acquireCount: { r: 3447959, w: 1, R: 1, W: 2 } }, Mutex: { acquireCount: { r: 4 } } } flowControl:{ acquireCount: 3447958, timeAcquiringMicros: 1215115 } storage:{ data: { bytesRead: 580449277358, bytesWritten: 2598814, timeReadingMicros: 4797651363, timeWritingMicros: 1985 } } protocol:op_msg 9039886ms
|
|
|
2020-10-22T12:28:51.106+0800 I INDEX [conn997955] index build: drain applied 1444434 side writes (inserted: 694530, deleted: 749904) for 'org_1_et_1_pbOrg_1' in 40458 ms
|
5、default active create index 3. i only create one index
cpp_varname: maxNumActiveUserIndexBuilds
default: 3
validator:
gte: 0
|
|
Hi 601290552@qq.com, thanks for your patience so far. I've compiled my observations but have not identified a clear cause yet.
From the diagnostic data we see queueing from 2020-10-22T12:23:19.232Z+0800 to 2020-10-22T12:28:10.906+0800. This occurs during the bulk key insertion for a 2.5 hour index build on the expMonitordb.monitorIn collection, but does not coincide directly with that bulk key insertion. The queuing most closely coincides with a 291318ms update to the expMonitordb.monitorIn collection, which is blocked acquiring the Database.timeAcquiringMicros.w lock for almost all of its execution time. It's not yet clear what the blocking operation was.
A few notes:
- The "Detected blocked worker threads, starting new thread to unblock service executor" log line occurs many times in the provided logs, oftentimes multiple times a minute. The first and last line are noted in the timeline.
- createIndex for lastUse:1 in system.sessions is logged twice during the provided logs, and multiple other createIndex commands are reported in diagnostic data. One of those commands runs long during the period of queueing and is noted in the timeline below.
The timeline:
- 2020-10-22T09:58:11.342+0800 - (Not pictured) Index build on expMonitordb.monitorIn (
{ org: 1.0, et: 1.0, pbOrg: 1.0 }
) begins
- 2020-10-22T10:04:20.249+080 - (Not pictured) The first "Detected blocked worker threads" line in the provided logs
- 2020-10-22T12:22:53.020+0800 - (A) bulk key inserts for the expMonitordb.monitorIn ( {{{ org: 1.0, et: 1.0, pbOrg: 1.0 }}}) index begin
- 2020-10-22T12:23:19.232Z+0800 - (B) Queueing begins, a createIndexes command is reported in diagnostic data (could not correlate with a log entry), the noted long-running (291318ms) update to expMonitordb.monitorIn begins
- 2020-10-22T12:25:36.000+0800 - (D) Index build on system.sessions (lastUse:1) begins
- 2020-10-22T12:28:10.809+0800- (~E) The last "Detected blocked worker threads, starting new thread to unblock service executor" for a while
- 2020-10-22T12:28:10.890+0800 - (E) Index build on system.sessions (lastUse:1) completes after 154678ms.
- 2020-10-22T12:28:10.906+0800 - (F) An update to expMonitordb.monitorIn completes after 291318ms (with Database.timeAcquiringMicros.w: 291264650), queues resolve
- 2020-10-22T12:28:51.133+0800 - (G) Index build on expMonitordb.monitorIn ( {{{ org: 1.0, et: 1.0, pbOrg: 1.0 }}} ) completes after 9039886ms. At this time, we see the lock acquisition for the collection W lock that the end of the long-running index build should need.
|
|
hi Eric:
What is the current progress?
|
|
hi Eric Sedor:
thank you very much. i am waiting for it
|
|
601290552@qq.com we are investigating and apologize for the delay.
|
|
1、please help me analyze metrics from 2020-10-22 08:00:00+08:00 to 16:00:00+08:00,because the problem begin at 2020-10-22 10:30:00+08:00,index create time is 2020-10-22 09:58:00+08:00,the issue stop time is 2020-10-22 14:00:00+08:00.analyze metrics, it would include connections and flowcontrol metrics?
2、please help analyze how and why create index influence db performance about response time and final blocking all write?
|
|
hello:
please help me deal with it.need to other diag log?if too long time,some diag log would be lost.tks.
|
|
i will upload shard1 primary log including:mongo slow log and diag log.
rw------ 1 mongo mongo 10410467 Oct 22 08:17 metrics.2020-10-21T19-47-05Z-00000
rw------ 1 mongo mongo 10489382 Oct 22 12:31 metrics.2020-10-22T00-17-05Z-00000
rw------ 1 mongo mongo 10472702 Oct 22 16:31 metrics.2020-10-22T04-31-37Z-00000
rw------ 1 mongo mongo 10336305 Oct 22 20:31 metrics.2020-10-22T08-31-42Z-00000
rw------ 1 mongo mongo 872577 Oct 22 20:51 metrics.2020-10-22T12-31-43Z-00000
|
|
create index from 2020/10/22 09:58:00 to 2020/10/22 12:28:00.
but from 10:30 to 12:30.connections from 150 to 1000.so it effect system.
4.2 create index is online,why blocking write for Index Build: inserting keys from external sorter into index mode and other time update is slow 10 times from normal time?
so create index has two problems:
one problem is :create index is running,but .create index execute more than 30 minutes,so
database begin to deal with update slowly, more than 10 times on begin to create index or before create index.
two problem is:Index Build: inserting keys from external sorter into index,so that database is blocking all request.
from 10:32: normal update is 155ms,after update is 3909ms,so it spends time on timeAcquiringMicros:
{ w: 3908088 }
.
2020-10-22T10:32:19.127+0800 I COMMAND [conn999225] command expMonitordb.$cmd appName: "monitor_in_out" command: update { update: "monitorOut", bypassDocumentValidation: false, ordered: true, stmtIds: [ 0 ], updates: [ { q: { org: "571038", ct: new Date(1602241845000), no: "YT2092258602172" }, u: { $set: { curCode: 131, curEmp: "00754344", curOrg: "571901", curT: new Date(1603333798000), preOrg: "571901", nextOrg: "571038", st: new Date(1603333938954), status: 4, ioType: "01" } }, multi: false, upsert: true } ], runtimeConstants: { localNow: new Date(1603333938972), clusterTime: Timestamp(1603333938, 4789) }, shardVersion: [ Timestamp(21262, 9), ObjectId('5f0ee7bb9a174cbcccb36243') ], allowImplicitCollectionCreation: false, lsid: { id: UUID("09afed15-ad59-4bf8-939d-ecea3d219183"), uid: BinData(0, F26770D132634AFD9C12F0330423A9A86C8757FAA1BC0F272877335651AAEA5A) }, txnNumber: 1947281, $clusterTime: { clusterTime: Timestamp(1603333938, 4789), signature: { hash: BinData(0, 83C0AA143F1BE5725E52C85B2425E2DD8C438C87), keyId: 6844800181754396704 } }, $audit: { $impersonatedUsers: [ { user: "lhexp", db: "expMonitordb" } ], $impersonatedRoles: [ { role: "readWrite", db: "expMonitordb" } ] }, $client: { driver: { name: "mongo-java-driver|sync", version: "4.0.5" }, os: { type: "Linux", name: "Linux", architecture: "amd64", version: "3.10.0-693.21.1.el7.x86_64" }, platform: "Java/Oracle Corporation/1.8.0_172-b11", application: { name: "monitor_in_out" }, mongos: { host: "srvdb10.yto.cloud:21051", client: "10.7.53.133:45306", version: "4.2.8" } }, $configServerState: { opTime: { ts: Timestamp(1603333938, 2583), t: 1 } }, $db: "expMonitordb" } numYields:1 reslen:426 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 5 } }, ReplicationStateTransition: { acquireCount: { w: 6 } }, Global: { acquireCount: { r: 1, w: 4 } }, Database: { acquireCount: { w: 4 } }, Collection: { acquireCount: { w: 4 } }, Metadata: { acquireCount: { W: 1 } }, Mutex: { acquireCount: { r: 8 } } } flowControl:{ acquireCount: 2 } storage:{} protocol:op_msg 155ms
|
2020-10-22T10:32:23.462+0800 I COMMAND [conn999198] command expMonitordb.$cmd appName: "monitor_in_out" command: update { update: "monitorOut", bypassDocumentValidation: false, ordered: true, stmtIds: [ 0 ], updates: [ { q: { org: "538001", ct: new Date(1603189414000), no: "YT4873213854502" }, u: { $set: { curCode: 171, curEmp: "01927198", curOrg: "280001", curT: new Date(1603333774000), preOrg: null, nextOrg: "", st: new Date(1603333939119), status: 4, ioType: "01" } }, multi: false, upsert: true } ], runtimeConstants: { localNow: new Date(1603333939137), clusterTime: Timestamp(1603333939, 1195) }, shardVersion: [ Timestamp(21262, 9), ObjectId('5f0ee7bb9a174cbcccb36243') ], allowImplicitCollectionCreation: false, lsid: { id: UUID("1a38e17f-5d87-4734-9246-f1a57fc16c30"), uid: BinData(0, F26770D132634AFD9C12F0330423A9A86C8757FAA1BC0F272877335651AAEA5A) }, txnNumber: 2029302, $clusterTime: { clusterTime: Timestamp(1603333939, 1195), signature: { hash: BinData(0, 747EE21466E6E579EB645F8D0541FBB587FB5D14), keyId: 6844800181754396704 } }, $audit: { $impersonatedUsers: [ { user: "lhexp", db: "expMonitordb" } ], $impersonatedRoles: [ { role: "readWrite", db: "expMonitordb" } ] }, $client: { driver: { name: "mongo-java-driver|sync", version: "4.0.5" }, os: { type: "Linux", name: "Linux", architecture: "amd64", version: "3.10.0-693.21.1.el7.x86_64" }, platform: "Java/Oracle Corporation/1.8.0_172-b11", application: { name: "monitor_in_out" }, mongos: { host: "srvdb10.yto.cloud:21051", client: "10.7.53.132:58114", version: "4.2.8" } }, $configServerState: { opTime: { ts: Timestamp(1603333938, 2583), t: 1 } }, $db: "expMonitordb" } numYields:0 reslen:426 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 4 } }, ReplicationStateTransition: { acquireCount: { w: 5 } }, Global: { acquireCount: { r: 1, w: 3 } }, Database: { acquireCount: { w: 3 }, acquireWaitCount: { w: 1 }, timeAcquiringMicros: { w: 3908088 } }, Collection: { acquireCount: { w: 3 } }, Metadata: { acquireCount: { W: 1 }, acquireWaitCount: { W: 1 }, timeAcquiringMicros: { W: 34 } }, Mutex: { acquireCount: { r: 8 } } } flowControl:{ acquireCount: 1 } storage:{} protocol:op_msg 3909ms
|
|
Generated at Thu Feb 08 05:26:29 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.