-
Type: Bug
-
Resolution: Gone away
-
Priority: Minor - P4
-
None
-
Affects Version/s: None
-
Component/s: None
-
Labels:None
-
8
-
Storage - Ra 2020-07-27
Mongodb encountered a dhandle read write deadlock in wiredtiger.
[ReplicaSetFixture:job0:primary] {"t":{"$date":"2020-06-26T22:25:16.671+00:00"},"s":"I", "c":"STORAGE", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":77644,"port":20000,"dbPath":"/data/db/job0/resmoke/node0","architecture":"64-bit","host":"ip-10-122-30-1"}} [ReplicaSetFixture:job0:secondary0] {"t":{"$date":"2020-06-26T22:25:16.673+00:00"},"s":"I", "c":"STORAGE", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":77647,"port":20001,"dbPath":"/data/db/job0/resmoke/node1","architecture":"64-bit","host":"ip-10-122-30-1"}} [ReplicaSetFixture:job0:secondary1] {"t":{"$date":"2020-06-26T22:25:16.677+00:00"},"s":"I", "c":"STORAGE", "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":77650,"port":20002,"dbPath":"/data/db/job0/resmoke/node2","architecture":"64-bit","host":"ip-10-122-30-1"}}
[2020/06/27 01:07:13.640] Mutex at 0x7fabfae04ff0 held by "WTIdleSessionSweeper" (Thread 0x7fabead0e700 (LWP 77686)) waited on by "conn28" (Thread 0x7fabc4ec0700 (LWP 78011)) [2020/06/27 01:07:14.981] MongoDB Lock at 0x7fac0d369900 held by "OplogApplier-0" (Thread 0x7fabd87e2700 (LWP 77831)) (mongo::MODE_X) waited on by "BackgroundSync" (Thread 0x7fabca1cb700 (LWP 77860)) [2020/06/27 01:07:14.981] Mutex at 0x7fabfae04ff0 held by "WTIdleSessionSweeper" (Thread 0x7fabead0e700 (LWP 77686)) waited on by "decreaseSnapshotHistoryCachePressure" (Thread 0x7fabde4fa700 (LWP 77756)) [2020/06/27 01:07:16.329] MongoDB Lock at 0x7fac0d369900 held by "OplogApplier-0" (Thread 0x7fabd87e2700 (LWP 77831)) (mongo::MODE_X) waited on by "TTLMonitor" (Thread 0x7fabe16ff700 (LWP 77751))
mongod-secondary0 (pid 77647) "WTIdleSessionSweeper" thread with WiredTigerSessionCache::closeExpiredIdleSessions was queued to __wt_readlock and got Mutex
[2020/06/27 01:06:55.287] Thread 14: "WTIdleSessionSweeper" (Thread 0x7fabead0e700 (LWP 77686)) [2020/06/27 01:06:55.287] #0 0x00007fabf3a58a5e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 [2020/06/27 01:06:55.287] #1 0x00007fabf625a3c9 in __wt_cond_wait_signal (session=session@entry=0x7fabfaef74a0, cond=0x7fac09a6ef00, usecs=usecs@entry=10000, run_func=run_func@entry=0x7fabf628b010 <__read_blocked>, signalled=signalled@entry=0x7fabead0d3c0) at src/third_party/wiredtiger/src/os_posix/os_mtx_cond.c:115 [2020/06/27 01:06:55.287] #2 0x00007fabf628b3e9 in __wt_cond_wait (run_func=0x7fabf628b010 <__read_blocked>, usecs=10000, cond=<optimized out>, session=0x7fabfaef74a0) at src/third_party/wiredtiger/src/include/misc.i:19 [2020/06/27 01:06:55.287] #3 __wt_readlock (session=session@entry=0x7fabfaef74a0, l=l@entry=0x7fac005a5fc0) at src/third_party/wiredtiger/src/support/mtx_rw.c:252 [2020/06/27 01:06:55.287] #4 0x00007fabf6286026 in __wt_session_lock_dhandle (session=session@entry=0x7fabfaef74a0, flags=flags@entry=0, is_deadp=is_deadp@entry=0x7fabead0d4d7) at src/third_party/wiredtiger/src/session/session_dhandle.c:164 [2020/06/27 01:06:55.287] #5 0x00007fabf621609b in __curfile_reopen (cursor=0x7fac0b8e7800, check_only=<optimized out>) at src/third_party/wiredtiger/src/cursor/cur_file.c:576 [2020/06/27 01:06:55.287] #6 0x00007fabf6275d5b in __session_close_cursors (session=session@entry=0x7fabfaef74a0, cursors=<optimized out>, cursors=<optimized out>) at src/third_party/wiredtiger/src/session/session_api.c:222 [2020/06/27 01:06:55.287] #7 0x00007fabf6275e9f in __session_close_cached_cursors (session=session@entry=0x7fabfaef74a0) at src/third_party/wiredtiger/src/session/session_api.c:250 [2020/06/27 01:06:55.287] #8 0x00007fabf628153b in __session_close (wt_session=0x7fabfaef74a0, config=<optimized out>) at src/third_party/wiredtiger/src/session/session_api.c:286 [2020/06/27 01:06:55.287] #9 0x00007fabf61e97be in mongo::WiredTigerSession::~WiredTigerSession (this=0x7fabff7ea190, __in_chrg=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp:78 [2020/06/27 01:06:55.288] #10 0x00007fabf61eb8aa in mongo::WiredTigerSessionCache::closeExpiredIdleSessions (this=0x7fabfae04f00, idleTimeMillis=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp:419 [2020/06/27 01:06:55.288] #11 0x00007fabf61c6bd8 in mongo::WiredTigerKVEngine::WiredTigerSessionSweeper::run (this=0x7fabfae5e800) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/atomic_base.h:390 [2020/06/27 01:06:55.288] #12 0x00007fabf7cf8b36 in mongo::BackgroundJob::jobBody (this=0x7fabfae5e800) at src/mongo/util/background.cpp:160
mongod-secondary0 "ReplWriterWorker-1" thread was also queued to __wt_readlock
[2020/06/27 01:06:55.242] Thread 43: "ReplWriterWorker-1" (Thread 0x7fabd5fde700 (LWP 77835)) [2020/06/27 01:06:55.242] #0 0x00007fabf3a58a5e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 [2020/06/27 01:06:55.243] #1 0x00007fabf625a3c9 in __wt_cond_wait_signal (session=session@entry=0x7fabfaef59f0, cond=0x7fabfaeb2600, usecs=usecs@entry=10000, run_func=run_func@entry=0x7fabf628b010 <__read_blocked>, signalled=signalled@entry=0x7fabd5fdb520) at src/third_party/wiredtiger/src/os_posix/os_mtx_cond.c:115 [2020/06/27 01:06:55.243] #2 0x00007fabf628b3e9 in __wt_cond_wait (run_func=0x7fabf628b010 <__read_blocked>, usecs=10000, cond=<optimized out>, session=0x7fabfaef59f0) at src/third_party/wiredtiger/src/include/misc.i:19 [2020/06/27 01:06:55.243] #3 __wt_readlock (session=session@entry=0x7fabfaef59f0, l=0x7fabfaec8668) at src/third_party/wiredtiger/src/support/mtx_rw.c:252 [2020/06/27 01:06:55.243] #4 0x00007fabf62869d2 in __session_find_shared_dhandle (checkpoint=0x0, uri=0x7fabf809d2d3 "file:WiredTigerHS.wt", session=0x7fabfaef59f0) at src/third_party/wiredtiger/src/session/session_dhandle.c:409 [2020/06/27 01:06:55.243] #5 __session_get_dhandle (checkpoint=0x0, uri=0x7fabf809d2d3 "file:WiredTigerHS.wt", session=0x7fabfaef59f0) at src/third_party/wiredtiger/src/session/session_dhandle.c:446 [2020/06/27 01:06:55.243] #6 __wt_session_get_dhandle (session=0x7fabfaef59f0, uri=0x7fabf809d2d3 "file:WiredTigerHS.wt", checkpoint=0x0, cfg=0x7fabd5fdb840, flags=0) at src/third_party/wiredtiger/src/session/session_dhandle.c:475 [2020/06/27 01:06:55.243] #7 0x00007fabf6287114 in __wt_session_get_btree_ckpt (session=session@entry=0x7fabfaef59f0, uri=uri@entry=0x7fabf809d2d3 "file:WiredTigerHS.wt", cfg=cfg@entry=0x7fabd5fdb840, flags=flags@entry=0) at src/third_party/wiredtiger/src/session/session_dhandle.c:320 [2020/06/27 01:06:55.243] #8 0x00007fabf621e0fa in __wt_curfile_open (session=session@entry=0x7fabfaef59f0, uri=uri@entry=0x7fabf809d2d3 "file:WiredTigerHS.wt", owner=owner@entry=0x0, cfg=cfg@entry=0x7fabd5fdb840, cursorp=cursorp@entry=0x7fabd5fdb838) at src/third_party/wiredtiger/src/cursor/cur_file.c:800 [2020/06/27 01:06:55.243] #9 0x00007fabf6281d3f in __session_open_cursor_int (session=0x7fabfaef59f0, uri=<optimized out>, owner=0x0, other=<optimized out>, cfg=0x7fabd5fdb840, cursorp=0x7fabd5fdb838) at src/third_party/wiredtiger/src/session/session_api.c:462 [2020/06/27 01:06:55.243] #10 0x00007fabf6235e46 in __wt_hs_cursor_open (session=0x7fabfaef59f0) at src/third_party/wiredtiger/src/history/hs.c:221 [2020/06/27 01:06:55.243] #11 0x00007fabf6235ee8 in __wt_hs_cursor (session=session@entry=0x7fabfaef59f0, session_flags=session_flags@entry=0x7fabd5fdb934, is_owner=is_owner@entry=0x7fabd5fdb933) at src/third_party/wiredtiger/src/history/hs.c:259 [2020/06/27 01:06:55.243] #12 0x00007fabf62330a0 in __wt_evict (session=session@entry=0x7fabfaef59f0, ref=ref@entry=0x7fac077d6440, previous_state=previous_state@entry=3 '\003', flags=2, flags@entry=0) at src/third_party/wiredtiger/src/evict/evict_page.c:137 [2020/06/27 01:06:55.244] #13 0x00007fabf622c18d in __evict_page (session=0x7fabfaef59f0, is_server=<optimized out>) at src/third_party/wiredtiger/src/evict/evict_lru.c:2254 [2020/06/27 01:06:55.244] #14 0x00007fabf622d61c in __wt_cache_eviction_worker (session=session@entry=0x7fabfaef59f0, busy=<optimized out>, readonly=readonly@entry=false, pct_full=<optimized out>) at src/third_party/wiredtiger/src/evict/evict_lru.c:2341 [2020/06/27 01:06:55.244] #15 0x00007fabf62cb59f in __wt_cache_eviction_check (busy=false, didworkp=0x0, didworkp=0x0, readonly=false, busy=false, session=<optimized out>) at src/third_party/wiredtiger/src/include/cache.i:479 [2020/06/27 01:06:55.244] #16 __cursor_enter (session=<optimized out>) at src/third_party/wiredtiger/src/include/cursor.i:164 [2020/06/27 01:06:55.244] #17 __cursor_func_init (reenter=true, cbt=0x7fabff108c00) at src/third_party/wiredtiger/src/include/cursor.i:406 [2020/06/27 01:06:55.244] #18 __wt_btcur_insert (cbt=cbt@entry=0x7fabff108c00) at src/third_party/wiredtiger/src/btree/bt_cursor.c:825 [2020/06/27 01:06:55.244] #19 0x00007fabf621ce09 in __curfile_insert (cursor=0x7fabff108c00) at src/third_party/wiredtiger/src/cursor/cur_file.c:265 [2020/06/27 01:06:55.244] #20 0x00007fabf61ef160 in mongo::WiredTigerSizeStorer::flush (this=<optimized out>, syncToDisk=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_size_storer.cpp:179 [2020/06/27 01:06:55.244] #21 0x00007fabf61b4389 in mongo::WiredTigerKVEngine::syncSizeInfo (this=<optimized out>, sync=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp:1534 [2020/06/27 01:06:55.244] #22 0x00007fabf61b47d5 in mongo::WiredTigerKVEngine::haveDropsQueued (this=0x7fabfae78000) at src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp:1900 [2020/06/27 01:06:55.245] #23 0x00007fabf61eba17 in mongo::WiredTigerSessionCache::releaseSession (this=0x7fabfae04f00, session=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp:530 [2020/06/27 01:06:55.245] #24 0x00007fabf61e5dd7 in std::unique_ptr<mongo::WiredTigerSession, mongo::WiredTigerSessionCache::WiredTigerSessionDeleter>::~unique_ptr (this=0x7fac0f628300, __in_chrg=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:347 [2020/06/27 01:06:55.245] #25 mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit (this=0x7fac0f6282a0, __in_chrg=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:166 [2020/06/27 01:06:55.245] #26 0x00007fabf61e5ec1 in mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit (this=0x7fac0f6282a0, __in_chrg=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:166 [2020/06/27 01:06:55.245] #27 0x00007fabf7d34c93 in std::default_delete<mongo::RecoveryUnit>::operator() (this=0x7fac003c8d08, __ptr=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:347 [2020/06/27 01:06:55.245] #28 std::unique_ptr<mongo::RecoveryUnit, std::default_delete<mongo::RecoveryUnit> >::~unique_ptr (this=0x7fac003c8d08, __in_chrg=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:274 [2020/06/27 01:06:55.245] #29 mongo::OperationContext::~OperationContext (this=0x7fac003c8c80, __in_chrg=<optimized out>) at src/mongo/db/operation_context.cpp:89 [2020/06/27 01:06:55.245] #30 0x00007fabf7d34d91 in mongo::OperationContext::~OperationContext (this=0x7fac003c8c80, __in_chrg=<optimized out>) at src/mongo/db/operation_context.cpp:89 [2020/06/27 01:06:55.245] #31 0x00007fabf7d3b905 in mongo::ServiceContext::OperationContextDeleter::operator() (this=this@entry=0x7fabd5fdd0c8, opCtx=0x7fac003c8c80) at src/mongo/db/service_context.cpp:294 [2020/06/27 01:06:55.245] #32 0x00007fabf64f6412 in std::unique_ptr<mongo::OperationContext, mongo::ServiceContext::OperationContextDeleter>::~unique_ptr (this=0x7fabd5fdd0c8, __in_chrg=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:347 [2020/06/27 01:06:55.245] #33 mongo::repl::<lambda(size_t, size_t)>::<lambda(auto:43)>::operator()<mongo::Status> (status=Status(OK, "\300\250\367\370\253\177\000\000\000\000\000\000\000\000\000\000\240\061\300\372\253\177\000\000\000=\233\377\253\177\000\000\340jj\377\253\177\000\000\005\315(\000\000\000\000\000x\342\376\370\253\177\000\000\220\214<\000\254\000\064?:\206slJ\223\277\026\351\334\245\306\266\v\343\260\304B\230\374\034\024\232\373\364\310\231o\271$'\256A\344d\233\223L\244\225\231\033xR\270U\263\000\000\000\000\000\000\000\000\000\060\006\000\000\000\000\000\000\000\215,\f\254\177\000\000\240\202b\017\254\177", '\000' <repeats 22 times>, "\253\177", '\000' <repeats 22 times>, "\001\000\000\000P\215<\000\254\177\000\000"...), __closure=<optimized out>) at src/mongo/db/repl/oplog_applier_impl.cpp:547 [2020/06/27 01:06:55.245] #34 mongo::unique_function<void(mongo::Status)>::callRegularVoid<mongo::repl::scheduleWritesToOplog(mongo::OperationContext*, mongo::repl::StorageInterface*, mongo::ThreadPool*, const std::vector<mongo::repl::OplogEntry>&)::<lambda(size_t, size_t)>::<lambda(auto:43)> > (args#0=..., f=..., isVoid=...) at src/mongo/util/functional.h:145 [2020/06/27 01:06:55.246] #35 mongo::unique_function<void(mongo::Status)>::SpecificImpl::call(mongo::Status &&) (this=<optimized out>, args#0=...) at src/mongo/util/functional.h:159 [2020/06/27 01:06:55.246] #36 0x00007fabf79a55a2 in mongo::unique_function<void (mongo::Status)>::operator()(mongo::Status) const (args#0=Status(OK, <error reading variable: Cannot create a lazy string with address 0x0, and a non-zero length.>), this=<synthetic pointer>) at src/mongo/util/invariant.h:64 [2020/06/27 01:06:55.246] #37 mongo::ThreadPool::_doOneTask (this=0x7fabffa63e00, lk=0x7fabd5fdd390) at src/mongo/util/concurrency/thread_pool.cpp:406 [2020/06/27 01:06:55.246] #38 0x00007fabf79a7dc6 in mongo::ThreadPool::_consumeTasks (this=0x7fabffa63e00) at src/mongo/util/concurrency/thread_pool.cpp:346
mongod-secondary0 "conn28" thread (according to the test log it's OplogFetcher) was waiting for Mutex
[2020/06/27 01:06:55.230] Thread 65: "conn28" (Thread 0x7fabc4ec0700 (LWP 78011)) [2020/06/27 01:06:55.230] #0 0x00007fabf3a5b334 in __lll_lock_wait () from /lib64/libpthread.so.0 [2020/06/27 01:06:55.230] #1 0x00007fabf3a565d8 in _L_lock_854 () from /lib64/libpthread.so.0 [2020/06/27 01:06:55.230] #2 0x00007fabf3a564a7 in pthread_mutex_lock () from /lib64/libpthread.so.0 [2020/06/27 01:06:55.230] #3 0x00007fabf7e55588 in __gthread_mutex_lock (__mutex=0x7fabfae04ff0) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/x86_64-mongodb-linux/bits/gthr-default.h:748 [2020/06/27 01:06:55.230] #4 std::mutex::lock (this=0x7fabfae04ff0) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/std_mutex.h:103 [2020/06/27 01:06:55.230] #5 mongo::latch_detail::Mutex::lock (this=this@entry=0x7fabfae04fd8) at src/mongo/platform/mutex.cpp:56 [2020/06/27 01:06:55.230] #6 0x00007fabf61ebab0 in std::lock_guard<mongo::latch_detail::Latch>::lock_guard (__m=..., this=<synthetic pointer>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/std_mutex.h:161 [2020/06/27 01:06:55.231] #7 mongo::WiredTigerSessionCache::releaseSession (this=0x7fabfae04f00, session=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp:519 [2020/06/27 01:06:55.231] #8 0x00007fabf61e5dd7 in std::unique_ptr<mongo::WiredTigerSession, mongo::WiredTigerSessionCache::WiredTigerSessionDeleter>::~unique_ptr (this=0x7fac00551560, __in_chrg=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:347 [2020/06/27 01:06:55.231] #9 mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit (this=0x7fac00551500, __in_chrg=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:166 [2020/06/27 01:06:55.231] #10 0x00007fabf61e5ec1 in mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit (this=0x7fac00551500, __in_chrg=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:166 [2020/06/27 01:06:55.231] #11 0x00007fabf7d34c93 in std::default_delete<mongo::RecoveryUnit>::operator() (this=0x7fac00581a08, __ptr=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:347 [2020/06/27 01:06:55.231] #12 std::unique_ptr<mongo::RecoveryUnit, std::default_delete<mongo::RecoveryUnit> >::~unique_ptr (this=0x7fac00581a08, __in_chrg=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:274 [2020/06/27 01:06:55.231] #13 mongo::OperationContext::~OperationContext (this=0x7fac00581980, __in_chrg=<optimized out>) at src/mongo/db/operation_context.cpp:89 [2020/06/27 01:06:55.231] #14 0x00007fabf7d34d91 in mongo::OperationContext::~OperationContext (this=0x7fac00581980, __in_chrg=<optimized out>) at src/mongo/db/operation_context.cpp:89 [2020/06/27 01:06:55.231] #15 0x00007fabf7d3b905 in mongo::ServiceContext::OperationContextDeleter::operator() (this=this@entry=0x7fabffbfe3b8, opCtx=0x7fac00581980) at src/mongo/db/service_context.cpp:294 [2020/06/27 01:06:55.231] #16 0x00007fabf65930d9 in std::unique_ptr<mongo::OperationContext, mongo::ServiceContext::OperationContextDeleter>::reset (__p=<optimized out>, this=0x7fabffbfe3b8) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:347 [2020/06/27 01:06:55.231] #17 mongo::ServiceStateMachine::_runNextInGuard (this=0x7fabffbfe310, guard=...) at src/mongo/transport/service_state_machine.cpp:554 [2020/06/27 01:06:55.232] #18 0x00007fabf6593b16 in mongo::ServiceStateMachine::<lambda()>::operator() (__closure=<optimized out>) at src/mongo/transport/service_state_machine.cpp:208 [2020/06/27 01:06:55.232] #19 std::_Function_handler<void(), mongo::ServiceStateMachine::_scheduleNextWithGuard(mongo::ServiceStateMachine::ThreadGuard, mongo::transport::ServiceExecutor::ScheduleFlags, mongo::transport::ServiceExecutorTaskName, mongo::ServiceStateMachine::Ownership)::<lambda()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/std_function.h:297 [2020/06/27 01:06:55.232] #20 0x00007fabf7835e4b in std::function<void ()>::operator()() const (this=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/std_function.h:682 [2020/06/27 01:06:55.232] #21 mongo::transport::ServiceExecutorSynchronous::<lambda()>::operator() (__closure=0x7fac005868c0) at src/mongo/transport/service_executor_synchronous.cpp:124 [2020/06/27 01:06:55.232] #22 std::_Function_handler<void(), mongo::transport::ServiceExecutorSynchronous::schedule(mongo::transport::ServiceExecutor::Task, mongo::transport::ServiceExecutor::ScheduleFlags, mongo::transport::ServiceExecutorTaskName)::<lambda()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/std_function.h:297
Here we can see that "conn28" is related to "OplogFetcher" thread
[ReplicaSetFixture:job0:secondary0] | 2020-06-26T23:00:15.391+00:00 I COMMAND 51803 [conn28] "Slow query","attr":{"type":"command","ns":"local.oplog.rs","appName":"OplogFetcher","command":{"getMore":2591556819675862000,"collection":"oplog.rs","batchSize":13981010,"maxTimeMS":30000,"term":1,"lastKnownCommittedOpTime":{"ts":{"$timestamp":{"t":1593210322,"i":3053}},"t":1},"$db":"local","$replData":1,"$oplogQueryData":1,"$readPreference":{"mode":"secondaryPreferred"},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1593210322,"i":3053}},"signature":{"hash":{"$binary":{"base64":"qrn1rgkVQ3HB3NIe0kpDEgNR3gE=","subType":"0"}},"keyId":6842786207164793000}}},"originatingCommand":{"find":"oplog.rs","filter":{"ts":{"$gte":{"$timestamp":{"t":1593210320,"i":1}}}},"readConcern":{"level":"local","afterClusterTime":{"$timestamp":{"t":0,"i":1}}},"ntoreturn":13981010,"maxTimeMS":60000,"tailable":true,"awaitData":true,"oplogReplay":true,"term":1,"$db":"local","$replData":1,"$oplogQueryData":1,"$readPreference":{"mode":"secondaryPreferred"},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1593210322,"i":3053}},"signature":{"hash":{"$binary":{"base64":"qrn1rgkVQ3HB3NIe0kpDEgNR3gE=","subType":"0"}},"keyId":6842786207164793000}}},"planSummary":"COLLSCAN","cursorid":2591556819675862000,"keysExamined":0,"docsExamined":0,"numYields":3,"nreturned":0,"reslen":678,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":4}},"Global":{"acquireCount":{"r":4}},"Database":{"acquireCount":{"r":4}},"Mutex":{"acquireCount":{"r":1}},"oplog":{"acquireCount":{"r":4}}},"readConcern":{"level":"local","afterClusterTime":{"$timestamp":{"t":0,"i":1}},"provenance":"clientSupplied"},"storage":{"timeWaitingMicros":{"cache":225047}},"protocol":"op_msg","durationMillis":225} [ReplicaSetFixture:job0:secondary0] | 2020-06-26T23:00:45.392+00:00 I COMMAND 51803 [conn28] "Slow query","attr":{"type":"command","ns":"local.oplog.rs","appName":"OplogFetcher","command":{"getMore":2591556819675862000,"collection":"oplog.rs","batchSize":13981010,"maxTimeMS":30000,"term":1,"lastKnownCommittedOpTime":{"ts":{"$timestamp":{"t":1593210322,"i":3053}},"t":1},"$db":"local","$replData":1,"$oplogQueryData":1,"$readPreference":{"mode":"secondaryPreferred"},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1593210322,"i":3053}},"signature":{"hash":{"$binary":{"base64":"qrn1rgkVQ3HB3NIe0kpDEgNR3gE=","subType":"0"}},"keyId":6842786207164793000}}},"originatingCommand":{"find":"oplog.rs","filter":{"ts":{"$gte":{"$timestamp":{"t":1593210320,"i":1}}}},"readConcern":{"level":"local","afterClusterTime":{"$timestamp":{"t":0,"i":1}}},"ntoreturn":13981010,"maxTimeMS":60000,"tailable":true,"awaitData":true,"oplogReplay":true,"term":1,"$db":"local","$replData":1,"$oplogQueryData":1,"$readPreference":{"mode":"secondaryPreferred"},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1593210322,"i":3053}},"signature":{"hash":{"$binary":{"base64":"qrn1rgkVQ3HB3NIe0kpDEgNR3gE=","subType":"0"}},"keyId":6842786207164793000}}},"planSummary":"COLLSCAN","cursorid":2591556819675862000,"keysExamined":0,"docsExamined":0,"numYields":10,"nreturned":0,"reslen":678,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":11}},"Global":{"acquireCount":{"r":11}},"Database":{"acquireCount":{"r":11}},"Mutex":{"acquireCount":{"r":1}},"oplog":{"acquireCount":{"r":11}}},"readConcern":{"level":"local","afterClusterTime":{"$timestamp":{"t":0,"i":1}},"provenance":"clientSupplied"},"storage":{"data":{"bytesRead":7863952,"bytesWritten":207504,"timeReadingMicros":6311,"timeWritingMicros":40},"timeWaitingMicros":{"cache":721293}},"protocol":"op_msg","durationMillis":733} [ReplicaSetFixture:job0:secondary0] | 2020-06-27T01:05:18.512+00:00 W REPL 21122 [BackgroundSync] "Fetcher stopped querying remote oplog with error","attr": { error: "InvalidSyncSource: Sync source must be ahead of me. My last fetched oplog optime: { ts: Timestamp(1593212786, 13), t: 1 }, latest oplog optime of sync source: { ts: Timestamp(1593212786, 13), t: 1 }" }
Another thread that is blocked on the WiredTigerSessionCache mutex:
Thread 31: "decreaseSnapshotHistoryCachePressure" (Thread 0x7fabde4fa700 (LWP 77756)) #0 0x00007fabf3a5b334 in __lll_lock_wait () from /lib64/libpthread.so.0 #1 0x00007fabf3a565d8 in _L_lock_854 () from /lib64/libpthread.so.0 #2 0x00007fabf3a564a7 in pthread_mutex_lock () from /lib64/libpthread.so.0 #3 0x00007fabf7e55588 in __gthread_mutex_lock (__mutex=0x7fabfae04ff0) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/x86_64-mongodb-linux/bits/gthr-default.h:748 #4 std::mutex::lock (this=0x7fabfae04ff0) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/std_mutex.h:103 #5 mongo::latch_detail::Mutex::lock (this=this@entry=0x7fabfae04fd8) at src/mongo/platform/mutex.cpp:56 #6 0x00007fabf61eb414 in std::lock_guard<mongo::latch_detail::Latch>::lock_guard (__m=..., this=<synthetic pointer>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/std_mutex.h:161 #7 mongo::WiredTigerSessionCache::getSession (this=0x7fabfae04f00) at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp:452 #8 0x00007fabf61e372d in mongo::WiredTigerRecoveryUnit::_ensureSession (this=this@entry=0x7fabff550ee0) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:248 #9 0x00007fabf61e3891 in mongo::WiredTigerRecoveryUnit::_ensureSession (this=0x7fabff550ee0) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:318 #10 mongo::WiredTigerRecoveryUnit::getSessionNoTxn (this=0x7fabff550ee0) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:312 #11 0x00007fabf61b620a in mongo::WiredTigerKVEngine::isCacheUnderPressure (this=<optimized out>, opCtx=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:342 #12 0x00007fabf65b3b8f in mongo::SnapshotWindowUtil::decreaseTargetSnapshotWindowSize (opCtx=0x7fabff620d80) at src/mongo/db/snapshot_window_util.cpp:162 #13 0x00007fabf65b22ad in mongo::PeriodicThreadToDecreaseSnapshotHistoryCachePressure::<lambda(mongo::Client*)>::operator() (__closure=<optimized out>, client=<optimized out>) at /opt/mongodbtoolchain/revisions/e5348beb43e147b74a40f4ca5fb05a330ea646cf/stow/gcc-v3.Fno/include/c++/8.2.0/bits/unique_ptr.h:342