max_execution_time reached too early

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

@Muffinman

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?

@iluuu1994

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.

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?

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.

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.

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.

@Muffinman

@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

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).

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.

I was able to reproduce the issue on an M2 Pro with latest Sonoma (14.5). This is reproducible in pure C, and appears to be triggered/accelerated by other syscalls: https://gist.github.com/arnaud-lb/012195a2fe4d3a2c1bff530a73ae6b11

Switching to ITIMER_REAL fixes the issue in both PHP and the C reproducer.

I've sent a message to internals and will merge #13567 if there are no objections.

@arnaud-lb

@arnaud-lb Did they reply yet? 😅

There are no objections so far, so I will merge next week if it continues like that.

Use ITIMER_REAL for timeout handling on MacOS / Apple Silicon system

#13567 is now merged in 8.2 and 8.3.

I was seeing this on macOS and it was very puzzling! Glad to see it fixed in the latest release!

I've just upgraded PHP to 8.3.9 on M1 and here's what I see when running Psalm:

> php -v
PHP 8.3.9 (cli) (built: Jul  2 2024 14:10:14) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.3.9, Copyright (c) Zend Technologies
    with Zend OPcache v8.3.9, Copyright (c), by Zend Technologies
    with blackfire v1.92.18~mac-x64-non_zts83, https://blackfire.io, by Blackfire

> tools/psalm/vendor/bin/psalm --show-info --no-diff '--no-cache'
Target PHP version: 8.1 (inferred from composer.json) Enabled extensions: random.
Scanning files...
Analyzing files...

░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░  60 / 236 (25%)
░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ 120 / 236 (50%)
░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░ 180 / 236 (76%)
░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░░PHP Fatal error:  Maximum execution time of 0 seconds exceeded in /Users/vudaltsov/Projects/typhoon/typhoon/tools/psalm/vendor/vimeo/psalm/src/Psalm/Internal/Type/ParseTree.php on line 26
Fatal error: Maximum execution time of 0 seconds exceeded in /Users/vudaltsov/Projects/typhoon/typhoon/tools/psalm/vendor/vimeo/psalm/src/Psalm/Internal/Type/ParseTree.php on line 26

------------------------------
                              
       No errors found!       
                              
------------------------------
Psalm can automatically fix 6 of these issues.
Run Psalm again with 
--alter --issues=MissingParamType --dry-run
to see what it can fix.
------------------------------

Checks took 5.10 seconds and used 177.671MB of memory
Psalm was able to infer types for 99.4033% of the codebase

Never had this issue before. Could this be related?

Interestingly the error is not thrown when running psalm with --threads=1.

I'm still seeing the timeout error on my M1 mac, PHP 8.1.29. Was the fix only in 8.2 and 8.3?

Was the fix only in 8.2 and 8.3?

It seems. PHP 8.1 is not actively maintained anymore.

I use Homebrew throught https://github.com/shivammathur/homebrew-php which contains a patch for 8.1

@vudaltsov

I started seeing the same issue as @vudaltsov after upgrading from a 8.3.x version (don't remember which) to 8.3.9.
Also using homebrew PHP in a M3.
--threads=1 does stop that error for me as well.

Should we create a separate issue and a reproducer for this?

Navigation Menu

Repository navigation

`max_execution_time` reached too early #12814

Description

PHP Version

Operating System

54 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

max_execution_time reached too early #12814

Description

Description

PHP Version

Operating System

Activity

iluuu1994 commented on Nov 28, 2023

Muffinman commented on Nov 28, 2023

iluuu1994 commented on Nov 28, 2023

Muffinman commented on Nov 29, 2023

iluuu1994 commented on Nov 29, 2023

Muffinman commented on Nov 29, 2023

jackwh commented on Dec 4, 2023

iluuu1994 commented on Dec 4, 2023

Muffinman commented on Dec 4, 2023

54 remaining items

arnaud-lb commented on May 17, 2024

arnaud-lb commented on May 17, 2024

windaishi commented on May 23, 2024

arnaud-lb commented on May 24, 2024

arnaud-lb commented on May 28, 2024

TheDigitalOrchard commented on Jul 5, 2024

vudaltsov commented on Jul 12, 2024

vudaltsov commented on Jul 12, 2024

highfalutin commented on Jul 12, 2024

jdecool commented on Jul 12, 2024

samuel-nogueira-kununu commented on Aug 1, 2024

vudaltsov commented on Aug 1, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

`max_execution_time` reached too early #12814