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

Details

Related Gerrit Patches:

Event Timeline

bd808 created this task.Oct 25 2015, 9:39 PM
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.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptOct 25 2015, 9:39 PM

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

bd808 moved this task from To Do to In Dev/Progress on the User-bd808 board.Nov 4 2015, 5:25 AM

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

bd808 added a comment.Nov 9 2015, 5:28 PM

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

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

bd808 added a comment.Nov 9 2015, 7:03 PM

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

bd808 closed this task as Resolved.Nov 12 2015, 11:21 PM
$ 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

bd808 moved this task from Needs Review/Feedback to Done on the User-bd808 board.Nov 12 2015, 11:21 PM
bd808 moved this task from Done to Archive on the User-bd808 board.Nov 19 2015, 4:08 PM
Tgr added a subscriber: Tgr.Jan 31 2016, 4:50 AM

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.