Last modified: 2014-11-16 19:55:59 UTC
Created attachment 14830 [details] Patch file for wfDebugLog to render more precise timestamps Log entries from wfDebugLog() include a timestamp that shows the time to the nearest second. It is often the case that many actions complete and many log items are output in a single second, all showing the same timestamp. Consequently, often the timestamp is not precise enough to properly evaluate timing between events, especially those events that occur within the same timestamp second. This is different from the wfDebug() function, which renders timestamps to the nearest 0.0001 second when the $wgDebugTimestamps global is set. Note that Bug 14601 recommends using wfDebugLog() instead of the more widely used wfDebug(). PHP provides a microtime() function that reports time with the fractional part of the second, but the current wfDebugLog code relies on the MWDateTime() object, which does not store (or render) time more precisely than one second. The attached patch demonstrates one possible solution using microtime() to fetch the timestamp with the fractional second part, and appending that fractional part to the timestamp in the log entry. The patch only produces this more precise when the global variable $wgDebugLogTimestampPrecision is set to a number that represents the digits of precision greater than zero. The actual number of digits would not exceed the total number of digits provided by microtime(). If this global is zero (0) or is not set, the behavior is exactly as without the patch. For example: // show timestamps to the nearest millisecond $wgDebugLogTimestampPrecision = 3; As with the current wfDebugLog timestamp, the more precise timestamp provided by this example patch includes the decimal fraction of a second in a manner that is compatible with ISO 8601 (without the date/time "T" separator): "YY-MM-DD HH:MM:SS.S[...]". The time zone is omitted, as before. Another solution that might apply much more broadly would include modifying the MWDateTime object to record and render time more precisely.
Hi Daniel. Thanks for working on this. Patches to Bugzilla are pretty difficult to review. You want to submit a patch to [[mw:Gerrit]] instead (using Git) so that the proposed code change can be part of the formal code review process. Broadly, I'm hesitant to add another global configuration variable. Greater precision in debug timestamps seems potentially useful, but I'd prefer that we try to avoid the introduction of additional options wherever possible. We already have too many. :-)
I agree about global configuration problems, but I see that as a separate issue. I believe that this needs to be configurable for two reasons: 1) maintain backward compatibility and 2)(to a much lesser degree) avoid excess/irrelevant precision.
As I'm a n00b, I'm not sure how best to submit the patch to Gerrit. Would that be as a different branch? (What name?)
Related: Bug 29235 - MediaWiki is inconsistent in how it displays time (tracking) Bug 14601 - Use wfDebugLog instead of wfDebug by default
(In reply to Daniel Norton from comment #3) > As I'm a n00b, I'm not sure how best to submit the patch to Gerrit. Would > that be as a different branch? (What name?) You can read through [[mw:Gerrit/Getting started]]. If you need additional help, try [[mw:IRC]] (specifically "#wikimedia-dev" or "#mediawiki" on irc.freenode.net).
Change 118981 had a related patch set uploaded by Danorton: Bug 62713 - fractional second wfDebugLog timestamp https://gerrit.wikimedia.org/r/118981
Change 118981 had a related patch set uploaded by Danorton: Add fractional second to wfDebugLog timestamp https://gerrit.wikimedia.org/r/118981
I have added relative timestamps ($wgDebugTimestamp = true) back to wfDebugLog() info with change I2557601e85d1f4837c67621f2db27dae70b09880
Under current code hostname and timestamp (TS_DB) will be logged if and only if some particular wfDebugLog($channel, ...) is logged to a separate log file, for example: $wgDebugLogGroups = array( 'resourceloader' => '/var/tmp/rl.log' ); then /var/tmp/rl.log contains: 2014-11-16 19:48:48 tools.wikimedia.pl minitest: ResourceLoaderModule::getDefinitionMtime: New definition hash for module mediawiki.legacy.commonPrint in context en|ltr|vector|||styles|: 72809728a0143db31cf2311c69776df1. or, with $wgDebugTimestamps = true; and change I2557601e85d1f4837c67621f2db27dae70b09880 installed: 0.1650 22.2M 2014-11-16 19:48:48 tools.wikimedia.pl minitest: ResourceLoaderModule::getDefinitionMtime: New definition hash for module mediawiki.legacy.commonPrint in context en|ltr|vector|||styles|: 72809728a0143db31cf2311c69776df1. All other wfDebugLog() entries are formatted wfDebug()-like, i.e. without timestamp, hostname and wikiId.
