[SERVER-21733] WiredTiger reports that almost the entire file is available for reuse Created: 02/Dec/15  Updated: 03/Dec/15  Resolved: 02/Dec/15

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Max Hirschhorn Assignee: Keith Bostic (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

python buildscripts/resmoke.py --executor no_server repro_server21553.js

Participants:

 Description   

Discovered while verifying that SERVER-21553 had been fixed after the latest WiredTiger drop. <collStats>.wiredTiger["block-manager"] reports that the file size (compressed) is 3.090GB and that 3.089GB is available for reuse.

$ ./mongo --port 20010 --eval 'db.getSiblingDB("local").oplog.rs.stats(1024 * 1024)'
{
  "ns" : "local.oplog.rs",
  "count" : 4846273,
  "size" : 5136,
  "avgObjSize" : 1111,
  "storageSize" : 3164,
  "capped" : true,
  "max" : -1,
  "maxSize" : 5120,
  "sleepCount" : 0,
  "sleepMS" : 0,
  "wiredTiger" : {
    "metadata" : {
      "formatVersion" : 1,
      "oplogKeyExtractionVersion" : 1
    },
    "creationString" : "allocation_size=4KB,app_metadata=(formatVersion=1,oplogKeyExtractionVersion=1),block_allocation=best,block_compressor=snappy,cache_resident=0,checksum=on,colgroups=,collator=,columns=,dictionary=0,encryption=(keyid=,name=),exclusive=0,extractor=,format=btree,huffman_key=,huffman_value=,immutable=0,internal_item_max=0,internal_key_max=0,internal_key_truncate=,internal_page_max=4KB,key_format=q,key_gap=10,leaf_item_max=0,leaf_key_max=0,leaf_page_max=32KB,leaf_value_max=64MB,log=(enabled=),lsm=(auto_throttle=,bloom=,bloom_bit_count=16,bloom_config=,bloom_hash_count=8,bloom_oldest=0,chunk_count_limit=0,chunk_max=5GB,chunk_size=10MB,merge_max=15,merge_min=0),memory_page_max=10m,os_cache_dirty_max=0,os_cache_max=0,prefix_compression=0,prefix_compression_min=4,source=,split_deepen_min_child=0,split_deepen_per_child=0,split_pct=90,type=file,value_format=u",
    "type" : "file",
    "uri" : "statistics:table:collection-4--1644201538843773907",
    "LSM" : {
      "bloom filters in the LSM tree" : 0,
      "bloom filter false positives" : 0,
      "bloom filter hits" : 0,
      "bloom filter misses" : 0,
      "bloom filter pages evicted from cache" : 0,
      "bloom filter pages read into cache" : 0,
      "total size of bloom filters" : 0,
      "sleep for LSM checkpoint throttle" : 0,
      "chunks in the LSM tree" : 0,
      "highest merge generation in the LSM tree" : 0,
      "queries that could have benefited from a Bloom filter that did not exist" : 0,
      "sleep for LSM merge throttle" : 0
    },
    "block-manager" : {
      "file allocation unit size" : 4096,
      "blocks allocated" : 1619875,
      "checkpoint size" : 0,
      "allocations requiring file extension" : 116476,
      "blocks freed" : 1619842,
      "file magic number" : 120897,
      "file major version number" : 1,
      "minor version number" : 0,
      "file bytes available for reuse" : 3317309440,
      "file size in bytes" : 3318251520
    },
    "btree" : {
      "btree checkpoint generation" : 0,
      "column-store variable-size deleted values" : 0,
      "column-store fixed-size leaf pages" : 0,
      "column-store internal pages" : 0,
      "column-store variable-size RLE encoded values" : 0,
      "column-store variable-size leaf pages" : 0,
      "pages rewritten by compaction" : 0,
      "number of key/value pairs" : 0,
      "fixed-record size" : 0,
      "maximum tree depth" : 4,
      "maximum internal page key size" : 368,
      "maximum internal page size" : 4096,
      "maximum leaf page key size" : 3276,
      "maximum leaf page size" : 32768,
      "maximum leaf page value size" : 67108864,
      "overflow pages" : 0,
      "row-store internal pages" : 0,
      "row-store leaf pages" : 0
    },
    "cache" : {
      "bytes read into cache" : 12792485,
      "bytes written from cache" : 52784127588,
      "checkpoint blocked page eviction" : 0,
      "unmodified pages evicted" : 0,
      "page split during eviction deepened the tree" : 1,
      "modified pages evicted" : 24152,
      "data source pages selected for eviction unable to be evicted" : 5474,
      "hazard pointer blocked page eviction" : 947,
      "internal pages evicted" : 989,
      "internal pages split during eviction" : 10,
      "leaf pages split during eviction" : 6625,
      "in-memory page splits" : 23899,
      "in-memory page passed criteria to be split" : 69187,
      "overflow values cached in memory" : 0,
      "pages read into cache" : 393,
      "pages read into cache requiring lookaside entries" : 0,
      "overflow pages read into cache" : 0,
      "pages written from cache" : 1619875,
      "page written requiring lookaside records" : 0,
      "pages written requiring in-memory restoration" : 0
    },
    "compression" : {
      "raw compression call failed, no additional data available" : 0,
      "raw compression call failed, additional data available" : 0,
      "raw compression call succeeded" : 0,
      "compressed pages read" : 393,
      "compressed pages written" : 1618788,
      "page written failed to compress" : 723,
      "page written was too small to compress" : 364
    },
    "cursor" : {
      "create calls" : 1442,
      "insert calls" : 169121923,
      "bulk-loaded cursor-insert calls" : 0,
      "cursor-insert key and value bytes inserted" : 189478787539,
      "next calls" : 117370728,
      "prev calls" : 3,
      "remove calls" : 3400,
      "cursor-remove key bytes removed" : 30600,
      "reset calls" : 169128727,
      "restarted searches" : 1479224,
      "search calls" : 0,
      "search near calls" : 6800,
      "truncate calls" : 3400,
      "update calls" : 0,
      "cursor-update value bytes updated" : 0
    },
    "reconciliation" : {
      "dictionary matches" : 0,
      "internal page multi-block writes" : 0,
      "leaf page multi-block writes" : 6625,
      "maximum blocks required for a page" : 244,
      "internal-page overflow keys" : 0,
      "leaf-page overflow keys" : 0,
      "overflow values written" : 0,
      "pages deleted" : 17527,
      "fast-path pages deleted" : 1619482,
      "page checksum matches" : 0,
      "page reconciliation calls" : 24162,
      "page reconciliation calls for eviction" : 24162,
      "leaf page key bytes discarded using prefix compression" : 0,
      "internal page key bytes discarded using suffix compression" : 1619678
    },
    "session" : {
      "object compaction" : 0,
      "open cursor count" : 10
    },
    "transaction" : {
      "update conflicts" : 0
    }
  },
  "nindexes" : 0,
  "totalIndexSize" : 0,
  "indexSizes" : {
 
  },
  "ok" : 1
}


git version: 86e7b69a6c52c926d28a60d816faefa6db81eb96



 Comments   
Comment by Keith Bostic (Inactive) [ 02/Dec/15 ]

bruce.lucas is right, no checkpoints are completing in this workload (ask me if you care).

I believe what's happening is we're truncating oplog records as fast as we write them, that is, there are only a few real records underneath at any time and most of the file is comprised of blocks allocated and then quickly freed. Because those blocks were allocated and freed within the context of a single checkpoint, they can be immediately reused. (In other words, if you have checkpoint A in a file, then allocate block X, then free block X, block X can be immediately reused, no other checkpoint references it.)

I don't understand why the file is growing to 8GB before we hit that state of equilibrium, there are a few different things that could be involved, but I don't see any evidence there's anything wrong here.

Generated at Thu Feb 08 03:58:15 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.