`max_execution_time` reached too early

[Muffinman]

Description

Hi, I'm looking for some guidance in tracking down a very strange error with max_execution_time setting not being honoured correctly.

We have an incoming JSON POST request to a Laravel backend, which does some processing and stores some data.

The request is a few KB of tree data, and the controller calls a rebuildTree() method as below. Internally this makes a lot of calls to the MySQL DB and Redis DB.

Category::scoped(['site_key' => config('cms_scope')])
    ->rebuildTree($request->data);

The problem I'm facing is that this fails every time after 1 second with this error:

Maximum execution time of 30 seconds exceeded

I have added some debugging to the exception handler to try to work out why it is doing this:

var_dump(time() - $_SERVER['REQUEST_TIME']);
var_dump(getrusage());
var_dump(ini_get('max_execution_time'));
var_dump(error_get_last());

int(1) // Request had only been processing for ~1s before exception happened

array(17) {
  ["ru_oublock"]=>  int(0)
  ["ru_inblock"]=>  int(0)
  ["ru_msgsnd"]=>  int(43432)
  ["ru_msgrcv"]=>  int(51349)
  ["ru_maxrss"]=>  int(71073792)
  ["ru_ixrss"]=>  int(0)
  ["ru_idrss"]=>  int(0)
  ["ru_minflt"]=>  int(17193)
  ["ru_majflt"]=>  int(17)
  ["ru_nsignals"]=>  int(15)
  ["ru_nvcsw"]=>  int(7368)
  ["ru_nivcsw"]=>  int(104279)
  ["ru_nswap"]=>  int(0)
  ["ru_utime.tv_usec"]=>  int(212295)
  ["ru_utime.tv_sec"]=>  int(8)
  ["ru_stime.tv_usec"]=>  int(564183)
  ["ru_stime.tv_sec"]=>  int(1)
}

string(2) "30"

array(4) {
  ["type"]=>  int(1)
  ["message"]=>  string(45) "Maximum execution time of 30 seconds exceeded"
  ["file"]=>  string(112) "/path/to/site/vendor/laravel/framework/src/Illuminate/Redis/Connections/PhpRedisConnection.php"
  ["line"]=>  int(405)
}

Now for the next strange part, if I set the max_execution_time to some other far larger value, it works!

// set_time_limit(30); // Didn't work, same error
// set_time_limit(60); // Didn't work, same error
// set_time_limit(120); // Didn't work, same error
set_time_limit(300); // Works. Request completed in around 3.5s!
Category::scoped(['site_key' => config('cms_scope')])
    ->rebuildTree($request->data);

PHP Version

PHP 8.2.13

Operating System

MacOS 14.1.1

[iluuu1994]

Hi @Muffinman. Can you share a bit more about your setup? What web server + SAPI are you using? Are you using Octane or something similar by any chance?

[Muffinman]

Hi @iluuu1994 ,

I'm running the homebrew compiled php-fpm under nginx.

No octane in use, I only have php-redis and imagick extensions installed via pecl, everything else should be out of the box.

[iluuu1994]

That's odd. macOS should use (AFAIK) setitimer(ITIMER_REAL, ...) which doesn't even include IO time. So if anything, your request should allow to run for longer than the configured max_execution_time. Is this issue restricted to macOS or does it also occur on other operating systems?

[Muffinman]

I've only seen it on MacOS.

One other thing I've noticed is that if I replace the call to Category::rebuildTree() with a simple sleep(5), then the timeout problem does not happen, even though the request takes longer.

There must be something deep in that code which is causing PHP either to throw the wrong exception, or otherwise somehow miscount it's execution time.

[iluuu1994]

Unfortunately I don't have a (working) macOS machine to test this. Some minimal reproducer would be great, although I understand this might be tricky. It's also hard to rule out an error in php-redis itself.

[Muffinman]

Well I think I've managed to rule out php-redis, if I switch all the Laravel queue/cache drivers away from Redis the max_execution_time exception still happens, but instead happens in some Guzzle code.

Will keep experimenting to see if I can narrow it down further.

[jackwh]

@Muffinman I've got exactly the same issue, relieved to see it's not just me! Have you been able to find any clues?

In my case this affects both PHP 8.2.13, and a fresh clean install of PHP 8.3.0. Both running on macOS 14.1.2 using Valet (php-fpm + nginx). However, I was tipped off to the issue after a random page on my production server (running Ubuntu 18, PHP 8.2 and nginx) started throwing HTTP 500s and timing out. So this possibly also affects non-Mac environments as well.

Unfortunately it's not easy to debug further on production at the moment, as I've since had to make a short-term workaround to get the page running again. If any more clues come up I can try some specific tests though.

Other things I've noticed:

• No consistency in terms of which line throws the error, it just seems to get tangled up in various framework code each time
• If I add ini_set('max_execution_time', -1) the page loads after 2 or 3 seconds.
• If I change it to ini_set('max_execution_time', 30) (or 20, or 10, etc.) it still throws the error almost immediately. The error message also updates to show the configured timeout (e.g "Maximum execution time of 20 seconds"), so I know it's taking effect.
• I've searched the entire codebase (including vendor) for any scripts which might be overriding max_execution_time, set_time_limit(...), etc. but there are no occurrences

[iluuu1994]

Can any of you provide a reproducible codebase? If so, you can send it to me privately over email. If possible without dependencies (databases and whatnot).

[Muffinman]

No I didn't manage to track it down unfortunately. In my case I was able to mitigate it by pausing the Model events in Laravel.

I think it should be possible to create minimal a reproduction repo.