[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:
Related
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
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.



 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: DOCS-2452: clarification about millis field in query analysis
Branch: master
https://github.com/mongodb/docs/commit/51a973f0341d8ed4ab03b1798c6b580000d0a29c

Comment by Githook User [ 28/Feb/14 ]

Author:

{u'username': u'tychoish', u'name': u'Sam Kleinman', u'email': u'samk@10gen.com'}

Message: DOCS-2452: clarification about millis field in query analysis
Branch: v2.4
https://github.com/mongodb/docs/commit/012e3031c455f0c4f2a70d8c7def7121ae3d9311

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:

Production 1.java

	"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(20508293),
			"w" : NumberLong(0)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(10097386),
			"w" : NumberLong(7)
		}
	},
	"nreturned" : 0,
	"responseLength" : 20,
	"millis" : 10558,

Production 2.java

"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(19741001),
			"w" : NumberLong(0)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(9545319),
			"w" : NumberLong(8)
		}
	},
	"nreturned" : 0,
	"responseLength" : 20,
	"millis" : 10510,

Production 3.java

"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(24662979)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(54396064)
		}
	},
	"millis" : 54410,

Production 4.java

"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(26914119),
			"w" : NumberLong(0)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(13042626),
			"w" : NumberLong(191099)
		}
	},
	"responseLength" : 151,
	"millis" : 13949,

Production 5.java

"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(180400274),
			"w" : NumberLong(0)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(91985883),
			"w" : NumberLong(218)
		}
	},
	"responseLength" : 430,
	"millis" : 92538,

And many more, that it is hard to assume that the execution time was close to the time-acquiring-locks by mere coincidence.

Generated at Thu Feb 08 07:43:29 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.