• Type: Task
    • Resolution: Unresolved
    • Priority: Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Checkpoint Cleanup
    • None
    • Storage Engines - Transactions
    • 13.219
    • None
    • None

      We were for the longest time running Mongo v4 where we did not face this issue. But with v7 and change in checkpointing logic we started facing the issue.

      Values:
      Read preference: secondaryPreferred
      minSnapshotHistoryWindowInSeconds: 30
      MongoDB version: 7.0.11
      Deployment topology: Replica set

      Observed behavior
      An affected query reported:
      planSummary: IXSCAN
      keysExamined: 0
      docsExamined: 0
      nreturned: 0
      durationMillis: 3843
      cpuNanos: 3835262020
      numYields: 0

      Although the operation returned no results and reported no examined keys, it took approximately 3.8 seconds and consumed significant CPU.

      During the same period, we observed:

      1. Approximately 15 million entries per second in WiredTiger’s “entries skipped by cursor next calls” or “entries skipped by cursor prev calls” metrics.
      2. Increased application-thread page reads from disk into cache.
      3. Increased forced eviction of pages marked dirty.
      4. Repeated scans appearing to traverse the same pages without finding any visible entries.

      Workload pattern
      The affected index contains a leading field whose value changes as records move between states. Another indexed field is time-ordered and generally does not change.

      When the leading indexed value changes, we understand that WiredTiger may:

      1. Tombstone the old index key.
      2. Insert a new index key into a different region of the B-tree.
      3. Retain the old entry until it is no longer required for snapshot visibility.
      4. Persist the old entry during a checkpoint if it cannot yet be discarded.
      5. Later treat the page as clean, even though its on-disk representation still contains obsolete entries.
      6. From what we know, there can be cases where it will never be cleaned, like say the page never get any write and it has tombstone entries, but we are not reading that page also through any queries. Now when the next time we try to read that page it will try to force evict and reconcile and thus add a whole lot of latency to the query.

       

      Over time, older regions of the index can receive few or no additional writes while accumulating deleted entries.

      Working hypothesis
      Our current hypothesis is that scans are reading index pages containing large numbers of deleted or snapshot-invisible entries.

      When a cursor reads such a page, it steps over the entries without counting them as keysExamined. If the page contains no live entries, or enough deleted entries are encountered (this number is 1000 dead entries from what we read in code), WiredTiger marks the page dirty and schedules or performs forced eviction so that reconciliation can remove the obsolete entries.

       


      We realized that this is an known issue in mongo v7. 

      We are anchoring on metrics:

      1. wiredTiger.cursor.Total number of entries skipped by cursor next calls
      2. wiredTiger.cursor.Total number of entries skipped by cursor prev calls

       

      But these are cumulative metrics. Needed a patch which is meant to address so we can get this data at a query level. 

      Attaching a patch for the same:
      1. In the patch we have added a parameter to turn on/off.

      2. For each query we add the extra telemetry to the slow query logs.

            Assignee:
            [DO NOT USE] Backlog - Storage Engines Team
            Reporter:
            Sujay Venaik (EXT)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated: