Last modified: 2014-11-16 19:55:59 UTC

Wikimedia Bugzilla is closed!

Wikimedia migrated from Bugzilla to Phabricator. Bug reports are handled in Wikimedia Phabricator.
This static website is read-only and for historical purposes. It is not possible to log in and except for displaying bug reports and their history, links might be broken. See T64713, the corresponding Phabricator task for complete and up-to-date bug report information.
Bug 62713 - wfDebugLog timestamp should show fraction of second
wfDebugLog timestamp should show fraction of second
Status: PATCH_TO_REVIEW
Product: MediaWiki
Classification: Unclassified
General/Unknown (Other open bugs)
1.23.0
All All
: Normal enhancement (vote)
: ---
Assigned To: Nobody - You can work on this!
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2014-03-16 17:08 UTC by Daniel Norton
Modified: 2014-11-16 19:55 UTC (History)
2 users (show)

See Also:
Web browser: ---
Mobile Platform: ---
Assignee Huggle Beta Tester: ---


Attachments
Patch file for wfDebugLog to render more precise timestamps (644 bytes, application/octet-stream)
2014-03-16 17:08 UTC, Daniel Norton
Details

Description Daniel Norton 2014-03-16 17:08:04 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.
Comment 1 MZMcBride 2014-03-16 17:14:00 UTC
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. :-)
Comment 2 Daniel Norton 2014-03-16 17:23:07 UTC
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.
Comment 3 Daniel Norton 2014-03-16 17:23:47 UTC
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?)
Comment 4 Daniel Norton 2014-03-16 17:23:55 UTC
Related:
Bug 29235 - MediaWiki is inconsistent in how it displays time (tracking)
Bug 14601 - Use wfDebugLog instead of wfDebug by default
Comment 5 MZMcBride 2014-03-16 17:25:50 UTC
(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).
Comment 6 Gerrit Notification Bot 2014-03-16 19:06:18 UTC
Change 118981 had a related patch set uploaded by Danorton:
Bug 62713 - fractional second wfDebugLog timestamp

https://gerrit.wikimedia.org/r/118981
Comment 7 Gerrit Notification Bot 2014-03-17 16:10:37 UTC
Change 118981 had a related patch set uploaded by Danorton:
Add fractional second to wfDebugLog timestamp

https://gerrit.wikimedia.org/r/118981
Comment 8 Marcin Cieślak 2014-11-16 19:17:15 UTC
I have added relative timestamps ($wgDebugTimestamp = true) back to wfDebugLog() info with change I2557601e85d1f4837c67621f2db27dae70b09880
Comment 9 Marcin Cieślak 2014-11-16 19:55:59 UTC
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.

Note You need to log in before you can comment on or make changes to this bug.


Navigation
Links