`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

[windaishi]

@dunglas Just saw your PR also resolves the issue. Will this be released for 8.2 and 8.3 when merged, because your PR is against master? If so, I think my PR can be closed.

[dunglas]

@windaishi I don't know what's the policy regarding this. Anyway, this patch currently has issues with the curl extension and we're still investigating if relying on libdispatch is the best option. cc @arnaud-lb @devnexen

[iluuu1994]

I think releasing this on macOS right away is risky. I think the safer bet might be to switch to ITIMER_REAL on macOS exclusively on older branches for now, and use the new mechanism in master. It might be good to discuss this on the mailing list first.

[arnaud-lb]

I agree. Before discussing on the list, could everyone confirm that https://github.com/php/php-src/pull/13567 fixes the issue? Also, do everyone confirm that it's a MacOS 14 + Apple Silicon issue?

[Pixelshaped]

On a dev machine, setting max_execution_time to 0 doesn't solve (as in "hide") the issue.

I'm getting Maximum execution time of 0 seconds exceeded messages, which is weird considering 0 is the default value for CLI and it disables max execution time correctly there.

Putting in a high value is a workaround in the meantime.

[arnaud-lb]

@Pixelshaped what version of MacOS do you have? Is it fully up to date? Does https://github.com/php/php-src/pull/13567 fix the issue for you?

@Mmaaikel @ejdanderson does :+1: mean that you still have the issue and https://github.com/php/php-src/pull/13567 fixes it?

[Herz3h]

Same issue here, Sonoma, php 8.1 (or 8.2, or 8.3), Symfony project. Error happening in different files from vendor (seems to be random).

13567 didn't work for me

[iluuu1994]

@Herz3h That's somewhat surprising. How did you test the patch?

[Herz3h]

@iluuu1994 I edited the php@8.2 homebrew formula, added patch at the end (patch just adds the OR condition like in the PR: || (defined(__aarch64__) && defined(__APPLE__)) )

[gabrielmagit]

I have the same issue, PHP 8.1, 8.2, and 8.3 (via Brew, updated in the past week), no matter what setting for max_execution_time, it thinks it's reached the max in a little less than half the time set (i.e. if 60 seconds, in about 20-some seconds, if 300 seconds, in about 170-some seconds)

MacBook Pro M1 Pro, Sonoma 14.4.1

[barto74]

I have the same issue with PHP 8.1, 8.2, 8.3 using Mamp PRO. The timeout error comes almost immediately. But it doesn't come always. Reloading the page sometimes makes it work, sometimes it throws the error again. Setting max_execution_time to -1 doesn't help.

I would really appreciate a fix or a workaround, developing is hardly possible now. Do we know if this is only an M1 Pro CPU issue? If it's not present on the M2/M3 etc, I would even replace my laptop.

MacBook Pro M1 Pro, Sonoma 14.4.1.

[NickIvanter]

Do we know if this is only an M1 Pro CPU issue?

I have exactly this same issue on M2. Using Mamp PRO. The issue began after upgrading to Sonoma.

[arnaud-lb]

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.

[arnaud-lb]

I've sent a message to internals and will merge https://github.com/php/php-src/pull/13567 if there are no objections.

[windaishi]

@arnaud-lb Did they reply yet? 😅

[arnaud-lb]

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

[arnaud-lb]

https://github.com/php/php-src/pull/13567 is now merged in 8.2 and 8.3.

[TheDigitalOrchard]

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

[vudaltsov]

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?

[vudaltsov]

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

[highfalutin]

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?

[jdecool]

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

[samuel-nogueira-kununu]

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.

[vudaltsov]

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