Uploaded image for project: 'WiredTiger'
  1. WiredTiger
  2. WT-6497

dhandle rwlock deadlock

    • Type: Icon: Bug Bug
    • Resolution: Gone away
    • Priority: Icon: Minor - P4 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
      

            Assignee:
            ravi.giri@mongodb.com Ravi Giri
            Reporter:
            chenhao.qu@mongodb.com Chenhao Qu
            Votes:
            0 Vote for this issue
            Watchers:
            8 Start watching this issue

              Created:
              Updated:
              Resolved: