Microseconds in Yii Framework application.log

July 9, 2012 • 3 minutes read

How can you add microseconds to application.log file (standard log in Yii Framework)?

Here is the configuration with enabled logs

//... start main config
'preload' => array(
'log',
),
'components' => array(
'log' => array(
    'class' => 'CLogRouter',
    'routes' => array(
        array(
            'class' => 'CFileLogRoute',
            'levels' => 'warning, error, profile',
        ),
    ),
),
)
//... end main config

And here is application.log:

2012/06/25 15:25:32 [error] [system.db.CDbCommand] CDbCommand::fetchAll() failed: SQLSTATE[42S02]
2012/07/06 12:57:33 [profile] [application] begin:posts with limit and offset
2012/07/06 12:57:38 [profile] [application] end:posts with limit and offset

As seen above there are seconds in time stamps. But if accuracy is important to every fraction of a second? Ideally milliseconds should be displayed. For example, if i will start code optimization with profiling and this profiling information will record in this log.

We can create extension that will change and extend the log format. Let's inherit from CFileLogRoute Call this file ExtendedLogger.php

class ExtendedLogger extends CFileLogRoute
{
    protected function formatLogMessage($message,$level,$category,$time)
    {
        $micro = sprintf("%06d",($time - floor($time)) * 1000000);
        return date('Y-m-d H:i:s.'.$micro,$time)." [$level] [$category] $message\n";
    }
}

As you can see it overrides formatLogMessage method in which we have microsecods now. Let's copy ExtendedLogger.php to extensions/ExtendedLogger/ExtendedLogger.php and change config to this:

    'preload' => array(
        'log',
    ),
    'components' => array(
        'log' => array(
            'class' => 'CLogRouter',
            'routes' => array(
                array(
                    'class' => 'CFileLogRoute',
                    'levels' => 'warning, error',
                ),
                array(
                    'class' => 'application.extensions.ExtendedLogger.ExtendedLogger',
                    'levels' => 'profile',
                ),
            ),
        ),
    )

Now you can see application.log like this:

2012/07/05 19:52:32.707493 [profile] [application] begin:getPostsByUserId without cache
2012/07/05 19:52:33.775888 [profile] [application] end:getPostsByUserId without cache

Translation of this article: Русский