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

WiredTiger -> session.truncate: the start cursor position is after the stop cursor position

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical - P2
    • Resolution: Fixed
    • Affects Version/s: 3.0.0-rc9
    • Fix Version/s: 3.0.1, 3.1.0
    • Component/s: Storage, WiredTiger
    • Labels:
      None
    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL
    • Backport Completed:
    • Steps To Reproduce:
      Hide

      Run iibench-mongodb using attached "run.simple.bash". Edit it to set path for JAVA and then use "bash run.simple.bash 1000000". Also edit paths in mongo.conf

      mongod command line is:
      numactl bin/mongod --config /foo/mongo.conf --storageEngine wiredTiger --wiredTigerCacheSizeGB 70 --master

      Show
      Run iibench-mongodb using attached "run.simple.bash". Edit it to set path for JAVA and then use "bash run.simple.bash 1000000". Also edit paths in mongo.conf mongod command line is: numactl bin/mongod --config /foo/mongo.conf --storageEngine wiredTiger --wiredTigerCacheSizeGB 70 --master

      Description

      Issue Status as of Mar 10, 2015

      ISSUE SUMMARY
      A bug in the WiredTiger algorithm for page management may cause the server to abort with a message like the following:

      2015-02-21T07:08:08.397-0800 E STORAGE  [WiredTigerRecordStoreThread for local.oplog.$main] WiredTiger (22) [1424531288:395397][1514015:0x7f903a7ff700], session.truncate: the start cursor position is after the stop cursor position: Invalid argument
      2015-02-21T07:08:08.399-0800 I -        [WiredTigerRecordStoreThread for local.oplog.$main] Invariant failure: ret resulted in status BadValue 22: Invalid argument at src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp 518
      

      USER IMPACT
      The mongod process aborts after the invariant failure and needs to be restarted. This can only impact capped collections.

      WORKAROUNDS
      N/A

      AFFECTED VERSIONS
      MongoDB 3.0.0 running with the WiredTiger storage engine.

      FIX VERSION
      The fix is included in the 3.0.1 production release.

      RESOLUTION DETAILS
      WiredTiger no longer incorrectly positions the start cursor during the truncate operation.

      Original description

      I get this from iibench-mongodb with 10 insert threads, 1 query thread and zlib after about 300M docs have been inserted. It did not occur with snappy. Prior to this crash there were many stalls (slow inserts) and that was also only an issue with zlib. This appears to be different than the "session.truncate" crash that occurred prior to rc9 (see https://jira.mongodb.org/browse/SERVER-17141)

      log has this content:

      2015-02-21T07:08:08.397-0800 E STORAGE  [WiredTigerRecordStoreThread for local.oplog.$main] WiredTiger (22) [1424531288:395397][1514015:0x7f903a7ff700], session.truncate: the start cursor position is after the stop cursor position: Invalid argument
      2015-02-21T07:08:08.399-0800 I -        [WiredTigerRecordStoreThread for local.oplog.$main] Invariant failure: ret resulted in status BadValue 22: Invalid argument at src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp 518
      2015-02-21T07:08:08.409-0800 I CONTROL  [WiredTigerRecordStoreThread for local.oplog.$main] 
       0x117b00b 0x1114881 0x10f7fb8 0xf267df 0xf2cbbf 0x10f941e 0x11c8358 0x7f904931e7c9 0x7f90490578ad 0
      ----- BEGIN BACKTRACE -----
      {"backtrace":[{"b":"400000","o":"D7B00B"},{"b":"400000","o":"D14881"},{"b":"400000","o":"CF7FB8"},{"b":"400000","o":"B267DF"},{"b":"400000","o":"B2CBBF"},{"b":"400000","o":"CF941E"},{"b":"400000","o":"DC8358"},{"b":"7F9049317000","o":"77C9"},{"b":"7F9048F4B000","o":"10C8AD"},{"b":"0","o":"0"}],"processInfo":{ "mongodbVersion" : "3.0.0-rc9", "gitVersion" : "nogitversion", "uname" : { "sysname" : "Linux", "release" : "3.10.53-43_fbk14_02627_gb5c286c", "version" : "#1 SMP Mon Oct 20 15:06:57 PDT 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000", "buildId" : "9D8BCA7928778A629A6BD7DD44CF150933BC2E78" }, { "b" : "7FFFA18FE000", "path" : "linux-vdso.so.1", "elfType" : 3, "buildId" : "50103D521098AC1A8DA637FE9F84CCFE48B62B25" }, { "b" : "7F9049F87000", "path" : "/usr/local/fbcode/gcc-4.9-glibc-2.20/lib/librt.so.1", "elfType" : 3, "buildId" : "36E417C497D7D99E323324B54709FFF95E21F209" }, { "b" : "7F9049D83000", "path" : "/usr/local/fbcode/gcc-4.9-glibc-2.20/lib/libdl.so.2", "elfType" : 3, "buildId" : "7258590522FF8998FF3DC9CD4800354FF634B049" }, { "b" : "7F9049A52000", "path" : "/usr/local/fbcode/gcc-4.9-glibc-2.20/lib/libstdc++.so.6", "elfType" : 3, "buildId" : "AADD96ABFCFED89F9C3343339F009D973AC5822F" }, { "b" : "7F904974B000", "path" : "/usr/local/fbcode/gcc-4.9-glibc-2.20/lib/libm.so.6", "elfType" : 3, "buildId" : "5180B0D6214EFC6BD4024BCC46459868BB9FF312" }, { "b" : "7F9049534000", "path" : "/usr/local/fbcode/gcc-4.9-glibc-2.20/lib/libgcc_s.so.1", "elfType" : 3, "buildId" : "CAE88F8F821F6A585CC52F17AA185621534F442C" }, { "b" : "7F9049317000", "path" : "/usr/local/fbcode/gcc-4.9-glibc-2.20/lib/libpthread.so.0", "elfType" : 3, "buildId" : "F3CF4B6D065A6FCF55D752C1B7FBF951C041B871" }, { "b" : "7F9048F4B000", "path" : "/usr/local/fbcode/gcc-4.9-glibc-2.20/lib/libc.so.6", "elfType" : 3, "buildId" : "C645843801A68480D80BF9D0FD4A20182CBD1D9C" }, { "b" : "7F904A190000", "path" : "/usr/local/fbcode/gcc-4.9-glibc-2.20/lib/ld.so", "elfType" : 3, "buildId" : "FAF6C327CBADE1769B09F51830B64480E9FFDC82" } ] }}
       mongod.30rc9.jem.norox(_ZN5mongo15printStackTraceERSo+0x2B) [0x117b00b]
       mongod.30rc9.jem.norox(_ZN5mongo10logContextEPKc+0xE1) [0x1114881]
       mongod.30rc9.jem.norox(_ZN5mongo17invariantOKFailedEPKcRKNS_6StatusES1_j+0x108) [0x10f7fb8]
       mongod.30rc9.jem.norox(_ZN5mongo21WiredTigerRecordStore27cappedDeleteAsNeeded_inlockEPNS_16OperationContextERKNS_8RecordIdE+0x8EF) [0xf267df]
       mongod.30rc9.jem.norox(+0xB2CBBF) [0xf2cbbf]
       mongod.30rc9.jem.norox(_ZN5mongo13BackgroundJob7jobBodyEv+0x11E) [0x10f941e]
       mongod.30rc9.jem.norox(+0xDC8358) [0x11c8358]
       libpthread.so.0(+0x77C9) [0x7f904931e7c9]
       libc.so.6(clone+0x6D) [0x7f90490578ad]
       ??? [0]
      -----  END BACKTRACE  -----
      2015-02-21T07:08:08.409-0800 I -        [WiredTigerRecordStoreThread for local.oplog.$main] 
       
      ***aborting after invariant() failure
      

      1. jmongoiibench.java
        35 kB
        Mark Callaghan
      2. mongo.conf
        0.4 kB
        Mark Callaghan
      3. run.simple.bash
        4 kB
        Mark Callaghan

        Issue Links

          Activity

          Hide
          keith.bostic Keith Bostic added a comment -

          Michael Cahill, here's the cursor pattern when we reach the failure:

          6119733380620749582, 6119733380620752036 <<< start, stop cursor keys
          6119733380620752037, 6119733380620754371
          6119733380620754372, 6119733380620756227
          6119733380620756228, 6119733384915715571
          6119733384915715572, 6119733384915716610
          6119733384915716611, 6119733384915716910
          6119733384915716911, 6119733384915716931
          6119733384915716932, 6119733384915717296
          6119733384915719796, 6119733384915717920 <<< start, stop cursor keys that failed order test
           
          6119733384915717297 <<< first record key in the collection at time of failure
          6119739174531629688 <<< last record key

          So, the failing start cursor is valid for the collection, but for some reason has skipped about 2,000 records forward from the beginning?

          Show
          keith.bostic Keith Bostic added a comment - Michael Cahill , here's the cursor pattern when we reach the failure: 6119733380620749582, 6119733380620752036 <<< start, stop cursor keys 6119733380620752037, 6119733380620754371 6119733380620754372, 6119733380620756227 6119733380620756228, 6119733384915715571 6119733384915715572, 6119733384915716610 6119733384915716611, 6119733384915716910 6119733384915716911, 6119733384915716931 6119733384915716932, 6119733384915717296 6119733384915719796, 6119733384915717920 <<< start, stop cursor keys that failed order test   6119733384915717297 <<< first record key in the collection at time of failure 6119739174531629688 <<< last record key So, the failing start cursor is valid for the collection, but for some reason has skipped about 2,000 records forward from the beginning?
          Hide
          keith.bostic Keith Bostic added a comment -

          I've now seen this failure on a system with the SERVER-17141 fix, so I don't believe they're related.

          Show
          keith.bostic Keith Bostic added a comment - I've now seen this failure on a system with the SERVER-17141 fix, so I don't believe they're related.
          Hide
          keith.bostic Keith Bostic added a comment - - edited

          Michael Cahill, I've gotten a look at the tree. The one oddity I see is the path to the incorrect search key is via a leaf page referenced from an internal page that otherwise only references internal pages. So, it looks like this:

          0x3cc98b200: row-store internal
                  disk (nil), entries 100, dirty, write generation=1
          ...
          K {1425008395, 1420}                    <<< internal
          memory 0x147218aa80 [NoAddr]
          K {1425008395, 5883}                    <<< internal
          memory 0x147218aad0 [NoAddr]
          K {1425008396, 1919}                    <<< internal
          memory 0x147218ab20 [NoAddr]
          K {1425008399, 581}                     <<< internal
          memory  0x147218ab70 [NoAddr]
          K {1425008400, 1478}                    <<< internal
          memory 0xd90eae7b0 [2934874112-2934878208, 4096, 4092605218]
          K {1425008401, 8096}                    <<< internal
          memory 0x147218ac10 [NoAddr]
          K {1425008423, 1497}                    <<< internal: CORRECT "FIRST" KEY
          memory 0x147218ac60 [NoAddr]
          K {1425008628, 3139}                    <<< leaf: INCORRECT "FIRST" KEY
          memory 0x55d90ba40 [1708761088-1708793856, 32768, 2920185554]

          It's also interesting the write-generation of the internal page shared by both the correct/incorrect search keys is 1.

          Show
          keith.bostic Keith Bostic added a comment - - edited Michael Cahill , I've gotten a look at the tree. The one oddity I see is the path to the incorrect search key is via a leaf page referenced from an internal page that otherwise only references internal pages. So, it looks like this: 0x3cc98b200: row-store internal disk (nil), entries 100, dirty, write generation=1 ... K {1425008395, 1420} <<< internal memory 0x147218aa80 [NoAddr] K {1425008395, 5883} <<< internal memory 0x147218aad0 [NoAddr] K {1425008396, 1919} <<< internal memory 0x147218ab20 [NoAddr] K {1425008399, 581} <<< internal memory 0x147218ab70 [NoAddr] K {1425008400, 1478} <<< internal memory 0xd90eae7b0 [2934874112-2934878208, 4096, 4092605218] K {1425008401, 8096} <<< internal memory 0x147218ac10 [NoAddr] K {1425008423, 1497} <<< internal: CORRECT "FIRST" KEY memory 0x147218ac60 [NoAddr] K {1425008628, 3139} <<< leaf: INCORRECT "FIRST" KEY memory 0x55d90ba40 [1708761088-1708793856, 32768, 2920185554] It's also interesting the write-generation of the internal page shared by both the correct/incorrect search keys is 1.
          Hide
          keith.bostic Keith Bostic added a comment -

          Possible fix linked here, testing now.

          Show
          keith.bostic Keith Bostic added a comment - Possible fix linked here , testing now.
          Hide
          michael.cahill Michael Cahill added a comment -

          Note: we believe the fix in https://github.com/wiredtiger/wiredtiger/pull/1731 is correct. It has been merged into WiredTiger develop and will go through MongoDB testing shortly.

          Show
          michael.cahill Michael Cahill added a comment - Note: we believe the fix in https://github.com/wiredtiger/wiredtiger/pull/1731 is correct. It has been merged into WiredTiger develop and will go through MongoDB testing shortly.

            People

            • Votes:
              0 Vote for this issue
              Watchers:
              12 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: