Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-21366

Long-running transactions in MigrateStatus::apply

    • Type: Icon: Improvement Improvement
    • Resolution: Won't Fix
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.0.7
    • Component/s: Sharding
    • None
    • Sharding
    • Sharding D (12/11/15)

      In a sharded scenario involving chunk moves, inserts, and deletes (via TTL) we observe WT "range of pinned ids" statistic growing, indicating long-running transactions. Added this patch to look for transactions taking >100ms.

      diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp
      index 58cdefc..c0a406c 100644
      --- a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp
      +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp
      @@ -253,9 +253,15 @@ void WiredTigerRecoveryUnit::_txnClose(bool commit) {
           invariant(_active);
           WT_SESSION* s = _session->getSession();
           if (commit) {
      +        if (_timer.millis() >= 100)
      +            log() << "XXX commiting; _timer.millis() " << _timer.millis();
      +        wassert(_timer.millis() < 100);
               invariantWTOK(s->commit_transaction(s, NULL));
               LOG(2) << "WT commit_transaction";
           } else {
      +        if (_timer.millis() >= 100)
      +            log() << "XXX rolling back; _timer.millis() " << _timer.millis();
      +        wassert(_timer.millis() < 100);
               invariantWTOK(s->rollback_transaction(s, NULL));
               LOG(2) << "WT rollback_transaction";
           }
      

      Here was the longest, a transaction that ran for about 23 s:

      2015-11-09T13:58:05.984-0500 I STORAGE  [migrateThread] XXX rolling back; _timer.millis() 23047
      2015-11-09T13:58:05.984-0500 I -        [migrateThread] warning assertion failure _timer.millis() < 100 src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp 264
      2015-11-09T13:58:05.990-0500 I CONTROL  [migrateThread] 
       0xf62172 0xf0b329 0xeeef6b 0xd87f6b 0xdf3e64 0xe03619 0xe04fdc 0xdf0c79 0xdf1f0d 0xfb154f 0x7f212d8e7182 0x7f212c9e847d
      ----- BEGIN BACKTRACE -----
      {"backtrace":[{"b":"400000","o":"B62172"},{"b":"400000","o":"B0B329"},{"b":"400000","o":"AEEF6B"},{"b":"400000","o":"987F6B"},{"b":"400000","o":"9F3E64"},{"b":"400000","o":"A03619"},{"b":"400000","o":"A04FDC"},{"b":"400000","o":"9F0C79"},{"b":"400000","o":"9F1F0D"},{"b":"400000","o":"BB154F"},{"b":"7F212D8DF000","o":"8182"},{"b":"7F212C8EE000","o":"FA47D"}],"processInfo":{ "mongodbVersion" : "3.0.8-pre-", "gitVersion" : "d4f8d4b2a576160348de61f972fa478a845234fd", "uname" : { "sysname" : "Linux", "release" : "3.13.0-32-generic", "version" : "#57-Ubuntu SMP Tue Jul 15 03:51:08 UTC 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000", "buildId" : "83C5D7336ECF9A76049E8DE24FC106DEF6241FF9" }, { "b" : "7FFFA00FE000", "elfType" : 3, "buildId" : "E464DBB7341B7B9E7874DC0619C5F429416E6AC6" }, { "b" : "7F212D8DF000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "9318E8AF0BFBE444731BB0461202EF57F7C39542" }, { "b" : "7F212D6D7000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "92FCF41EFE012D6186E31A59AD05BDBB487769AB" }, { "b" : "7F212D4D3000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "C1AE4CB7195D337A77A3C689051DABAA3980CA0C" }, { "b" : "7F212D1CF000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3, "buildId" : "4BF6F7ADD8244AD86008E6BF40D90F8873892197" }, { "b" : "7F212CEC9000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "1D76B71E905CB867B27CEF230FCB20F01A3178F5" }, { "b" : "7F212CCB3000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "CC0D578C2E0D86237CA7B0CE8913261C506A629A" }, { "b" : "7F212C8EE000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "30C94DC66A1FE95180C3D68D2B89E576D5AE213C" }, { "b" : "7F212DAFD000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "9F00581AB3C73E3AEA35995A0C50D24D59A01D47" } ] }}
       mongod(_ZN5mongo15printStackTraceERSo+0x32) [0xf62172]
       mongod(_ZN5mongo10logContextEPKc+0xE9) [0xf0b329]
       mongod(_ZN5mongo9wassertedEPKcS1_j+0x19B) [0xeeef6b]
       mongod(_ZN5mongo22WiredTigerRecoveryUnit9_txnCloseEb+0x3DB) [0xd87f6b]
       mongod(_ZN5mongo13MigrateStatus5applyEPNS_16OperationContextERKSsNS_7BSONObjES5_S5_RKS5_Py+0x9B4) [0xdf3e64]
       mongod(_ZN5mongo13MigrateStatus3_goEPNS_16OperationContextERKSsNS_7BSONObjES5_S5_S4_RKNS_3OIDERKNS_19WriteConcernOptionsE+0x2309) [0xe03619]
       mongod(_ZN5mongo13MigrateStatus2goEPNS_16OperationContextERKSsNS_7BSONObjES5_S5_S4_RKNS_3OIDERKNS_19WriteConcernOptionsE+0xCC) [0xe04fdc]
       mongod(_ZN5mongo13migrateThreadESsNS_7BSONObjES0_S0_SsNS_3OIDENS_19WriteConcernOptionsE+0x109) [0xdf0c79]
       mongod(_ZN5boost6detail11thread_dataINS_3_bi6bind_tIvPFvSsN5mongo7BSONObjES5_S5_SsNS4_3OIDENS4_19WriteConcernOptionsEENS2_5list7INS2_5valueISsEENSB_IS5_EESD_SD_SC_NSB_IS6_EENSB_IS7_EEEEEEE3runEv+0x11D) [0xdf1f0d]
       mongod(+0xBB154F) [0xfb154f]
       libpthread.so.0(+0x8182) [0x7f212d8e7182]
       libc.so.6(clone+0x6D) [0x7f212c9e847d]
      -----  END BACKTRACE  -----
      

      addr2line:

      mongo::printStackTrace(std::ostream&) at src/mongo/util/stacktrace_posix.cpp:105
      mongo::logContext(char const*) at src/mongo/util/log.cpp:134 (discriminator 1)
      mongo::wasserted(char const*, char const*, unsigned int) at src/mongo/util/assert_util.cpp:119
      mongo::WiredTigerRecoveryUnit::_txnClose(bool) at src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp:264 (discriminator 1)
      mongo::MigrateStatus::apply(mongo::OperationContext*, std::string const&, mongo::BSONObj, mongo::BSONObj, mongo::BSONObj, mongo::BSONObj const&, unsigned long long*) at src/mongo/s/d_migrate.cpp:2411
      ~intrusive_ptr at src/third_party/boost/boost/smart_ptr/intrusive_ptr.hpp:96
       (inlined by) ~SharedBuffer at src/mongo/util/shared_buffer.h:38
       (inlined by) ~BSONObj at src/mongo/bson/bsonobj.h:90
       (inlined by) mongo::MigrateStatus::_go(mongo::OperationContext*, std::string const&, mongo::BSONObj, mongo::BSONObj, mongo::BSONObj, std::string const&, mongo::OID const&, mongo::WriteConcernOptions const&) at src/mongo/s/d_migrate.cpp:2209
      ~intrusive_ptr at src/third_party/boost/boost/smart_ptr/intrusive_ptr.hpp:96
       (inlined by) ~SharedBuffer at src/mongo/util/shared_buffer.h:38
       (inlined by) ~BSONObj at src/mongo/bson/bsonobj.h:90
       (inlined by) mongo::MigrateStatus::go(mongo::OperationContext*, std::string const&, mongo::BSONObj, mongo::BSONObj, mongo::BSONObj, std::string const&, mongo::OID const&, mongo::WriteConcernOptions const&) at src/mongo/s/d_migrate.cpp:1870
      ~intrusive_ptr at src/third_party/boost/boost/smart_ptr/intrusive_ptr.hpp:96
       (inlined by) ~SharedBuffer at src/mongo/util/shared_buffer.h:38
       (inlined by) ~BSONObj at src/mongo/bson/bsonobj.h:90
       (inlined by) mongo::migrateThread(std::string, mongo::BSONObj, mongo::BSONObj, mongo::BSONObj, std::string, mongo::OID, mongo::WriteConcernOptions) at src/mongo/s/d_migrate.cpp:2635
      ~basic_string at /usr/include/c++/4.8/bits/basic_string.h:539
       (inlined by) operator()<void (*)(std::basic_string<char>, mongo::BSONObj, mongo::BSONObj, mongo::BSONObj, std::basic_string<char>, mongo::OID, mongo::WriteConcernOptions), boost::_bi::list0> at src/third_party/boost/boost/bind/bind.hpp:670
       (inlined by) boost::_bi::bind_t<void, void (*)(std::string, mongo::BSONObj, mongo::BSONObj, mongo::BSONObj, std::string, mongo::OID, mongo::WriteConcernOptions), boost::_bi::list7<boost::_bi::value<std::string>, boost::_bi::value<mongo::BSONObj>, boost::_bi::value<mongo::BSONObj>, boost::_bi::value<mongo::BSONObj>, boost::_bi::value<std::string>, boost::_bi::value<mongo::OID>, boost::_bi::value<mongo::WriteConcernOptions> > >::operator()() at src/third_party/boost/boost/bind/bind_template.hpp:20
       (inlined by) boost::detail::thread_data<boost::_bi::bind_t<void, void (*)(std::string, mongo::BSONObj, mongo::BSONObj, mongo::BSONObj, std::string, mongo::OID, mongo::WriteConcernOptions), boost::_bi::list7<boost::_bi::value<std::string>, boost::_bi::value<mongo::BSONObj>, boost::_bi::value<mongo::BSONObj>, boost::_bi::value<mongo::BSONObj>, boost::_bi::value<std::string>, boost::_bi::value<mongo::OID>, boost::_bi::value<mongo::WriteConcernOptions> > > >::run() at src/third_party/boost/boost/thread/detail/thread.hpp:62
      thread_proxy at src/third_party/boost/libs/thread/src/pthread/thread.cpp:133
      

      This transaction was held open for the duration of applying deletes during the catchup phase of a chunk migration.

        1. ShorterScopedXact.patch
          1 kB
          Kaloian Manassiev

            Assignee:
            backlog-server-sharding [DO NOT USE] Backlog - Sharding Team
            Reporter:
            bruce.lucas@mongodb.com Bruce Lucas (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            18 Start watching this issue

              Created:
              Updated:
              Resolved: