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

Large in memory collection scan very slow with WiredTiger compared to mmapv1

    Details

    • Operating System:
      ALL
    • Steps To Reproduce:
      Hide

      Add a large amount of data into a collection (my test data generation is outlined in this gist).

      Here are the various storage config options used:

      //mmapv1
       
      storage:
          dbPath: "/ssd/db/mmap"
          engine: "mmapv1"
       
      //WT with compression off
       
      storage:
          dbPath: "/ssd/db/wt_none"
          engine: "wiredtiger"
          wiredtiger:
              collectionConfig: "block_compressor="
       
      // WT with snappy
       
      storage:
          dbPath: "/ssd/db/wt_snappy"
          engine: "wiredtiger"
       
      // WT with zlib
       
      storage:
          dbPath: "/ssd/db/wt_zlib"
          engine: "wiredtiger"
          wiredtiger:
              collectionConfig: "block_compressor=zlib"

      To force a collection scan, run the following:

      var start = new Date().getTime();
      db.data.find().explain("executionStats")
      var end = new Date().getTime();
      print("Time to touch data: " + (end - start) + "ms");

      Start and end are not really required since this is an explain and contains timing info, but I was also using this to compare to (for example) the touch command, so I wanted apples to apples timing comparisons.

      Show
      Add a large amount of data into a collection (my test data generation is outlined in this gist ). Here are the various storage config options used: //mmapv1   storage: dbPath: "/ssd/db/mmap" engine: "mmapv1"   //WT with compression off   storage: dbPath: "/ssd/db/wt_none" engine: "wiredtiger" wiredtiger: collectionConfig: "block_compressor="   // WT with snappy   storage: dbPath: "/ssd/db/wt_snappy" engine: "wiredtiger"   // WT with zlib   storage: dbPath: "/ssd/db/wt_zlib" engine: "wiredtiger" wiredtiger: collectionConfig: "block_compressor=zlib" To force a collection scan, run the following: var start = new Date().getTime(); db.data.find().explain( "executionStats" ) var end = new Date().getTime(); print( "Time to touch data: " + (end - start) + "ms" ); Start and end are not really required since this is an explain and contains timing info, but I was also using this to compare to (for example) the touch command, so I wanted apples to apples timing comparisons.

      Description

      This may be "works as designed" (i.e. that WT is going to be slower for traversing large data structures in memory) but I would like to make sure and quantify the expected behavior here if that is the case.

      While attempting to profile the benefits of compression in terms of bandwidth savings, the expected performance of the default snappy compression (which delivered decent on-disk compression) looked slower than expected, significantly slower than mmapv1.

      That led to a round of testing to better understand what was going on here. So, I used 4 basic storage engine configurations:

      • mmapv1
      • WT with no compression ("block_compressor=")
      • WT with snappy (default, so no block_compressor specified)
      • WT with zlib ("block_compressor=zlib")

      The only WT config that came close to the mmapv1 performance was zlib, and that was on the read from disk test. So, I decided to test on SSD rather than spinning media, the result was that everything got a bit faster, but the relative differences remained - WT was still significantly slower.

      For my initial testing methodology, since I was trying to demonstrate the benefits of compression for IO bandwidth savings, I had been clearing the caches on the system after each run.

      Now that IO appeared to have no effect I decided to do consecutive runs of the collection scan, which would make the second run all in-memory (the collection is <16GiB and the test machine has 32GiB RAM, even with indexes it would fit in memory, but indexes are not in play)

      However the collection scan was still slow with WiredTiger even when the data was already loaded into RAM. The mmapv1 test dropped from the ~300 second range down to 13 seconds, but the WT testing showed no similar reduction - it did improve, but was still in the hundreds of seconds range rather than double digits.

      I have tried tweaking cache_size, lsm, directio, readahead to no effect (the last two before I had ruled out IO issues completely), but no significant improvement either.

      Basic initial graph attached, I will add detailed timing information, graphs, perf output below to avoid bloating the description too much.

        Issue Links

          Activity

          Hide
          agorrod Alex Gorrod added a comment -

          I believe the issue here is with the code in CollectionScan::work. All code examples below are psuedo code of what is actually in the tree, in an attempt to simplify the explanation:

          DiskLoc nextLoc = _iter->getNext();
          member->obj = _iter->dataFor(nextLoc).releaseToBson();

          The code in the WiredTiger iterator WiredTigerRecordStore::Iterator::getNext is doing (in pseudo code):

          toReturn = curr();
          WT_CURSOR *c = getCursor();
          c->next();
          _curr = c->get_key();
          return toReturn;

          Then the code in WiredTigerRecordStore::Iterator::dataFor is doing:

          WiredTigerRecordStore::Iterator::dataFor(DiskLoc loc) {
              if( loc == _curr())
                  return (current_value);
              else {
                  // Open a new cursor and do a search to avoid repositioning the cursor being used for
                  // a traversal.
                  RecordStore::dataFor(loc);
              }
           

          So the CollectionScan::work method is doing both a cursor->next and a cursor search because the value it passes to dataFor is no longer the value of curr() in the iterator (we've already stepped past that).

          Show
          agorrod Alex Gorrod added a comment - I believe the issue here is with the code in CollectionScan::work. All code examples below are psuedo code of what is actually in the tree, in an attempt to simplify the explanation: DiskLoc nextLoc = _iter->getNext(); member->obj = _iter->dataFor(nextLoc).releaseToBson(); The code in the WiredTiger iterator WiredTigerRecordStore::Iterator::getNext is doing (in pseudo code): toReturn = curr(); WT_CURSOR *c = getCursor(); c->next(); _curr = c->get_key(); return toReturn; Then the code in WiredTigerRecordStore::Iterator::dataFor is doing: WiredTigerRecordStore::Iterator::dataFor(DiskLoc loc) { if( loc == _curr()) return (current_value); else { // Open a new cursor and do a search to avoid repositioning the cursor being used for // a traversal. RecordStore::dataFor(loc); } So the CollectionScan::work method is doing both a cursor->next and a cursor search because the value it passes to dataFor is no longer the value of curr() in the iterator (we've already stepped past that).
          Hide
          redbeard0531 Mathias Stearn added a comment -

          We will be changing CollectionScan::work to call dataFor on the result of curr() before getNext().

          Show
          redbeard0531 Mathias Stearn added a comment - We will be changing CollectionScan::work to call dataFor on the result of curr() before getNext().
          Hide
          adamc Adam Comerford (Inactive) added a comment - - edited

          Summary table, patched (improved CollectionScan) 2.8.0-rc1-pre, SSD based storage:

          Engine/Compression Coll scan time (disk) Coll scan time (mem) in-mem improvement
          mmapv1/none 51.789 13.479 -
          WT/none 178.283 34.269 -92.1%
          WT/snappy 141.284 36.997 -91.4%
          WT/zlib 147.025 68.585 -67.3%
          Show
          adamc Adam Comerford (Inactive) added a comment - - edited Summary table, patched (improved CollectionScan) 2.8.0-rc1-pre, SSD based storage: Engine/Compression Coll scan time (disk) Coll scan time (mem) in-mem improvement mmapv1/none 51.789 13.479 - WT/none 178.283 34.269 -92.1% WT/snappy 141.284 36.997 -91.4% WT/zlib 147.025 68.585 -67.3%
          Hide
          adamc Adam Comerford (Inactive) added a comment -

          In case anyone was concerned about the variance in performance of WT "in-memory" here, it turns out that my data set size was exploding the default (15G) cache size in WiredTiger. Once I increased the cache_size parameter to 24G, the results looked as below, far more consistent for WT in-memory collection scans:

          Engine/Compression Coll scan time (mem)
          mmapv1/none 12.857
          WT/none 22.236
          WT/snappy 22.453
          WT/zlib 22.617
          Show
          adamc Adam Comerford (Inactive) added a comment - In case anyone was concerned about the variance in performance of WT "in-memory" here, it turns out that my data set size was exploding the default (15G) cache size in WiredTiger. Once I increased the cache_size parameter to 24G, the results looked as below, far more consistent for WT in-memory collection scans: Engine/Compression Coll scan time (mem) mmapv1/none 12.857 WT/none 22.236 WT/snappy 22.453 WT/zlib 22.617
          Hide
          redbeard0531 Mathias Stearn added a comment -

          Further improvements possible with SERVER-16444

          Show
          redbeard0531 Mathias Stearn added a comment - Further improvements possible with SERVER-16444

            People

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

              Dates

              • Created:
                Updated:
                Resolved: