ENH: Use REQUEST_TIME_FLOAT for log entries #179

Closed
Vovan-VE opened this Issue Dec 14, 2016 · 1 comment

Projects

None yet

2 participants

@Vovan-VE

What steps will reproduce the problem?

A sequence of parallel requests with delay less then request handling duration.

What's expected?

Each request is logged with its own REQUEST_TIME_FLOAT in time field to sort them by chronological order.

What do you get instead?

Each request is logged with a time near to request end. So, the set of requests is shuffled in pseudo random manner due to unpredictable handling duration.

Additional info

https://github.com/yiisoft/yii2-debug/blob/master/LogTarget.php#L155:

     'ip' => $request->getUserIP(),
-    'time' => time(),
+    'time' => $_SERVER['REQUEST_TIME_FLOAT'],
     'statusCode' => $response->statusCode,
Q A
Yii version 2.0.10
PHP version 7.0.8
Operating system Ubuntu/16.04
@samdark
Member
samdark commented Dec 14, 2016

Could be done like the following:

protected function getRequestTime()
{
    if (isset($_SERVER['REQUEST_TIME_FLOAT'])) {
        return $_SERVER['REQUEST_TIME_FLOAT'];
    }

    return microtime(true);
}

All the code should be adjusted though because both $_SERVER['REQUEST_TIME_FLOAT'] and microtime(true) are returning float values. These values should be displayed properly.

@samdark samdark self-assigned this Dec 14, 2016
@samdark samdark added this to the 2.0.8 milestone Dec 14, 2016
@samdark samdark added a commit that referenced this issue Dec 14, 2016
@samdark samdark Fixes #179: Increased request time logging accuracy and precision 6747d4a
@samdark samdark closed this in 454d89c Dec 15, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment