Uploaded image for project: 'Documentation'
  1. Documentation
  2. DOCS-2452

Document (profile) millis is elapsed time from start to end of op.

    • Type: Icon: Task Task
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • v1.3.1
    • Affects Version/s: None
    • Component/s: manual
    • Labels:
    • Environment:
      Ubuntu 12.04 LTS

      The current description of millis for profiling/logs is confusing, and incorrect in many cases. Please remove mentions of lock time and simply document as the elapsed time from start to end of op (which includes any lock/yielding time).

      This applies to everywhere where millis for an operation is reported: current ops, profile, logs...

      Orig Description
      Unlike what's written in the documentation, the field system.profile.millis in the profiler result, may include time spent acquiring locks (system.profile.lockStats.timeAcquiringMicros). I have set up an experiment to prove it (see steps to reproduce). I noticed this when profiling our production environment, and then noticed obvious coloration between the two values "millis" and "timeAcquiringMicros".

      I believe millis does not include the waiting for lock time, only if the operation started after the lock is acquired. This is not always the case. I think, according to my understanding, that bulk inserts or updates, may yield the locks and acquire new ones in the middle of their execution. If this happens, it seems that "millis" includes the "timeAcquiringMicros" of the new locks as it spans over it.

      I believe what we need is either a more clear documentation of what time the field "millis" might or might not include, or (which would be much better) make sure the field "millis" purely represents the execution time without any waiting-for-locks time.

            Assignee:
            sam.kleinman Sam Kleinman (Inactive)
            Reporter:
            anasser Ahmed Nasser
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved:
              10 years, 9 weeks ago