{"action":"opened","issue":{"url":"https://api.github.com/repos/Seldaek/monolog/issues/657","labels_url":"https://api.github.com/repos/Seldaek/monolog/issues/657/labels{/name}","comments_url":"https://api.github.com/repos/Seldaek/monolog/issues/657/comments","events_url":"https://api.github.com/repos/Seldaek/monolog/issues/657/events","html_url":"https://github.com/Seldaek/monolog/issues/657","id":108561250,"number":657,"title":"Microsecond timestamps cost milliseconds of runtime with heavy log usage","user":{"login":"bd808","id":6469,"avatar_url":"https://avatars.githubusercontent.com/u/6469?v=3","gravatar_id":"","url":"https://api.github.com/users/bd808","html_url":"https://github.com/bd808","followers_url":"https://api.github.com/users/bd808/followers","following_url":"https://api.github.com/users/bd808/following{/other_user}","gists_url":"https://api.github.com/users/bd808/gists{/gist_id}","starred_url":"https://api.github.com/users/bd808/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bd808/subscriptions","organizations_url":"https://api.github.com/users/bd808/orgs","repos_url":"https://api.github.com/users/bd808/repos","events_url":"https://api.github.com/users/bd808/events{/privacy}","received_events_url":"https://api.github.com/users/bd808/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":0,"created_at":"2015-09-27T21:11:41Z","updated_at":"2015-09-27T21:11:41Z","closed_at":null,"body":"The use of `DateTime::createFromFormat` to create timestamps with microsecond resolution can incur milliseconds of runtime overhead when handling a request 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.\r\n\r\nThis simplistic benchmark shows the relative costs of collecting microsecond level timing data:\r\n\r\n```php\r\n<?php\r\n$limit = 1000;\r\n$tz = new DateTimeZone('UTC');\r\n\r\n$start = microtime(true);\r\nfor ($i = 0; $i < $limit; $i++) {\r\n        $dt = DateTime::createFromFormat('U.u', sprintf('%.6F', microtime(true)), $tz)->\r\n                setTimezone($tz);\r\n}\r\necho 'createFromFormat: ', microtime(true) - $start, \"\\n\";\r\n\r\n$start = microtime(true);\r\nfor ($i = 0; $i < $limit; $i++) {\r\n        $dt = new DateTime(null, $tz);\r\n}\r\necho 'DateTime:         ', microtime(true) - $start, \"\\n\";\r\n```\r\n\r\n```sh\r\n$ php benchmark.php\r\ncreateFromFormat: 0.010702133178711\r\nDateTime:         0.0037209987640381\r\n```\r\n\r\nUse of `DateTime::createFromFormat` was introduced in 61a4945 replacing a simple usage of `new DateTime`. In a application that generates a few dozens or even hundreds of log events per request the runtime cost difference of `DateTime::createFromFormat` is probably not noticeable. The costs add up however on a heavily loaded system handling hundreds of requests per second with hundreds or even thousands of log events generated per request. Under any conditions the benefit of having microsecond resolution for timestamps verses millisecond level resolution is debatable. When having this level of granularity requires milliseconds of wall clock time to compute, the benefit is even more tenuous.\r\n\r\nThe easy fix for this issue would be to simply replace `\\DateTime::createFromFormat('U.u', sprintf('%.6F', microtime(true)), static::$timezone)->setTimezone(static::$timezone)` with `'datetime' => new \\DateTime(null, static::$timezone)` in `Monolog\\Logger`. A more complicated approach would be to introduce a feature flag that allows control of millisecond/microsecond timestamp resolution. If I was the benevolent dictator for this project I would chose the simple solution under the basic assumption that logging should seek to be as low impact as possible, especially for `debug` events that are likely to be discarded anyway."}}