Add ClosureContextProcessor

[upyx]

Hi! That processor generates a context by a closure if the closure is set as the only value in the context.

I use it a lot to reduce performance impact by debug code.

e.g.

function register () {
    // this:
    $log->debug('User registration in progress: {uuid}, {date}, {profiled}, {more}', [
        // expensive context generation !!!
    ]);
    // changes to:
    $log->debug('User registration in progress: {uuid}, {date}, {profiled}, {more}', [fn() => [
        // expensive context generation in closure will run only if debug level is set
    ]]);

    $log->info('User {name} registered.' ['name' => $user->name]);
}

[Seldaek]

I wonder if this is the best way to do this.. I don't really like that it makes the context dependent on the configuration of a processor, and you need to configure the processor on the right handler to ensure it does not call your closure too early.

How about this alternative:

class LazyContext {
    public function __construct(
        private \Closure $contextGenerator
    ) {}

    public function jsonSerialize() {
        return ($this->contextGenerator)();
    }
}

// then use it as:
$log->debug('foo', [new LazyContext(function () {
    return 'anything';
})]);

That would then be normalized by NormalizerFormatter as [0 => ['LazyContext' => 'anything']] and by JsonFormatter as ['anything'] I believe.

So your solution produces cleaner output, but carries a bit more configuration risk.

Anyway I do wonder if this really belongs in Monolog itself.. Is it so common to create expensive-to-init context data? I can't recall ever having that problem at least.

[upyx]

It's an option that I've shared. And yes, it has the same issues as the PsrLogMessageProcessor. I don't like it too. But loosing 60% of perfomance by logging I hate more :smiling_face_with_tear:

Is it so common to create expensive-to-init context data?

An array of five strings with calls of get_debug_type(), get_class() and few getters is enough to slow down an app. Closures work faster... for 2x, 3x times faster.

Simple example:

        $log->debug('debug', [
            fn() => [
                'one' => \get_class($object),
                'two' => \get_debug_type($object),
                'three' => $object->getName(),
                'four' => $count,
                'five' => $count,
            ],
        ]);

and

        $log->debug('debug', [
                'one' => \get_class($object),
                'two' => \get_debug_type($object),
                'three' => $object->getName(),
                'four' => $count,
                'five' => $count,
        ]);

Creation of closure work 3 times faster: 22925691ms vs 67377785ms vs in 100000 loop in my laptop.

When logging is needed in some hot loop, it matters. Symfony's Messenger does it. When we just started to use it, a worker consumed about 2000 messages per second without logging and only 10 with it. So, logs can slow down to 200 times. Thanks to blackfire >.< we have found the problem.

[upyx]

How about this alternative

Two creations of objects are twice as expensive. It's not good in the fight for performance.

[Seldaek]

Sorry for the delay here, looks reasonable to me, thanks!