[Question] MonologBundle + long running process

[tiborb]

I have a long running console command for testing:

protected function execute(InputInterface $input, OutputInterface $output)
{    

    $container = $this->getContainer();
    $logger = $container->get('logger');

    $lim = 5000;
    $count = 0;
    while (true){
        $count++;
        $logger->debug("line one");
        $logger->debug("line two");
        $logger->debug("line three");
        #var_export($logger);
        if ($count >= $lim){
            break;
        }
    }
}

and my prod config looks like this:

monolog:
    handlers:
        main:
            type:         fingers_crossed
            action_level: error
            handler:      nested
            buffer_size:  30
        nested:
            type:  stream
            path:  "%kernel.logs_dir%/%kernel.environment%.log"
            level: debug

The elements in the buffer do not exceed the limit, but the overall memory usage of the process is still increasing with every iteration.
If I let the process run for a few minutes it gets over 1gb and i have no idea where the memory increase comes from.

I also did some profiling with xdebug but it doesn't help too much:

function                                                                                        #calls  time     memory  time     memory
----------------------------------------------------------------------------------------------------------------------------------------
Monolog\Logger->addRecord                                                                        15000  19.2248 -2024304  6.6741 12480632
Composer\Autoload\includeFile                                                                      245  0.6489  7826512  0.2820  5104360
sprintf                                                                                          15002  1.0057  3840680  1.0057  3840680
Monolog\Logger->debug                                                                            15000  21.0143   736080  1.7896  2760384
Symfony\Component\HttpKernel\Kernel->initializeContainer                                             1  0.0147  1717064  0.0099  1478920
DateTime::createFromFormat                                                                       15000  1.1265   960000  1.1265   960000
Monolog\Handler\FingersCrossedHandler->isHandling                                                15000  0.9998   720000  0.9998   720000
Monolog\Handler\FingersCrossed\ErrorLevelActivationStrategy->isHandlerActivated                  15000  1.0250   720000  1.0250   720000
include                                                                                            245  0.3669  2722152  0.0159   509520
FilesystemIterator->current                                                                         85  0.0058   383728  0.0058   383728
Symfony\Component\Finder\Expression\Regex::create                                                   30  0.0296   380840  0.0105   351632
appProdProjectContainer->getDefaultParameters                                                        1  0.0002   179504  0.0002   179504
composerRequireee80ec58e11a2d87b2e216687850288a                                                      8  0.0186   288168  0.0125   162928
Symfony\Component\Finder\Adapter\PhpAdapter->searchInDirectory                                      15  0.1565   348440  0.0056    76840
ComposerAutoloaderInitee80ec58e11a2d87b2e216687850288a::loadClassLoader                              1  0.0011    63872  0.0010    63824
appProdProjectContainer->__construct                                                                 1  0.0008   237344  0.0003    57712
strtr                                                                                              639  0.0421    41256  0.0421    41256
substr                                                                                             765  0.0475    33600  0.0475    33600
Symfony\Component\Finder\Finder->addAdapter                                                         45  0.0242    34840  0.0075    31240
explode                                                                                             88  0.0053    30936  0.0053    30936
Symfony\Component\Finder\Finder->Symfony\Component\Finder\{closure}                                135  0.0089    29928  0.0089    29928
Composer\Autoload\ClassLoader->set                                                                  53  0.0038    29928  0.0038    29928
require_once                                                                                         5  0.0477   719696  0.0009    29080
FilterIterator->key                                                                                248  0.0200    27688  0.0200    27688
stream_get_meta_data                                                                                17  0.0010    24752  0.0010    24752
Symfony\Component\Finder\Iterator\ExcludeDirectoryFilterIterator->__construct                       15  0.0172    29520  0.0082    23280
ReflectionClass->getConstructor                                                                     74  0.0047    23096  0.0047    23096
str_replace                                                                                        113  0.0070    22448  0.0070    22448
Symfony\Component\Console\Input\InputDefinition->setArguments                                      109  0.0405    32168  0.0159    22328
Symfony\Component\Console\Input\InputDefinition->setOptions                                        108  0.0707    37224  0.0120    21552
ReflectionClass->__construct                                                                        82  0.4401  3963992  0.0088    21024
preg_match                                                                                        1061  0.0719    20400  0.0719    20400
Symfony\Component\Console\Input\InputOption->isArray                                               412  0.0253    19776  0.0253    19776
array_merge                                                                                         32  0.0019    19712  0.0019    19712
Symfony\Component\Console\Application->add                                                          76  0.1666   504288  0.0231    19584
Symfony\Component\Console\Command\Command->__construct                                              76  0.5897   560088  0.0121    19112
ReflectionClass->newInstance                                                                        74  0.5825   572240  0.0080    19056
RecursiveDirectoryIterator->hasChildren                                                             85  0.0574    18216  0.0574    18216
SplFileInfo->__construct                                                                            85  0.0065    16528  0.0065    16528
Symfony\Component\Finder\Finder->__construct                                                        15  0.0938   349816  0.0089    16208

Any help would be much appreciated,
Tibor

[jakzal]

I just had a quick look and found out that memory leaks in the Symfony\Bridge\Monolog\Handler\DebugHandler (or actually in its base class - Monolog\Handler\TestHandler).

Adding --no-debug to your command in combination with buffer_size will prevent memory leaks.

[tiborb]

Thanks. The issue occurred in prod mode, which deactivates the debug. Seems to work after reinstalling monolg-bundle 2.7.1, maybe there was something wrong with my installation.

This is how my prod config looks like at the moment:

monolog:
    handlers:
        main:
            type:         fingers_crossed
            action_level: error
            handler:      nested
            buffer_size:  30
        nested:
            type:  stream
            path:  "%kernel.logs_dir%/%kernel.environment%.log"
            level: error

And the command runs in prod mode , over 16h now and stable.

I will close this issue now.

[collmomo]

I don't want to reopen a closed issued but I too had the same issue http://stackoverflow.com/questions/35977213/memory-leak-symfony-and-monolog-and-console/35977531#35977531

[gingerCodeNinja]

@jakzal Do you remember what the memory leak was in TestHandler, or if it was fixed and if so, in which version of monolog?

[flaushi]

Thanks. The issue occurred in prod mode, which deactivates the debug. Seems to work after reinstalling monolg-bundle 2.7.1, maybe there was something wrong with my installation.

This is how my prod config looks like at the moment:

monolog:
    handlers:
        main:
            type:         fingers_crossed
            action_level: error
            handler:      nested
            buffer_size:  30
        nested:
            type:  stream
            path:  "%kernel.logs_dir%/%kernel.environment%.log"
            level: error

And the command runs in prod mode , over 16h now and stable.

I will close this issue now.

Hey @tiborb , you changed the level of the nested handler from debug (collecting all messages) to error (allowing the nested handler to discard all debug and warning messages). Maybe the leak was not resolved, but just your configuration prevented the leak to occur?