[SERVER-40100] Mongos hangs without any log messages Created: 13/Mar/19  Updated: 08/Jan/24  Resolved: 15/Apr/19

Status: Closed
Project: Core Server
Component/s: Internal Code
Affects Version/s: 4.0.4
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Artem Assignee: Eric Sedor
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File bt.txt     Text File mongos.20190317.bt.txt     File mongos.20190317.diagnostics.tgz     Text File mongos.20190318.bt.txt     File mongos.20190318.diagnostic.tgz    
Issue Links:
Duplicate
duplicates SERVER-40110 ClusterCursorManager::CursorEntry::is... Closed
Related
is related to SERVER-40110 ClusterCursorManager::CursorEntry::is... Closed
Operating System: ALL
Steps To Reproduce:

Unknown.

Participants:

 Description   

Symptoms: mongos listen port, but don't serve client requests for few hours (until restart). Nothing suspicious in the logs found.

I was make core dump and backtrace for all threads (backtrace file is attached to this issue).

How often: around twice a month per production environment.

Version:

mongos version v4.0.4
{{ git version: f288a3bdf201007f3693c58e140056adf8b04839}}
{{ OpenSSL version: OpenSSL 1.0.2g 1 Mar 2016}}
{{ allocator: tcmalloc}}
{{ modules: none}}
{{ build environment:}}
{{ distmod: ubuntu1604}}
{{ distarch: x86_64}}
{{ target_arch: x86_64}}

Topology:

  • single shard cluster
  • 3-nodes configuration replicaset;
  • 4-nodes shard replicaset;
  • mongos instance on each client host.


 Comments   
Comment by Artem [ 08/May/19 ]

After removing queries, killed by `maxTimeMS` timeout we had no any hangs.

Comment by Eric Sedor [ 15/Apr/19 ]

bozaro, we believe SERVER-40110 will address this issue. Can you please watch that ticket for updates? Thank you again for your report.

Comment by Eric Sedor [ 19/Mar/19 ]

Thanks bozaro, this is good to know. We are attempting an internal reproduction around lots of queries with $maxTimeMS set.

Comment by Artem [ 19/Mar/19 ]

Looks like we fix query timeouts.

Problem query looks like: `db.someCollection.find({_id: {$in: [... over 20 000 values ...]}}).maxTimeMS(10000)`. And there are all of requested `_id` in database.

Comment by Artem [ 19/Mar/19 ]

The incident with the last backtraces occurred around `2019-03-18T18:47:44.016+0000Z`.

About maxTimeMS: we use this option for almost all queries with timeout 10 sec.

Also, we have increased the timeouts count in recent times due to some features. We are trying to reduce it. It is very likely that this may be related.

Comment by Eric Sedor [ 18/Mar/19 ]

Thanks for the additional information bozaro; we will be attempting an internal reproduction of this.

Can you clarify what time UTC that latest "similar" issue occurred?

In case it helps us, can you let us know if you are setting maxTimeMS for operations, and if so what value you're providing?

Comment by Artem [ 17/Mar/19 ]

Today we got very simillar issue on one host.

Backtraces and diagnostics data was attached.

 

Comment by Mira Carey [ 13/Mar/19 ]

My first theory: in ClusterCursorManager::stats, and specifically ClusterCursorManager::CursorEntry::isKillPending(). See thread 11:

Thread 11 (Thread 0x7fd2289c6700 (LWP 40703)):
#0 __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1 0x00007fd22d9bcdbd in _GI_pthread_mutex_lock (mutex=0x5611e57b2d00) at ../nptl/pthread>
#2 0x00005611e3b1c3c9 in mongo::OperationContext::markKilled(mongo::ErrorCodes::Error) ()
#3 0x00005611e3b1c968 in mongo::OperationContext::checkForInterruptNoAssert() ()
#4 0x00005611e33bb118 in mongo::ClusterCursorManager::stats() const ()
#5 0x00005611e2fc7d0f in mongo::(anonymous namespace)::ClusterCursorStats::appendAtLeaf(mongo>
#6 0x00005611e36aeb4d in mongo::MetricTree::appendTo(mongo::BSONObjBuilder&) const ()
#7 0x00005611e36aecd6 in mongo::MetricTree::appendTo(mongo::BSONObjBuilder&) const ()
#8 0x00005611e35fcc94 in mongo::CmdServerStatus::run(mongo::OperationContext*, std::__cxx11::>
#9 0x00005611e3607b4d in mongo::CommandHelpers::runCommandDirectly(mongo::OperationContext*, >
#10 0x00005611e3309bcd in mongo::FTDCSimpleInternalCommandCollector::collect(mongo::OperationC>
#11 0x00005611e33193f5 in mongo::FTDCCollectorCollection::collect(mongo::Client*) ()

Note that we're in checkForInterruptNoAssert from ClusterCusorManager::stats(), which in turn is calling markKilled.

For why, see isKillPending()

          bool isKillPending() const {
              // A cursor is kill pending if it's checked out by an OperationContext that was
              // interrupted.
              return _operationUsingCursor &&
                  !_operationUsingCursor->checkForInterruptNoAssert().isOK();
          }

That's a problem because:

  • the rule for opCtx is that the owning thread can call all methods, and external threads can call some methods, while holding the client lock
    • ftdc isn't holding the client lock
  • checkForInterruptNoAssert isn't meant to be called from off thread. opCtx->isKillPending() is the way to do that
  • checkForInterrupt can actually invoke markKilled, if the op is now timed out
  • markKilled does a dance with waitForConditionOrInterrupt that, when the latter is active, does:
    • an unlock of the client lock. This probably kicks the system into an unanticipated state
    • a lock of the mutex specified in waitForConditionOrInterrupt
    • a lock of the client lock
    • Setting the killcode
    • unlocking the mutex specified in waitForConditionOrInterrupt

I think this doesn't usually come up because the ops using cluster cursors usually haven't exceeded maxtimems. That may be an avenue for an isolated repro.

Comment by Eric Sedor [ 13/Mar/19 ]

Hello and thanks for the report and backtrace. Can you please also provide the logs leading up to a hang as well as an archive (tar or zip) the $dbpath/diagnostic.data directory (described here)?

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