Horizon: Horizon wrong time displayed, errors in log for completed job and ignoring memory restrictions for hard tasks

[kaan-atakan]

• Horizon Version: 3.4.3
• Laravel Version: 6.6.0
• PHP Version: 7.2.24
• Redis Driver & Version: phpredis 5.1.1
• Database Driver & Version: mysql

Description:

When running

Steps To Reproduce:

• Create a job that needs more than 60 seconds and to run and uses a lot of memory (I generated 3,000,000 unique strings using $faker->unique()->regexify() for the sake of testing). I'll attach the job file.
• (Re)start horizon
• Queue the job

What happens:

• Despite the memory limit being specified as 64MB in config/horizon.php the worker threads are started with the option --memory=128 which is also ignored and the processes are allowed to consume nearly a whole gigabyte of resident memory without failing

• Despite the job completing without issue, Laravel logs an exception (local.ERROR: ... attempted too many times or run too long. The job may have previously timed out. {"exception":"[object] (Illuminate\Queue\MaxAttemptsExceededException(code: 0): App\Jobs\SendOrderEmail ... at /work/jsong/vendor/laravel/framework/src/Illuminate/Queue/Worker.php:612...)

• A job that took 1 minute and 36 seconds to complete is displayed in the horizon recent jobs list as having taken 3.63 seconds. Another that took 1m32s displays as 0.68s. Another that also took 1m32s displays as 0.18s.

Looking at the timing of the exceptions and when the job was completed it seems that Horizon is logging the difference between when the exception was thrown and when the job was completed. I thought that perhaps this is more of a laravel issue than a horizon issue. But when I work the queue manually with php artisan queue:work or php artisan queue:work --deamon the exception is not thrown and the horizon interface reports time correctly

SendOrderEmail.php.txt

[driesvints]

We'll need to gather some more opinions here to determine if this is actually a bug or not as this is the first time it's being reported.

[kaan-atakan]

I've played around with it some more and dug into the source code. Some of the problems I've discovered have to do more with poor documentation. So the 'memory_limit' option at the root of config/horizon.php is documented in the comments as applying to workers when in fact the only reference to it in the source code is to check the memory usage of the supervisor. Setting this value to 1 terminates the supervisors.

I think also worth noting is that the value specified here and the memory usage reported by top before the process dies are not exactly the same. The supervisor seems to require about 44MB off memory, but only gets killed if the value is 15 or below. I'm not even exactly sure what the point of checking supervisor memory usage is (since it seems to be pretty constant, I've tried starting 100 worker threads and it still didn't go over 45MB). But it doesn't seem to be working as expected either.

The memory usage passed to the worker processes can be specified instead in the supervisor options like so:

'environments' => [
    'local' => [
        'supervisor-1' => [
            'connection' => 'redis',
            'queue' => ['default'],
            'balance' => 'simple',
            'processes' => 3,
            'tries' => 1,
            'memory' => 256,
            'timeout' => 300,
        ],
    ]
],

However the worker processes still ignore the memory limitations. Default laravel queue workers ignore the parameter too, I haven't checked if horizon is just a wrapper around these. If that's the case this might only be a laravel bug. I will report this on the laravel github and see what happens.

Notice also the timeout option of the supervisor. This overrides the default 60s timeout passed to the worker threads. Adding this solved the issue with the exception and misreported timing. However: I think there is still something funky going on here:

Why is the exception resetting the clock but not terminating the job? I think this is probably a bug.

So really there is two bugs and 2-3 documentation fixes (depending on how granular you want to get):

Documentation:

• the memory and timeout options of the supervisor are undocumented.
• the comment inside config/horizon.php is for memory_limit wrong

Bug:

• The timeout set in the supervisor config and passed to the workers via command line options is causing an event that resets the clock but doesn't fail the job.
• The memory consumption of the supervisor is being underreported where it is being checked (src/Listeners/MonitorMasterSupervisorMemory.php: $master->memoryUsage()).

I could open 3 seperate issues and close this one. But I'm going to wait on further input before doing it

[4n70w4]

The similar error! I set memory limit 256mb in horizon, but scripts fatalled by limit 128mb.

laravel/horizon v3.4.3
laravel/framework v5.8.35

Allowed memory size of 134217728 bytes exhausted (tried to allocate 1052672 bytes)

Runnig processes:

ps -ef
UID        PID  PPID  C STIME TTY          TIME CMD
app          1     0  0 Nov22 ?        00:42:27 php artisan horizon
app         12     1  0 Nov22 ?        00:42:22 /usr/bin/php artisan horizon:supervisor horizon-f6hF:supervisor-1 redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --balance=simple --max-processes=10 --min-processes=1 --nice=0
app       4447    12  3 08:18 ?        00:01:47 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1
app       4503    12  1 08:27 ?        00:00:37 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1
app       4513    12  1 08:29 ?        00:00:45 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1
app       4520    12  2 08:29 ?        00:00:46 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1
app       4527    12  0 08:29 ?        00:00:14 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1
app       4537    12  1 08:30 ?        00:00:32 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1
app       4544    12  0 08:30 ?        00:00:02 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1
app       4551    12  1 08:31 ?        00:00:33 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1
app       4559    12  1 08:32 ?        00:00:25 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1
app       4571    12  1 08:32 ?        00:00:26 /usr/bin/php artisan horizon:work redis --delay=5 --memory=256 --queue=default --sleep=3 --timeout=60 --tries=3 --supervisor=horizon-f6hF:supervisor-1

[AlexVanderbist]

I'm experiencing similar issues regarding the --memory limit per worker. I'm only running workers with the limit set to 1024 but they're still failing on 134217728 bytes (128M).

I'm happy to do some more digging if more information is needed.

[driesvints]

Think we can now mark this as a bug after three different people confirming. If anyone's willing to work on a PR for this, that'd be great.

[AlexVanderbist]

I'm looking into it! Currently it looks more like an issue in Laravel's own queue worker, as the --memory flag is being ignored there as well.

[driesvints]

I did find https://github.com/laravel/framework/issues/25738 which I close myself because there was no response anymore.

[AlexVanderbist]

I'm not sure if the queue:work command (or Horizon's memory config) are actually supposed to set PHP's memory_limit? Currently the memory option/flag is more like a memory_limit that will terminate a worker if it uses too much memory, before PHP's own memory_limit kicks in.

I'm not sure what the intended behaviour is tho. I expected --memory to actually set PHP's memory_limit as well.

[driesvints]

@AlexVanderbist just found the following issue which hints that memory_limit indeed isn't set with this: https://github.com/laravel/horizon/issues/246

You'll need to make sure memory_limit is set properly as well.

[driesvints]

We should definitely document that better. Feel free to send in a PR or otherwise I'll send one in later. Thanks for checking in on this.

[driesvints]

@kaan-atakan @4n70w4 can you both check if your memory_limit in PHP is set high enough?

[4n70w4]

Correctly setting to cli php interpreter memory limit via option php -d memory_limit=512M script.php args

Need add to horizon configurable this option.

-d | --define | Set a custom value for any of the configuration directives allowed in php.ini. The syntax is: -d configuration_directive[=value] # Omitting the value part will set the given configuration directive to "1" $ php -d max_execution_time -r '$foo = ini_get("max_execution_time"); var_dump($foo);' string(1) "1" # Passing an empty value part will set the configuration directive to "" php -d max_execution_time= -r '$foo = ini_get("max_execution_time"); var_dump($foo);' string(0) "" # The configuration directive will be set to anything passed after the '=' character $ php -d max_execution_time=20 -r '$foo = ini_get("max_execution_time"); var_dump($foo);' string(2) "20" $ php -d max_execution_time=doesntmakesense -r '$foo = ini_get("max_execution_time"); var_dump($foo);' string(15) "doesntmakesense"

https://www.php.net/manual/en/features.commandline.options.php

[driesvints]

I personally don't think it's a good idea to overwrite server settings from within Horizon (or the queue workers for that matter).

[4n70w4]

@driesvints If the user purposefully configures this, then why not?

[driesvints]

@4n70w4 because these settings are being set as limits to prevent scripts from overriding them. Remember that Horizon can be used in lots of different scenarios. If you for example have a shared server with different apps by different people, not all of them would want their server settings being overwritten by one app.

[riasvdv]

I think it would be nice to have a way to add PHP parameters to the command here to pass to the php executable https://github.com/laravel/horizon/blob/3.0/src/WorkerCommandString.php#L22 that you can define in the horizon config for different queues.

[driesvints]

@riasvdv now that's indeed an option we could take. But isn't the memory parameter already passed in there?

[riasvdv]

The memory parameter is passed there, but it doesn't change the actual memory of the PHP process, just when horizon terminates the job, if your horizon limit is higher than the actual PHP limit, the job fails because of PHPs limit and isn't terminated by Horizon

[riasvdv]

@driesvints Isn't it also just possible to assume when memory is passed that this is the memory in which we want the process to run? Couldn't we just pass -d memory_limit=${$options->memory}M straight through?

[4n70w4]

@driesvints -d memory_limit is not a server setting, this is a specific interpreter process setting.

[driesvints]

@riasvdv from what I currently understand it's the maximum memory that the process can use but your server side configured memory_limit is still a hard level enforced at the lowest level to prevent abuse. What we could do though is allow for memory_limit to specifically cascade through if you explicitly want to override it. Does that sounds good?

[riasvdv]

@driesvints Would work a lot better than setting it with ini_set in a queue job!

[driesvints]

This sets the maximum amount of memory in bytes that a script is allowed to allocate. This helps prevent poorly written scripts for eating up all available memory on a server.

It's a setting you define in your php.ini on your server. Let's not get off track here with discussing on how things are named.

@driesvints Would work a lot better than setting it with ini_set in a queue job!

Yeah agreed. I'll run this over with the rest of the team.

[taylorotwell]

Some people may want a more graceful memory_limit option. For example, setting the PHP memory limit is going to kill your job in the middle of processing a job, possibly leaving your system in an inconsistent state. The current memory limit functionality is graceful and checks the memory consumption after each job is finished processing.

I can see the use case for both... note you can already set a memory_limit in your CLI php.ini file. If we want to make the PHP memory limit configurable from Horizon I think it would need to be a configuration option in addition to the current memory limit option.

I personally do not want my jobs to be terminated in the middle of processing for only going 1mb over the memory limit for example. I would rather the worker restart after the job is finished.

[AlexVanderbist]

I can see the use case for both...

So would having both be an option?

Maybe our current use-case can shine some light on why we're looking to do this:

We've got 2 supervisors:

• the default one, 10 processes, 128MB limit in horizon.php: perfect for small jobs like sending mails, etc
• a high load queue, 2 processes, 1GB limit in horizon.php: for memory intensive jobs

Currently the high load queue requires us to raise PHP's memory_limit to 1GB. This also means our small queue jobs can now use up to 1GB of memory. Worst case resulting in 12GB memory usage due to concurrent jobs.

So for us the combination of the existing memory config and an additional php_memory_limit that sets the worker's memory_limit would be ideal.

[4n70w4]

It would also be nice at the start of the worker to write to the log or console that the memory limit of the horizon is higher than the memory limit of the interpreter. Or even prohibit start the worker in this case. To avoid false expectations.

[shanewiredin]

Any activity on this lately? We switched from regular queue workers to horizon recently, and are experiencing all the same issues reported in this thread. Additionally, the supervisor process (from horizon, not server supervisor.d) is taking way more memory than I would expect. Here's a screenshot showing 2 horizon instances (with 1 worker and 2 workers) using almost 2GB of memory (even though we have the horizon config at the default of 64MB).

Unfortunately this is impacting our server performance greatly, and we're going to have to abandon horizon and go back to regular queue workers, where we did not have this issue.

[hylke94]

Same issues here. We need te run an import from one system in the other system. So we hire a big server in the cloud (96 vcores + 600 GB ram). Even if we run only one worker with Horizon (limit in horizon queue settings on 4096(MB)), it still manages to fill all 600 GB of memory with a single worker (yes, I know, script limit in ini file is set to -1)..

Any progression on this issue so far?

Edit:
Managed to take a screenshot of it starting up:

[driesvints]

Locking to prevent more "progress report" comments which aren't useful at all. Anyone's free to send in a PR for this.

[driesvints]

Hi all, since this is something we won't be working on ourselves I'm going to close this. We are however, open to PRs if anyone's willing to work on one. Thanks.