[SERVER-32876] Don't stall ftdc due to WT cache full Created: 24/Jan/18  Updated: 30/Oct/23  Resolved: 11/Apr/18

Status: Closed
Project: Core Server
Component/s: Diagnostics, WiredTiger
Affects Version/s: None
Fix Version/s: 3.4.14, 3.6.5, 3.7.4

Type: Bug Priority: Critical - P2
Reporter: Bruce Lucas (Inactive) Assignee: Michael Cahill (Inactive)
Resolution: Fixed Votes: 2
Labels: SWDI
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File poc34.diff     File poc36.diff    
Issue Links:
Backports
Depends
depends on WT-3981 Make snapshot consistent with read_ti... Closed
depends on WT-3926 Allow read_timestamp to be set after ... Closed
is depended on by SERVER-32236 Avoid stalling ftdc when system is st... Closed
is depended on by SERVER-33191 Cache-full hangs on 3.6 Closed
Problem/Incident
Related
related to SERVER-55652 dbStats command can fail if an index ... Closed
is related to SERVER-34590 oplog visibility issues with round_to... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v3.6, v3.4
Sprint: Storage 2018-02-12, Storage 2018-02-26, Storage Non-NYC 2018-03-12, Storage Non-NYC 2018-03-26, Storage Non-NYC 2018-04-09, Storage Non-NYC 2018-04-23
Participants:
Linked BF Score: 45

 Comments   
Comment by Githook User [ 26/Apr/18 ]

Author:

{'email': 'michael.cahill@mongodb.com', 'username': 'michaelcahill', 'name': 'Michael Cahill'}

Message: SERVER-32876 Don't stall ftdc due to WT cache full.

(cherry picked from commit e96569ea3b7644fb7c60cb47df90e7dc369ea957)
Branch: v3.6
https://github.com/mongodb/mongo/commit/527a7130a83cf37af81e2424910a6be0fdb51c49

Comment by Githook User [ 11/Apr/18 ]

Author:

{'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}

Message: SERVER-32876 Don't stall ftdc due to WT cache full.
Branch: master
https://github.com/mongodb/mongo/commit/e96569ea3b7644fb7c60cb47df90e7dc369ea957

Comment by Esha Maharishi (Inactive) [ 16/Mar/18 ]

Thank you!

Comment by Githook User [ 15/Mar/18 ]

Author:

{'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}

Message: Revert "SERVER-32876 Avoid FTDC stalls when the WT cache is full."

This reverts commit 864e2e71c39d1e39ff0d1e8575a02b8afebb8a7b.
Branch: v3.6
https://github.com/mongodb/mongo/commit/5d4887d65850f2c1bdb8b2168f348752a1db5015

Comment by Githook User [ 15/Mar/18 ]

Author:

{'email': 'daniel.gottlieb@mongodb.com', 'name': 'Daniel Gottlieb', 'username': 'dgottlieb'}

Message: Revert "SERVER-32876 Avoid FTDC stalls when the WT cache is full."

This reverts commit 1924211418e478d1e8bb84cfdf0eab4b777371e1.
This reverts commit 368d9a39e91a0b58898be714b06cd0dfb19d6851.
Branch: master
https://github.com/mongodb/mongo/commit/ab7e4e3598c631a0b01ae10b76b60ee90df19866

Comment by Githook User [ 15/Mar/18 ]

Author:

{'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}

Message: SERVER-32876 Avoid FTDC stalls when the WT cache is full.

(cherry picked from commit 1924211418e478d1e8bb84cfdf0eab4b777371e1)
Branch: v3.6
https://github.com/mongodb/mongo/commit/864e2e71c39d1e39ff0d1e8575a02b8afebb8a7b

Comment by Githook User [ 15/Mar/18 ]

Author:

{'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}

Message: SERVER-32876 Fix comment typo.
Branch: master
https://github.com/mongodb/mongo/commit/368d9a39e91a0b58898be714b06cd0dfb19d6851

Comment by Githook User [ 15/Mar/18 ]

Author:

{'email': 'michael.cahill@mongodb.com', 'name': 'Michael Cahill', 'username': 'michaelcahill'}

Message: SERVER-32876 Avoid FTDC stalls when the WT cache is full.
Branch: master
https://github.com/mongodb/mongo/commit/1924211418e478d1e8bb84cfdf0eab4b777371e1

Comment by Githook User [ 12/Mar/18 ]

Author:

{'email': 'kelsey@mongodb.com', 'name': 'Kelsey Schubert', 'username': 'Schubes'}

Message: SERVER-32876 Don't stall ftdc due to WT cache full
Branch: v3.4
https://github.com/mongodb/mongo/commit/c3860652ccb14862b132d95df4f034230c7423e1

Comment by Githook User [ 10/Mar/18 ]

Author:

{'email': 'maria@mongodb.com', 'name': 'Maria van Keulen', 'username': 'mvankeulen94'}

Message: Revert "SERVER-32876 Use non-transactional WT session in fast paths to avoid FTDC stall"

This reverts commit d368f071651856039f2637202c122b1a55a44142.
Branch: master
https://github.com/mongodb/mongo/commit/ffde025012ca20c0376a22e3a0f52c1887d03a70

Comment by Githook User [ 07/Mar/18 ]

Author:

{'email': 'neha.khatr@mongodb.com', 'name': 'nehakhatri5'}

Message: SERVER-32876 Use non-transactional WT session in fast paths to avoid FTDC stall
Branch: master
https://github.com/mongodb/mongo/commit/d368f071651856039f2637202c122b1a55a44142

Comment by Michael Cahill (Inactive) [ 21/Feb/18 ]

I think WT-3926 will give us a way to decouple blocking for eviction from read timestamp allocation, which was the only contentious part of the POC here. As a bonus, it should improve performance (both because eviction is happening outside the lock and because the read timestamp is allocated closer to when it is used).

Once that change is in, getting the POC in to code review should be straightforward.

cc bruce.lucas

Comment by Michael Cahill (Inactive) [ 29/Jan/18 ]

alexander.gorrod, since the changes now contemplated here are storage-only, can you please figure out next steps?

Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ]

The FTDC stall repro works on master as well. The 5 POC fixes in poc36.diff apply cleanly to master, and fix the FTDC stalls.

(Note that poc36.diff also includes the change to wiredtiger_open to disable LAS for testing purposes, and is not one of the 5 fixes. This does needs a small tweak to apply.)

Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ]

Another way to create FTDC stalls due to cache full is to configure a largish cache, allow it to fill, then reduce the cache size with setParameter, e.g.

db.adminCommand({setParameter: 1, "wiredTigerEngineRuntimeConfig": "cache_size=100M"})

This will create an FTDC stall of a few seconds (depending on the originally configured cache size and disk speed). I ran with a loop setting large cache, allowing it to fill, then reducing the cache size, and observed an FTDC stall each time on 3.6 (with LAS disabled as above). With the POC changes from poc36.diff there were no FTDC stalls through a couple dozen iterations of cache-full.

Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ]

FIX 5

FTDC is stuck waiting for access to ReplicationCoordinatorImpl to get repl info:

#0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x00007f95a59bccfd in __GI___pthread_mutex_lock (mutex=0x56182eca2008) at ../nptl/pthread_mutex_lock.c:80
#2  0x000056182a420ba7 in mongo::repl::ReplicationCoordinatorImpl::fillIsMasterForReplSet(mongo::repl::IsMasterResponse*) ()
#3  0x000056182a09e224 in mongo::repl::appendReplicationInfo(mongo::OperationContext*, mongo::BSONObjBuilder&, int) ()
#4  0x000056182a0a1d16 in mongo::repl::ReplicationInfoServerStatus::generateSection(mongo::OperationContext*, mongo::BSONElement const&) const ()
#5  0x0000561829d4ac2a in mongo::ServerStatusSection::appendSection(mongo::OperationContext*, mongo::BSONElement const&, mongo::BSONObjBuilder*) const ()
#6  0x000056182ae4768f in mongo::CmdServerStatus::run(mongo::OperationContext*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, mongo::BSONObj const&, mongo::BSONObjBuilder&) ()
#7  0x000056182ae95576 in mongo::BasicCommand::enhancedRun(mongo::OperationContext*, mongo::OpMsgRequest const&, mongo::BSONObjBuilder&) ()
#8  0x000056182ae9048f in mongo::Command::publicRun(mongo::OperationContext*, mongo::OpMsgRequest const&, mongo::BSONObjBuilder&) ()
#9  0x000056182ae934e6 in mongo::Command::runCommandDirectly(mongo::OperationContext*, mongo::OpMsgRequest const&) ()
#10 0x000056182ac5fffd in mongo::FTDCSimpleInternalCommandCollector::collect(mongo::OperationContext*, mongo::BSONObjBuilder&) ()
#11 0x000056182ac6c993 in mongo::FTDCCollectorCollection::collect(mongo::Client*) ()

ReplicationCoordinatorImpl is tied up by a thread that is waiting for a lock in WiredTigerSnapshotManager:

#0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x00007f95a59bccfd in __GI___pthread_mutex_lock (mutex=0x56182edc4b58) at ../nptl/pthread_mutex_lock.c:80
#2  0x0000561829da8609 in mongo::WiredTigerSnapshotManager::setCommittedSnapshot(mongo::Timestamp const&) ()
#3  0x000056182a09732d in mongo::repl::ReplicationCoordinatorExternalStateImpl::updateCommittedSnapshot(mongo::repl::OpTime const&) ()
#4  0x000056182a423089 in mongo::repl::ReplicationCoordinatorImpl::_updateCommittedSnapshot_inlock(mongo::repl::OpTime const&) ()
#5  0x000056182a42d446 in mongo::repl::ReplicationCoordinatorImpl::_setStableTimestampForStorage_inlock() ()
#6  0x000056182a42d554 in mongo::repl::ReplicationCoordinatorImpl::_updateLastCommittedOpTime_inlock() ()
#7  0x000056182a42e5a2 in mongo::repl::ReplicationCoordinatorImpl::_setLastOptime_inlock(mongo::repl::UpdatePositionArgs::UpdateInfo const&, long long*) ()
#8  0x000056182a42ed57 in mongo::repl::ReplicationCoordinatorImpl::processReplSetUpdatePosition(mongo::repl::UpdatePositionArgs const&, long long*) ()
#9  0x0000561829d6fad0 in mongo::repl::CmdReplSetUpdatePosition::run(mongo::OperationContext*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, mongo::BSONObj const&, mongo::BSONObjBuilder&) ()

WiredTigerSnapshotManager is tied up by a thread that's holding a lock while trying to start a transaction while the cache is full:

#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x0000561829ddfdc9 in __wt_cond_wait_signal ()
#2  0x0000561829dcad81 in __wt_cache_eviction_worker ()
#3  0x0000561829e06c6a in ?? ()
#4  0x0000561829da8ba2 in mongo::WiredTigerSnapshotManager::beginTransactionOnOplog(mongo::WiredTigerOplogManager*, __wt_session*) const ()
#5  0x0000561829da5b7e in mongo::WiredTigerRecoveryUnit::_txnOpen() ()
#6  0x0000561829da5e37 in mongo::WiredTigerRecoveryUnit::getSession() ()
#7  0x0000561829d9706a in mongo::WiredTigerRecordStoreCursorBase::restore() ()
#8  0x000056182a504871 in mongo::CollectionScan::doRestoreState() ()
#9  0x000056182a30d039 in mongo::PlanExecutor::restoreStateWithoutRetrying() ()
#10 0x000056182a315ef2 in mongo::PlanYieldPolicy::yield(std::function<void ()>, std::function<void ()>) ()
#11 0x000056182a315bea in mongo::PlanYieldPolicy::yield(mongo::RecordFetcher*) ()
#12 0x000056182a30e0a1 in mongo::PlanExecutor::getNextImpl(mongo::Snapshotted<mongo::BSONObj>*, mongo::RecordId*) ()
#13 0x000056182a30e8cb in mongo::PlanExecutor::getNext(mongo::BSONObj*, mongo::RecordId*) ()

Looking at beginTransactionOnOplog, I'm not sure whether that lock actually needs to be held while we start the transaction, or whether it's even needed at all.

Is it possible that that lock could be functionally problematic: if _txnOpen can block due to cache full while holding a lock on WiredTigerSnapshotManager (and thus on ReplicationCoordinatorImpl), could that prevent access to WiredTigerSnapshotManager and ReplicationCoordinatorImpl that will help us get unstuck?

For the POC I changed beginTransactionOnOplog to drop the lock just before starting the transaction, and that prevented FTDC from getting stalled; TBD whether this is a safe change.

Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ]

FIX 4

FTDC can stall due to full cache in syncSizeInfo on releaseSession in 3.6 (and probably 3.4 as well):

#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x0000560fab9cede9 in __wt_cond_wait_signal ()
#2  0x0000560fab9b9da1 in __wt_cache_eviction_worker ()
#3  0x0000560fab9f5c8a in ?? ()
#4  0x0000560fab9999f6 in mongo::WiredTigerSizeStorer::syncCache(bool) ()
#5  0x0000560fab9799e9 in mongo::WiredTigerKVEngine::syncSizeInfo(bool) const ()
#6  0x0000560fab97d235 in mongo::WiredTigerKVEngine::haveDropsQueued() const ()
#7  0x0000560fab9969e8 in mongo::WiredTigerSessionCache::releaseSession(mongo::WiredTigerSession*) ()
#8  0x0000560fab994a91 in mongo::WiredTigerRecoveryUnit::~WiredTigerRecoveryUnit() ()
#9  0x0000560facfcd166 in mongo::ServiceContext::OperationContextDeleter::operator()(mongo::OperationContext*) const ()
#10 0x0000560fac85c250 in mongo::FTDCCollectorCollection::collect(mongo::Client*) ()
#11 0x0000560fac85fcc9 in mongo::FTDCController::doLoop() ()
#12 0x0000560fad217ca0 in ?? ()
#13 0x00007f24224df6aa in start_thread (arg=0x7f241b0ff700) at pthread_create.c:333
#14 0x00007f242221513d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

I don't know why I didn't hit this one in 3.4; I couldn't readily see a difference in the code, so maybe it was just a matter of luck, and this could occur in 3.4 as well.

I imagine this can't be solved by avoiding a transaction, correct?

It can be avoided by a flag to opt out of doing syncSizeInfo in this case, or perhaps better opt out of haveDropsQueued entirely as processing queued drops in the FTDC thread could cause the same problem. I didn't try to work out the best way to pass such a flag, but rather just commented out the call to haveDropsQueued. This disabled syncSizeInfo entirely, but since it is only called occasionally I don't think that invalidates the test.

Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ]

So I was able to get stuck with cache full in 3.6 by setting WT_CONN_EVICTION_NO_LOOKASIDE in wiredtiger_open (thanks for the suggestion keith@wiredtiger.com) and then running the same repro as 3.4 (heavy insert workload, induce lag). I also set eviction_dirty_trigger=95,eviction_trigger=95,eviction_target=94; not completely sure why this helped with the repro, but maybe it just allowed more lag to build up before primary hit cache full, increasing changes of a hang.

I hit the same 3 stalls as in 3.4, and did similar 3 fixes. Then I hit two more problems and prototyped fixes (POC attached as poc36.diff). For clarity I'll describe fixes 4 and 5 in subsequent comments.

With these 5 fixes FTDC does not stall in my test when we hit cache full in 3.6.

Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ]

Regarding reproducing it in 3.6 - is there a parameter setting to disable or discourage LAS use? This might give us a way to artificially create a stuck with cache full condition as this should behave similarly to 3.4.

Comment by Bruce Lucas (Inactive) [ 25/Jan/18 ]

workloads that reproduce the symptoms

In 3.4 it is not hard to reproduce FTDC stall due to full WT cache: start a replica set with --enableMajorityReadConcern with a smallish cache, start a heavy insert workload, and do something to induce lag - I accomplished this by putting the secondaries on a spinning disk while the primary is on ssd. This will get the repl set stuck with primary cache full due to lag which stalls replication as well preventing it from recovering. I don't know how to do it in 3.6, but we have seen it happen.

This makes it seem like changing getSession to getSessionNoTxn in WiredTigerRecordStore::storageSize would help a lot. We should try that, but I expect it will just uncover the next operation in FTDC that blocks when the WT cache is full.

You are correct. I made the change you suggest in 3.4, reproduced stuck with cache full as described above, and uncovered two more places (all in _txnOpen from CollectionStats) that were also fixed by using getSessionNoTxn. POC attached; with these changes FTDC does not stall with cache full in 3.4. Not at all sure this is the best way to do it, particularly the third case which addresses this stack:

#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x0000558708dda369 in __wt_cond_wait_signal (session=session@entry=0x55870be396e8, cond=0x55870ba02b00, usecs=usecs@entry=10000, run_func=run_func@entry=0x0, signalled=signalled@entry=0x7f66a3786a00) at src/third_party/wiredtiger/src/os_posix/os_mtx_cond.c:114
#2  0x0000558708db0634 in __wt_cond_wait (run_func=0x0, usecs=10000, cond=<optimized out>, session=0x55870be396e8) at src/third_party/wiredtiger/src/include/misc.i:19
#3  __wt_cache_eviction_worker (session=session@entry=0x55870be396e8, busy=<optimized out>, pct_full=<optimized out>) at src/third_party/wiredtiger/src/evict/evict_lru.c:2285
#4  0x0000558708e0d19b in __wt_cache_eviction_check (busy=<optimized out>, didworkp=0x0, session=0x55870be396e8) at src/third_party/wiredtiger/src/include/cache.i:398
#5  __wt_txn_begin (cfg=0x7f66a3786a70, session=0x55870be396e8) at src/third_party/wiredtiger/src/include/txn.i:261
#6  __session_begin_transaction (wt_session=0x55870be396e8, config=<optimized out>) at src/third_party/wiredtiger/src/session/session_api.c:1411
#7  0x0000558708154212 in mongo::WiredTigerRecoveryUnit::_txnOpen (this=this@entry=0x55870f2dfa80, opCtx=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:244
#8  0x00005587081545c0 in mongo::WiredTigerRecoveryUnit::getSession (opCtx=<optimized out>, this=0x55870f2dfa80) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:168
#9  mongo::WiredTigerCursor::WiredTigerCursor (this=0x7f66a3786ca0, uri=..., tableId=0, forRecordStore=<optimized out>, txn=<optimized out>) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:267
#10 0x000055870815dadf in mongo::WiredTigerUtil::getMetadata[abi:cxx11](mongo::OperationContext*, mongo::StringData) (opCtx=opCtx@entry=0x55870ba2f340, uri=...) at src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp:106
#11 0x0000558708161e05 in mongo::WiredTigerUtil::getApplicationMetadata (opCtx=opCtx@entry=0x55870ba2f340, uri=..., bob=bob@entry=0x7f66a3787020) at src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp:130
#12 0x000055870814a373 in mongo::WiredTigerRecordStore::appendCustomStats (this=0x55870f803200, txn=0x55870ba2f340, result=<optimized out>, scale=1) at src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp:1629
#13 0x0000558708042aae in mongo::appendCollectionStorageStats (txn=txn@entry=0x55870ba2f340, nss=..., param=..., result=result@entry=0x7f66a37876f0) at src/mongo/db/stats/storage_stats.cpp:82
#14 0x0000558707948d35 in mongo::CollectionStats::run (this=<optimized out>, txn=0x55870ba2f340, dbname=..., jsobj=..., errmsg=..., result=...) at src/mongo/db/commands/dbcommands.cpp:1010
#15 0x0000558707ac8f12 in mongo::(anonymous namespace)::FTDCSimpleInternalCommandCollector::collect (this=<optimized out>, txn=<optimized out>, builder=...) at src/mongo/db/ftdc/ftdc_mongod.cpp:264
#16 0x0000558707abd7a4 in mongo::FTDCCollectorCollection::collect (this=this@entry=0x55870b9ee4d0, client=client@entry=0x55870bc91400) at src/mongo/db/ftdc/collector.cpp:88
#17 0x0000558707ac131d in mongo::FTDCController::doLoop (this=0x55870b9ee400) at src/mongo/db/ftdc/controller.cpp:217
#18 0x0000558708ea1450 in std::execute_native_thread_routine (__p=<optimized out>) at ../../../../../gcc-5.4.0/libstdc++-v3/src/c++11/thread.cc:84
#19 0x00007f66aa3676aa in start_thread (arg=0x7f66a3788700) at pthread_create.c:333
#20 0x00007f66aa09d13d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

TBD whether this applies to 3.6 and master.

Comment by Michael Cahill (Inactive) [ 25/Jan/18 ]

I did some quick analysis of stack traces I have lying around from working on various issues. This isn't intended to be comprehensive, it's literally just a sample of what I had easily to hand.

This makes it seem like changing getSession to getSessionNoTxn in WiredTigerRecordStore::storageSize would help a lot. We should try that, but I expect it will just uncover the next operation in FTDC that blocks when the WT cache is full.

Here are some places where the FTDC thread can block:

   4 pthread_cond_timedwait@@GLIBC_2.3.2,
     mongo::CondVarLockGrantNotification::wait(unsigned,
     mongo::LockerImpl<false>::lockComplete(mongo::ResourceId,
     mongo::Lock::GlobalLock::waitForLock(unsigned,
     mongo::Lock::GlobalLock::GlobalLock(mongo::Locker*,
     mongo::Lock::DBLock::DBLock(mongo::Locker*,
     mongo::AutoGetDb::AutoGetDb(mongo::OperationContext*,
     mongo::AutoGetCollection::AutoGetCollection(mongo::OperationContext*,
     mongo::AutoGetCollectionForRead::AutoGetCollectionForRead(mongo::OperationContext*,
     mongo::appendCollectionStorageStats(mongo::OperationContext*,
     mongo::CollectionStats::run(mongo::OperationContext*mongo::(anonymous,
     mongo::FTDCCollectorCollection::collect(mongo::Client*),
     mongo::FTDCController::doLoop()execute_native_thread_routinestart_thread,
     clone
   3 pthread_cond_timedwait@@GLIBC_2.3.2__wt_cond_wait_signal,
     __wt_cache_eviction_worker__session_begin_transaction,
     mongo::WiredTigerRecoveryUnit::_txnOpen(mongo::OperationContext*),
     mongo::WiredTigerRecoveryUnit::getSession(mongo::OperationContext*),
     mongo::WiredTigerRecordStore::storageSize(mongo::OperationContext*,
     mongo::appendCollectionStorageStats(mongo::OperationContext*,
     mongo::CollectionStats::run(mongo::OperationContext*mongo::(anonymous,
     mongo::FTDCCollectorCollection::collect(mongo::Client*),
     mongo::FTDCController::doLoop()execute_native_thread_routinestart_thread,
     clone
   2 __lll_lock_wait_L_lock_854pthread_mutex_lock__evict_page,
     __wt_cache_eviction_worker__session_begin_transaction,
     mongo::WiredTigerRecoveryUnit::_txnOpen(mongo::OperationContext*),
     mongo::WiredTigerRecoveryUnit::getSession(mongo::OperationContext*),
     mongo::WiredTigerRecordStore::storageSize(mongo::OperationContext*,
     mongo::CollectionStats::run(mongo::OperationContext*mongo::(anonymous,
     mongo::FTDCCollectorCollection::collect(mongo::Client*),
     mongo::FTDCController::doLoop()execute_native_thread_routinestart_thread,
     clone
   1 sem_waitmongo::TicketHolder::waitForTicket(),
     mongo::LockerImpl<false>::lockGlobalBegin(mongo::LockMode),
     mongo::Lock::GlobalLock::_enqueue(mongo::LockMode),
     mongo::Lock::GlobalLock::GlobalLock(mongo::Locker*,
     mongo::Lock::GlobalLock::GlobalLock(mongo::Locker*,
     mongo::Lock::DBLock::DBLock(mongo::Locker*,
     mongo::AutoGetDb::AutoGetDb(mongo::OperationContext*,
     mongo::AutoGetCollection::AutoGetCollection(mongo::OperationContext*,
     mongo::AutoGetCollectionForRead::AutoGetCollectionForRead(mongo::OperationContext*,
mongo::appendCollectionStorageStats(mongo::OperationContext*,
     mongo::CollectionStats::run(mongo::OperationContext*mongo::(anonymous,
     mongo::FTDCCollectorCollection::collect(mongo::Client*),
     mongo::FTDCController::doLoop()execute_native_thread_routinestart_thread,
     lseek64??
   1 sem_waitmongo::TicketHolder::waitForTicket(),
     mongo::LockerImpl<false>::lockGlobalBegin(mongo::LockMode),
     mongo::Lock::GlobalLock::_enqueue(mongo::LockMode),
     mongo::Lock::GlobalLock::GlobalLock(mongo::Locker*,
     mongo::Lock::GlobalLock::GlobalLock(mongo::Locker*,
     mongo::Lock::DBLock::DBLock(mongo::Locker*,
     mongo::AutoGetDb::AutoGetDb(mongo::OperationContext*,
     mongo::AutoGetCollection::AutoGetCollection(mongo::OperationContext*,
     mongo::AutoGetCollectionForRead::AutoGetCollectionForRead(mongo::OperationContext*,
     mongo::CollectionStats::run(mongo::OperationContext*mongo::(anonymous,
     mongo::FTDCCollectorCollection::collect(mongo::Client*),
     mongo::FTDCController::doLoop()execute_native_thread_routinestart_thread,
     clone
   1 pthread_cond_timedwait@@GLIBC_2.3.2__wt_cond_wait_signal,
     __wt_cache_eviction_worker__session_begin_transaction,
     mongo::WiredTigerRecoveryUnit::_txnOpen(),
     mongo::WiredTigerRecoveryUnit::getSession(),
     mongo::WiredTigerRecordStore::storageSize(mongo::OperationContext*,
     mongo::appendCollectionStorageStats(mongo::OperationContext*,
     mongo::CollectionStats::errmsgRun(mongo::OperationContext*,
     mongo::ErrmsgCommandDeprecated::run(mongo::OperationContext*,
     mongo::BasicCommand::enhancedRun(mongo::OperationContext*,
     mongo::Command::publicRun(mongo::OperationContext*,
     mongo::Command::runCommandDirectly(mongo::OperationContext*,
     mongo::FTDCSimpleInternalCommandCollector::collect(mongo::OperationContext*,
     mongo::FTDCCollectorCollection::collect(mongo::Client*),
     mongo::FTDCController::doLoop()execute_native_thread_routinestart_thread,
     clone
   1 pthread_cond_timedwait@@GLIBC_2.3.2__wt_cond_wait_signal,
     __wt_cache_eviction_worker??,
     mongo::WiredTigerRecoveryUnit::_txnOpen(mongo::OperationContext*),
     mongo::WiredTigerRecoveryUnit::getSession(mongo::OperationContext*),
     mongo::WiredTigerRecordStore::storageSize(mongo::OperationContext*,
     mongo::appendCollectionStorageStats(mongo::OperationContext*,
     mongo::CollectionStats::run(mongo::OperationContext*??,
     mongo::FTDCCollectorCollection::collect(mongo::Client*),
     mongo::FTDCController::doLoop()execute_native_thread_routinestart_thread,
     clone
   1 base::internal::SpinLockDelay(intSpinLock::SlowLock()tc_realloc,
     __realloc_func__wt_realloc_aligned__wt_buf_grow_worker__rec_split_init,
     __rec_row_leaf__wt_reconcile__wt_evict__evict_page,
     __wt_cache_eviction_worker__session_begin_transaction,
     mongo::WiredTigerRecoveryUnit::_txnOpen(mongo::OperationContext*),
     mongo::WiredTigerRecoveryUnit::getSession(mongo::OperationContext*),
     mongo::WiredTigerRecordStore::storageSize(mongo::OperationContext*,
     mongo::appendCollectionStorageStats(mongo::OperationContext*,
     mongo::CollectionStats::run(mongo::OperationContext*mongo::(anonymous,
     mongo::FTDCCollectorCollection::collect(mongo::Client*),
     mongo::FTDCController::doLoop()execute_native_thread_routinestart_thread,
     clone
   1 pthread_cond_timedwait@@GLIBC_2.3.2mongo::FTDCController::doLoop(),
     execute_native_thread_routinestart_threadclone

Comment by Alexander Gorrod [ 25/Jan/18 ]

There were some relevant questions asked about this topic off ticket - bringing the conversation here:

Can we implement ignore_cache_size (WT-2932) for the non-in-memory case to allow us to read collection stats even if cache is full?

We can do something similar, but it's not trivial, since there are different cases that can block most of which aren't actually due to using the actual statistics cursor. A few cases I'm aware of are:

  • When retrieving a session, a transaction is started which can block
  • Gathering oplog statistics issue queries to find the first and last entries from MongoDB which can block.

Is there a way to return an error if cache is full, maybe after a timeout, so we may miss collection stats but won't get completely stuck?

That is possible, and I've been thinking about it recently. It's quite an invasive change in terms of how applications that use WiredTiger need to do error handling, and will require a configuration setting to control the timeout period. Getting the design decisions correct will require conversation, so a fast turnaround is probably not possible on this approach.

Comment by Alexander Gorrod [ 25/Jan/18 ]

bruce.lucas It would be very useful to have access to either workloads that reproduce the symptoms we are trying to avoid, or call stacks from a system while it is stalled. Do you know where we could find either of those?

Generated at Thu Feb 08 04:31:34 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.