D
D
Denis2020-07-07 18:26:51
PHP
Denis, 2020-07-07 18:26:51

Formation of a log line only if the required debugging level is enabled?

Good day. I ran into a problem with the execution time of some scripts in one large project. I wanted to try to win at least half a second by reducing the formation of a line for logging. There are a lot of logs, the log call looks something like this:

class SomeClass(){
    function someFunction(string $param1, string $param2, int $param3): bool{
        debugLog(
            'log-level-3',
            __METHOD__ ,
            ': start with arguments: ' .PHP_EOL. $param1 . PHP_EOL. $param2.PHP_EOL . $param3
        );
        // code
        $success = $this->doSomething();
        debugLog('log-level-3', __METHOD__, ': end ' . $success ? 'successfully' : 'failure');
        return $success;
    }
}


The question arose: How to perform delayed generation of a line in the 3rd debugLog parameter, so that the line would be collected only if 'log-level-3' is enabled in the configurations?

I wanted to pass an anonymous function to the 3rd parameter, which should return a string, but then the readability of the code is very spoiled

class SomeClass(){
    function someFunction(string $param1, string $param2, int $param3): bool{
        debugLog(
            'log-level-3',
            __METHOD__ ,
            function() use ($param1, $param2, $param3){
                return ': start with arguments: ' .PHP_EOL. $param1 . PHP_EOL. $param2.PHP_EOL . $param3;
            }
        );
        // code
        $success = $this->doSomething();
        debugLog('log-level-3', __METHOD__, function() use ($success) { return ': end ' . $success ? 'successfully' : 'failure';});
        return $success;
    }
}


The project is very large, a lot of work with files. We conducted tests on servers identical in hardware under linux and windows. On linux, the brakes during the formation of documents are insignificant, the longest is ~ 15 seconds. When working under windows - scripts for generating documents can sometimes work up to ~ 90 seconds.

There is an idea to try to speed up the work a bit by reducing the huge number of concatenations.

Questions :
1) Is there a way to somehow beautifully arrange such logging so as not to lose readability?
2) Does it make sense to deal with hundreds of concatenations in almost every request?

An example of a real call in the way it exists now:
5f0491bd6ea24472902176.png

Answer the question

In order to leave comments, you need to log in

1 answer(s)
D
Denis, 2021-02-02
@aksined_by

Wrote a small benchmark for 1,000,000 entries in the log, provided that logging is not performed in any of the cases. One function collects a string and passes it, and the second function calls some callback that generates a string if a log is needed.

function logText(string $message, int $logLevel = LOG_WARNING){
    if ($logLevel <= LOG_WARNING){
        file_put_contents(__DIR__ . '/logText.log', date('H:m:s') . "\t$message\n", FILE_APPEND);
    }
}

function logFn($renderMsg, int $logLevel = LOG_WARNING){
    if ($logLevel <= LOG_WARNING){
        $text = $renderMsg();
        file_put_contents(__DIR__ . '/logText.log', date('H:m:s') . "\t$text\n", FILE_APPEND);
    }
}

$a = microtime(true);
for ($i = 1000000; $i > 0; $i--){
    logText("$i some text value " . ($i*100), LOG_DEBUG);
}
$time = microtime(true)-$a;
echo "<h3>time log message: $time</h3>";


$a = microtime(true);
for ($i = 1000000; $i > 0; $i--){
    logFn(
        function() use ($i){
            return "$i some text value " . ($i*100);
        }, LOG_DEBUG
    );
}
$time = microtime(true)-$a;
echo "<h3>time fn message: $time</h3>";

The difference turned out to be quite insignificant, but it turned out that the transmission of the formed string is faster.
The answer was approximately similar and looked something like this:
time log message: 0.54136490821838
time fn message: 0.66178202629089

Didn't find what you were looking for?

Ask your question

Ask a Question

731 491 924 answers to any question