[DOCS-2452] Document (profile) millis is elapsed time from start to end of op. Created: 23/Dec/13 Updated: 20/May/15 Resolved: 28/Feb/14 |
|
| Status: | Closed |
| Project: | Documentation |
| Component/s: | manual |
| Affects Version/s: | None |
| Fix Version/s: | v1.3.1 |
| Type: | Improvement | Priority: | Minor - P4 |
| Reporter: | Ahmed Nasser | Assignee: | Sam Kleinman (Inactive) |
| Resolution: | Done | Votes: | 0 |
| Labels: | profiling | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Environment: |
Ubuntu 12.04 LTS |
||
| Issue Links: |
|
||||
| Participants: | |||||
| Days since reply: | 9 years, 50 weeks, 5 days ago | ||||
| Description |
|
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 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. |
| Comments |
| Comment by Githook User [ 28/Feb/14 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {u'username': u'tychoish', u'name': u'Sam Kleinman', u'email': u'samk@10gen.com'}Message: | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Githook User [ 28/Feb/14 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Author: {u'username': u'tychoish', u'name': u'Sam Kleinman', u'email': u'samk@10gen.com'}Message: | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Ahmed Nasser [ 23/Dec/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Thank you Scott. But sometimes timeAcquiringMicros is larger than millis, so "The elapsed time from start to end of op" will not be so accurate as well, right? | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Scott Hernandez (Inactive) [ 23/Dec/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Ahmed, We will update the docs to be less misleading. | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| Comment by Ahmed Nasser [ 23/Dec/13 ] | ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
|
Just noticed that I was wrong about the results of this experiment as the time in millis is less than the timeAcquiringMicros. I will see if I can reproduce the problem in a different way. However, I can still confirm I have cases on the production environment with obvious coloration between the two values:
And many more, that it is hard to assume that the execution time was close to the time-acquiring-locks by mere coincidence. |