PHP Logging - Injecting File/Log Context

Introduction

Recently a work conversation came up around writing interfaces for log events, and whether it was necessary to require __FILE__ and __LINE__ as arguments for a logging event in PHP. For non-PHP developers these are the magic constants that represent the file and line that is currently being executed in PHP. This is important, as the second of the two following snippets is infinitely more useful when debugging:

An error has occured: Unable to contact database.

MySQLConnector.php:151 - An error has occured: Unable to contact database.

If the error stems from a typo in the database host name on line 148 the second entry is a much better starting point than the first. Now, another option is to provide unique logging messages so you can search over the code base looking for your unique log: yes, that is also a possible pattern. Here I am looking specifically at providing the file and line an error has occurred in for use during the debugging process.

Surely there's a better way to provide the file and line number in the log, why not just call __FILE__ and __LINE__ from within a log() method on your logger?

It makes sense at first, but does not work out in practice. Consider the following brief example, example.php:

<?php

function writeLog(string message)
{
	echo __FILE__ . ":" . __LINE__ . " " . $message . "\n";
}

writeLog('Starting script...')

//Do Something

writeLog ('Ending script.');

What will the log output look like?

example.php:5 Starting script...
example.php:5 Ending script.

Which is as useful as not having the file name and line there at all. If the log() function had been a part of a class or in a different file that file's name would appear instead of the file that I called log() from.

Thankfully there is a solution! Introducing debug_backtrace(). This function returns the "backtrace: or "stacktrace" from wherever it is called. In theory, if I use debug_backtrace() inside of my log() function and pop off the last result I can figure out where the call was made from. Like so:

<?php

function writeLog($message)
{
    $trace = debug_backtrace();
    echo $trace[count($trace) - 1]['file'] . ":" . $trace[count($trace) - 1]['line'] . " - " . $message . "\n";
}

writeLog('Starting script...');

// Do Stuff

writeLog("Ending script.");

Which, when run:

example.php:9 Starting script...
example.php:13 Ending script.

Gives the result I am looking for.

Great, post over, problem solved, right?

StackExchange post, PHP get line number from logging event:

Problem

According to the internet, debug_backtrace() is too slow to use in a production environment. Overall, that is a sentiment I agree with - capturing the entire callstack is memory intensive and slow, and logging should have as close to a non-measurable effect on application performance as possible. At the same time, the thought of having to add __FILE__ and __LINE__ to every logging event disgusts me.

So I am going to run the numbers and see for myself.

Solution

PHPBench is a benchmarking tool for PHP. I have never used it, but I know it exists. Benchmarking the performance of different methods of getting the file and line information into log events is one of the two use cases I would want to use PHPBench in my head (the other being measuring performance during code refactoring), so it is time to learn it. First though I need some logging functionality.

For the sake of testing different setups I am defining a series of different logging classes, as well as transport classes.

These files are all available on GitHub if you want to skip over the content here and open them up in your favourite editor.

Loggers

PsrLogger.php

A simple implementation of the PSR-3 compliant \Psr\Log\LoggerInterface interface for logging. Although the implementation does not include the additional context I want (file, line) it should serve as a baseline for logging performance.

<?php

namespace LoggerBenchmark\Loggers;

use LoggerBenchmark\Transports\TransportInterface;

class PsrLogger implements \Psr\Log\LoggerInterface
{

    const EMERGENCY = 'emergency';
    const ALERT     = 'alert';
    const CRITICAL  = 'critical';
    const ERROR     = 'error';
    const WARNING   = 'warning';
    const NOTICE    = 'notice';
    const INFO      = 'info';
    const DEBUG     = 'debug';

    public function setTransport(TransportInterface $transport)
    {
        $this->transport = $transport;
    }

    public function log(mixed $level, string|\Stringable $message, array $context = array()): void
    {
        if (method_exists($this, $level)) {
            $this->$level($message, $context);
        } else {
            throw new \BadMethodCallException("Invalid Method called on PsrLogger: $level");
        }
    }

    public function emergency(string|\Stringable $message, array $context = array()): void
    {
        $this->transport->save(self::EMERGENCY, $message, json_encode($context));
    }
    public function alert(string|\Stringable $message, array $context = array()): void
    {
        $this->transport->save(self::ALERT, $message, json_encode($context));
    }
    public function critical(string|\Stringable $message, array $context = array()): void
    {
        $this->transport->save(self::CRITICAL, $message, json_encode($context));
    }
    public function error(string|\Stringable $message, array $context = array()): void
    {
        $this->transport->save(self::ERROR, $message, json_encode($context));
    }
    public function warning(string|\Stringable $message, array $context = array()): void
    {
        $this->transport->save(self::WARNING, $message, json_encode($context));
    }
    public function notice(string|\Stringable $message, array $context = array()): void
    {
        $this->transport->save(self::NOTICE, $message, json_encode($context));
    }
    public function info(string|\Stringable $message, array $context = array()): void
    {
        $this->transport->save(self::INFO, $message, json_encode($context));
    }
    public function debug(string|\Stringable $message, array $context = array()): void
    {
        $this->transport->save(self::DEBUG, $message, json_encode($context));
    }
}

ExtenddedArgumentLogger.php

A simple logger that requires passing __FILE__ and _LINE__ as parameters. I expect this to be the fastest of the 3 implementations that add in the extra context information, but it also changes the signature of the log() method.

<?php

namespace LoggerBenchmark\Loggers;

use LoggerBenchmark\Transports\TransportInterface;

class ExtendedArgumentLogger
{
    public function setTransport(TransportInterface $transport)
    {
        $this->transport = $transport;
    }
    public function log (string $file, string $line, mixed $level, string|\Stringable $message, array $context = array())
    {
        $this->transport->save($file, $line, $level, $message, $context);
    }
}

StackTraceParsingLogger.php

Using debug_backtrace() to pick out the file and line, this is the way I have added this additional context to logs in the past.

<?php

namespace LoggerBenchmark\Loggers;

use LoggerBenchmark\Transports\TransportInterface;

class StackTraceParsingLogger
{
    public function setTransport(TransportInterface $transport)
    {
        $this->transport = $transport;
    }
    public function log (mixed $level, string|\Stringable $message, array $context = array())
    {
        $trace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
        $this->transport->save($trace[count($trace) - 1]['file'], $trace[count($trace) - 1]["line"], $level, $message, $context);
    }
}

ExceptionTraceParsingLogger.php

Using the \Exception class' getTrace() method to pick out the file and line, very similar to StackTraceParsingLogger.php.

<?php

namespace LoggerBenchmark\Loggers;

use LoggerBenchmark\Transports\TransportInterface;

class ExceptionTraceParsingLogger
{
    public function setTransport(TransportInterface $transport)
    {
        $this->transport = $transport;
    }
    public function log (mixed $level, string|\Stringable $message, array $context = array())
    {
        $exception = (new \Exception())->getTrace();
        $this->transport->save($exception[0]['file'], $exception[0]["line"], $level, $message, $context);
    }
}

Transports

FileTransport.php

Saves logs to a random file in /tmp, and optionally deletes the file afterwards.

<?php

namespace LoggerBenchmark\Transports;

class FileTransport implements TransportInterface
{

    private $file;
    private $keepLogs = false;
    private $fileName;

    /**
     * Random string generator
     * Adapted from https://stackoverflow.com/a/13212994
     */
    private function generateRandomString($length = 10) {
        return substr(str_shuffle(str_repeat($x='0123456789abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ', ceil($length/strlen($x)) )),1,$length);
    }

    public function __construct()
    {
        $this->fileName = $this->generateRandomString();
        $this->file = fopen("/tmp/" . $this->fileName . "_benchmarkLog", "w+");
    }

    public function save(...$message)
    {
        fwrite($this->file, implode(" - ", $message));
    }

    public function __destruct()
    {
        if ($this->keepLogs !== true) {
            unlink("/tmp/" . $this->fileName . "_benchmarkLog");
        }
    }
}

VoidTransport.php

• VoidTransport.php, doing nothing with the passed log, removing any time spent on I/O operations.

<?php

namespace LoggerBenchmark\Transports;

class VoidTransport implements TransportInterface
{
    public function save(...$message)
    {
        return;
    }
}

Helpers

Additionally, I am using the following class to pad additional calls into the callstack to make the logging a little more detailed, so that I am not skirting any issues by having too simple of an application.

RecursiveNestingHelper.php

<?php

namespace LoggerBenchmark\Helpers;

use Psr\Log\LoggerInterface;

class RecursiveNestingHelper
{

    private static float $nestingChance = 0.9;

    public static function nest(object $logger, string $level, string $message): void
    {
        if (rand(0, 100) < self::$nestingChance) {
            self::nest($logger, $level, $message);
        }
        $logger->log($level, $message);
    }
}

PHPBench

PHPBench has a really similar file layout to PHPUnit, so most of it is familiar already. each method name needs to start with bench, and go in their own class that appends Bench to the end of the name of the class being benchmarked. The only change I want to make from the default setup is to modify the configuration to save the reports as HTML into a reports folder so that I can easily get them posted here.

{
    "$schema": "./vendor/phpbench/phpbench/phpbench.schema.json",
    "runner.bootstrap": "vendor/autoload.php",
    "report.outputs": {
        "build-artifact": {
            "renderer": "html",
            "path": "./report/output.html",
            "title": "Logging Benchmarks"
        }
    }
}

The last thing to cover is the use of @Revs and @Iterations on each test. Since a single running method can have different execution times for a number of reasons, these are the tools to calculate average run times. Each benchmark is run @Iterations number of times (where each result set is added to the results) and each of these result sets represents the average run time over @Revs number of runs. Therefore a benchmark with a @Iterations of 3 and a @Revs of 10 would have 3 entries on my report, and each entry would be the average of 10 runs.

Since I have some randomness introduced by RecursiveNestingHelper.php it is important to use sufficiently large @revs in each benchmark to prevent the randomness from skewing the results.

For a first pass, each logger is being tested in 3 conditions:

• A single log output to a file
• 10000 different log entries output to a file
• 10000 different log entries sent to VoidTransport.php

Last piece I need is a script to automate generating all the reports, since I want all of them to start with, and I don't want to be running 12 commands to generate them.

#!/bin/bash

./vendor/bin/phpbench run --store LoggerBenchmark/Benchmarks/

mkdir -p ./report

#Report types
reports=( "aggregate" "default" "env" "bare" "bare-vertical" "bar_chart_time" "memory" "overview" "benchmark" "benchmark_compare" )

for report in "${reports[@]}"
do
    ./vendor/bin/phpbench report --ref=latest --output=html --report=$report > /dev/null
    mv ./.phpbench/html/index.html ./report/$report.html > /dev/null
    echo "$report report is available at ./report/$report.html"
done

And from it, I get some fun stats:

Results

PHPBenchmark Output

Turns out overview.html holds all the information that I find useful and the writing of the script to generate each report was not needed. Well, now I know. From this data though, some conclusions can be drawn:

Conclusions & Thoughts

The "baseline" PsrLogger is not as good as I thought it would be.
This is probably due to the extra boilerplate that the PsrLogger classes uses, inheriting from an interface.

There is a measurable difference between the debug_backtrace parsing logger and the Exception based logger.
I thought these would be nearly identical, but there must be something else going on here. I have seen the Exception method recommended as an equivilent to the debug_backtrace that can be done in one line, but evidently they are not completely identical.

Additionally, I now have a template for using PHPBench and some basic results to test against. There will probably be some additional logger classes to compare in the future, and certainly there will be additional PHPBench tests to come.

For now though, I am going to continue to ignore the ExtendedArgumentBench results and adopt StackTraceParsingLogger.