Page MenuHomePhabricator

wfDebugLog timestamp should show fraction of second
Open, LowPublic

Description

Author: daniel

Description:
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.


Version: 1.23.0
Severity: enhancement
See Also:
https://bugzilla.wikimedia.org/show_bug.cgi?id=73492

Attached:

Details

Reference
bz62713

Event Timeline

bzimport raised the priority of this task from to Medium.Nov 22 2014, 2:54 AM
bzimport set Reference to bz62713.
bzimport added a subscriber: Unknown Object (MLST).

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. :-)

daniel wrote:

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.

daniel wrote:

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?)

daniel wrote:

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-General" 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.

This is different from the wfDebug() function, which renders timestamps to the nearest 0.0001 second when the $wgDebugTimestamps global is set.

This feature has been removed since then, I believe. Timestamps remain enabled by default in various contexts, but T75492 tracks those are missing them.

I'm not convinced we need or want microsecond precison on debug logs by default, so long as the order is reliable, which it appears to be.

Debug messages are not meant to be used for profiling, we have better tools for that. Suggesting to decline this task.

Krinkle lowered the priority of this task from Medium to Low.Jan 8 2021, 1:03 AM