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

Slow query logs could report totalOplogSlotDurationMicros >>> durationMillis

    • Type: Icon: Bug Bug
    • Resolution: Unresolved
    • Priority: Icon: Minor - P4 Minor - P4
    • None
    • Affects Version/s: None
    • Component/s: None
    • Labels:
    • Storage Execution
    • ALL

      This a problem only to capped collection.

      I noticed in the help ticket where a slow query log message reporting that a single capped insert took 2 seconds (i.e, durationMillis ), but the totalOplogSlotDurationMicros took 13 seconds (but there were zero write conflicts and oplog visibility lag is under 2secs)

      When performing multiple writes within a single storage transaction and oplog slots reserved separately for each write, a timer is started for each oplog slot. As a result, totalOplogSlotDurationMicros can report the cumulative duration of all open oplog slots in that single storage transaction. Basically, we do this

      WUOW start
      Insert Doc55 -> (Reserves oplog slot1; Timer1 starts)
      Delete 1 -> (Reserves oplog slot2; Timer2 starts)
      Delete2 -> (Reserves oplog slot2; Timer3 starts )
      Delete 3 -> (Reserves oplog slot3; Timer4 starts)
      WUOW commit (
      totalOplogSlotDurationMicros = (Timer1+Timer2+Timer3+Timer4).elapsed())
      

      This would be a problem for  capped collections because deletes are performed within the same storage transaction as inserts, with optimes reserved separately for each delete op.

      In vectored inserts, even though multiple writes occur within a single storage transaction, we track the longest duration of an open oplog slot for each storage transaction (WUOW) and sum it up. This is because we reserve slots in bulk  for each WUOW.

      Currently, the calculation for totalOplogSlotDuration varies depending on how we reserve oplog slots (bulk vs individually) within a storage transaction (in a given WUOW) and causes confusion.

            Assignee:
            Unassigned Unassigned
            Reporter:
            suganthi.mani@mongodb.com Suganthi Mani
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated: