Page MenuHomePhabricator

Monolog microsecond timestamps cost milliseconds of runtime with heavy log usage
Closed, ResolvedPublic

Description

Originally reported by @ori via a gerrit patch.

The use of DateTime::createFromFormat to create timestamps with microsecond resolution can incur milliseconds of runtime overhead when handling a request which generates a significant number of logging events. This cost is paid even if the events are eventually discarded as the $record['datetime'] member for each event is populated even if no handlers are interested in recording the event durably.

This simplistic benchmark shows the relative costs of collecting microsecond level timing data:

<?php
$limit = 1000;
$tz = new DateTimeZone('UTC');

$start = microtime(true);
for ($i = 0; $i < $limit; $i++) {
        $dt = DateTime::createFromFormat('U.u', sprintf('%.6F', microtime(true)), $tz)->
                setTimezone($tz);
}
echo 'createFromFormat: ', microtime(true) - $start, "\n";

$start = microtime(true);
for ($i = 0; $i < $limit; $i++) {
        $dt = new DateTime(null, $tz);
}
echo 'DateTime:         ', microtime(true) - $start, "\n";
$ php benchmark.php
createFromFormat: 0.010702133178711
DateTime:         0.0037209987640381

Reported upstream as https://github.com/Seldaek/monolog/issues/657 with a proposed fix provided in https://github.com/Seldaek/monolog/pull/658

Event Timeline

bd808 claimed this task.
bd808 raised the priority of this task from to Medium.
bd808 updated the task description. (Show Details)
bd808 added subscribers: bd808, ori.

Change 248800 had a related patch set uploaded (by BryanDavis):
MonologSpi: add support for customizing Monolog\Logger instances

https://gerrit.wikimedia.org/r/248800

Change 249308 had a related patch set uploaded (by BryanDavis):
Bump Monolog to 1.17.2

https://gerrit.wikimedia.org/r/249308

Change 249309 had a related patch set uploaded (by BryanDavis):
Monolog: Backport useMicrosecondTimestamps()

https://gerrit.wikimedia.org/r/249309

Change 249311 had a related patch set uploaded (by BryanDavis):
Bump development Monolog version

https://gerrit.wikimedia.org/r/249311

Change 249313 had a related patch set uploaded (by BryanDavis):
Monolog: Use useMicrosecondTimestamps() on Loggers

https://gerrit.wikimedia.org/r/249313

Change 249308 merged by jenkins-bot:
Bump Monolog to 1.17.2

https://gerrit.wikimedia.org/r/249308

Change 249311 merged by jenkins-bot:
Bump development Monolog version

https://gerrit.wikimedia.org/r/249311

Change 249309 merged by jenkins-bot:
Monolog: Backport useMicrosecondTimestamps()

https://gerrit.wikimedia.org/r/249309

Change 251010 had a related patch set uploaded (by Ori.livneh):
MonologSpi: add support for customizing Monolog\Logger instances

https://gerrit.wikimedia.org/r/251010

Change 248800 merged by jenkins-bot:
MonologSpi: add support for customizing Monolog\Logger instances

https://gerrit.wikimedia.org/r/248800

Change 251010 merged by jenkins-bot:
MonologSpi: add support for customizing Monolog\Logger instances

https://gerrit.wikimedia.org/r/251010

Change 249313 merged by jenkins-bot:
Monolog: Use useMicrosecondTimestamps() on Loggers

https://gerrit.wikimedia.org/r/249313

I can still see DateTime::createFromFormat being called in https://performance.wikimedia.org/xenon/svgs/daily/2015-11-08.api.reversed.svgz

Screen Shot 2015-11-09 at 10.20.36.png (452×1 px, 120 KB)

The code in Monolog\Logger is:

if ($this->microsecondTimestamps) {
    $ts = \DateTime::createFromFormat('U.u', sprintf('%.6F', microtime(true)), static::$timezone);
} else {
    $ts = new \DateTime(null, static::$timezone);
}

The config to set $this->microsecondTimestamps = false is in operations/mediawiki-config and mediawiki/vendor so this should no longer be happening if all wikis are on 1.27.0-wmf.5 as I expect.

Obviously there is something not quite correct about the operations/mediawiki-config patch.

Change 252017 had a related patch set uploaded (by BryanDavis):
Monolog: Disable microsecond timestamps on all loggers

https://gerrit.wikimedia.org/r/252017

Change 252017 had a related patch set uploaded (by BryanDavis):
Monolog: Disable microsecond timestamps on all loggers

https://gerrit.wikimedia.org/r/252017

The prior patch was necessary but not sufficient. It missed the '@default' logger definition which is actually used to handle most log events (wfDebug and any un-monitored channels).

Change 252017 merged by jenkins-bot:
Monolog: Disable microsecond timestamps on all loggers

https://gerrit.wikimedia.org/r/252017

$ xenon-grep --entrypoint=api --resolution=daily --count=50 | grep Monolog
  21 | Monolog\Logger::addRecord                              | 0.61%

DateTime::createFromFormat is not found at all in https://performance.wikimedia.org/xenon/svgs/daily/2015-11-11.api.reversed.svgz

I ran a test with the code in the task summary plus manual microtime (something like $dt = new DateTime(null, $tz); $mt = microtime( true ); return $dt->format(...) . '.' . ( $mt - (int)$mt)). Second-precision datetime took 5us per round, datetime plus manual microtime took 8us, full-precision datetime took 25us.

IMO a 60% overhead seems acceptable, so maybe we could calculate and add microseconds (or at least milliseconds) manually in a formatter.

Change 580096 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] [WIP] logging: Remove useMicrosecondTimestamps(false) calls

https://gerrit.wikimedia.org/r/580096

Change 580096 abandoned by Krinkle:

[operations/mediawiki-config@master] logging: Remove useMicrosecondTimestamps(false) calls

Reason:

https://gerrit.wikimedia.org/r/580096

Change 963661 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] debug: Optimize createLogger() and set UTC timezone by default

https://gerrit.wikimedia.org/r/963661

Change 580096 restored by Krinkle:

[operations/mediawiki-config@master] logging: Remove useMicrosecondTimestamps(false) calls

https://gerrit.wikimedia.org/r/580096

Change 963661 merged by jenkins-bot:

[mediawiki/core@master] debug: Optimize createLogger() and set UTC timezone by default

https://gerrit.wikimedia.org/r/963661

Change 580096 merged by jenkins-bot:

[operations/mediawiki-config@master] logging: Remove useMicrosecondTimestamps(false) calls

https://gerrit.wikimedia.org/r/580096