From https://integration.wikimedia.org/ci/job/php-compile-php84/6/console:
09:17:26 FAIL ExcimerProfiler max depth [tests/maxDepth.phpt]
Description
Description
Details
Details
Related Changes in Gerrit:
Related Objects
Related Objects
Event Timeline
Comment Actions
https://codesearch.wmcloud.org/search/?q=ExcimerProfiler+max+depth&files=&excludeFiles=&repos=
cat tmp.php
<?php $profiler = new ExcimerProfiler; $profiler->setEventType(EXCIMER_REAL); $profiler->setPeriod(0.1); $profiler->setMaxDepth(5); function foo( $depth ) { global $profiler; if ( $depth > 0 ) { foo( $depth - 1 ); } else { $profiler->start(); while (!count($profiler->getLog())) { usleep(10000); } $profiler->stop(); } } foo( 20 ); $log = $profiler->flush(); echo $log->formatCollapsed() . "\n";
$ php --version PHP 8.2.25 … $ php tmp.php excimer_truncated;foo;foo;foo;foo;foo;foo 1 $ echo "$EXPECTED" excimer_truncated;foo;foo;foo;foo;foo;foo %d
$ docker run --rm -it --entrypoint /bin/bash -v "$PWD":/src docker-registry.wikimedia.org/releng/composer-php84:8.4.1 nobody@c126592f3731:/$ php --version PHP 8.4.1 … nobody@c126592f3731:/$ cd /src && export EXPECTED="…" nobody@c126592f3731:/src$ php tmp.php excimer_truncated;foo;foo;foo;foo;foo 1 nobody@c126592f3731:/src$ echo "$EXPECTED" excimer_truncated;foo;foo;foo;foo;foo;foo %d
It looks like it has one fewer "foo"s on PHP 8.4.
Comment Actions
I've changed the test locall to give the frames more obvious names and order to them:
tests/maxDepth.phpt
--TEST-- ExcimerProfiler max depth --SKIPIF-- <?php if (!extension_loaded("excimer")) print "skip"; ?> --FILE-- <?php $profiler = new ExcimerProfiler; $profiler->setEventType(EXCIMER_REAL); $profiler->setPeriod(0.1); $profiler->setMaxDepth(5); function foo() { foo_1(); } function foo_1() { foo_2(); } function foo_2() { foo_3(); } function foo_3() { foo_4(); } function foo_4() { foo_5(); } function foo_5() { foo_6(); } function foo_6() { foo_7(); } function foo_7() { foo_8(); } function foo_8() { foo_9(); } function foo_9() { foo_10(); } function foo_10() { global $profiler; $profiler->start(); while (!count($profiler->getLog())) { usleep(10000); } $profiler->stop(); } foo(); $log = $profiler->flush(); echo $log->formatCollapsed() . "\n"; --EXPECTF-- excimer_truncated;foo_5;foo_6;foo_7;foo_8;foo_9;foo_10 %d
On PHP 8.1 - 8.3, this returns the status quo of:
excimer_truncated;foo_5;foo_6;foo_7;foo_8;foo_9;foo_10 1
This breaks down today as:
- foo_10 (depth=0, current function)
- foo_9 (depth=1)
- foo_8 (depth=2)
- foo_7 (depth=3)
- foo_6 (depth=4)
- foo_5 (depth=5)
- excimer_truncated
Which seems plausibly correct, but there's room for multiple of-by-one choices:
- From a consumer perspective you can expect "maxDepth" to represent the complete stack as returned, or the "real" stack before the "fake" excimer_truncated frame at the end of the stack.
- From a consumer, you may expect it to be the distance from top/current function (0-indexed), or total length (1-indexed).
- From the internal side, I can imagine that, if PHP manages the stack separately from the current in-progress function, maxDepth may be implemented in a way that applies to the former, after unconditionally starting with the current function name.
- From the internal side, we can stop traversing at the max, and then insert the fake frame, or we can stop traversing one before, so that the depth of real and fake together will end up within the max.
There isn't an obvious right or wrong to me, so long as the total length is within ~2 of the configured maxDepth.
Self-imposed requirements:
- Consistent behaviour across supported PHP versions for a given Excimer version.
- Behaviour can be easily explained and is within 0-2 of the configured maxDepth.
Having said that, the status quo output does look wrong to me. In the excimer_log_find_or_add_frame function, we insert the "fake" frame, if we meet the log->max_depth && depth >= log->max_depth condition. This suggests to me that when we start the depth=5 iteration, this condition evaluates to true. Yet, at least on PHP 8.3 and earlier, it inserts one more frame there, which surprises me.
On PHP 8.4 this returns:
excimer_truncated;foo_6;foo_7;foo_8;foo_9;foo_10 1
Note foo_5 missing, which actually makes more sense (per the above).
Debugging
diff --git a/excimer_log.c b/excimer_log.c index ba1c7fe12c..5d075a19d5 100644 --- a/excimer_log.c +++ b/excimer_log.c @@ -192,6 +192,7 @@ static uint32_t excimer_log_find_or_add_frame(excimer_log *log, } else if (!execute_data->prev_execute_data) { prev_index = 0; } else if (log->max_depth && depth >= log->max_depth) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] calling excimer_log_get_truncation_marker\n", depth, log->max_depth); prev_index = excimer_log_get_truncation_marker(log); } else { prev_index = excimer_log_find_or_add_frame(log, @@ -218,6 +219,7 @@ static uint32_t excimer_log_find_or_add_frame(excimer_log *log, if (func->common.function_name) { frame.function_name = func->common.function_name; + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] add frame for %s\n", depth, log->max_depth, ZSTR_VAL(frame.function_name)); zend_string_addref(frame.function_name); } diff --git a/tests/maxDepth.phpt b/tests/maxDepth.phpt index e09c6e8de4..84b1b4630c 100644 --- a/tests/maxDepth.phpt +++ b/tests/maxDepth.phpt @@ -10,24 +10,49 @@ $profiler->setEventType(EXCIMER_REAL); $profiler->setPeriod(0.1); $profiler->setMaxDepth(5); -function foo( $depth ) { +function foo() { + foo_1(); +} +function foo_1() { + foo_2(); +} +function foo_2() { + foo_3(); +} +function foo_3() { + foo_4(); +} +function foo_4() { + foo_5(); +} +function foo_5() { + foo_6(); +} +function foo_6() { + foo_7(); +} +function foo_7() { + foo_8(); +} +function foo_8() { + foo_9(); +} +function foo_9() { + foo_10(); +} +function foo_10() { global $profiler; - - if ( $depth > 0 ) { - foo( $depth - 1 ); - } else { - $profiler->start(); - while (!count($profiler->getLog())) { - usleep(10000); - } - $profiler->stop(); + $profiler->start(); + while (!count($profiler->getLog())) { + usleep(10000); } + $profiler->stop(); } -foo( 20 ); +foo(); $log = $profiler->flush(); echo $log->formatCollapsed() . "\n"; --EXPECTF-- -excimer_truncated;foo;foo;foo;foo;foo;foo %d +excimer_truncated;foo_5;foo_6;foo_7;foo_8;foo_9;foo_10 %d
PHP 8.2
$ php --version PHP 8.2.27 # clean compile excimer$ git clean -dffx && phpize && ./configure && make && make install && make test … $ run test standalone excimer$ php -n -d extension_dir="$PWD/modules/" -d extension=excimer tests/maxDepth.php excimer_log_find_or_add_frame [depth=5 max_depth=5] calling excimer_log_get_truncation_marker excimer_log_find_or_add_frame [depth=5 max_depth=5] add frame for foo_5 excimer_log_find_or_add_frame [depth=4 max_depth=5] add frame for foo_6 excimer_log_find_or_add_frame [depth=3 max_depth=5] add frame for foo_7 excimer_log_find_or_add_frame [depth=2 max_depth=5] add frame for foo_8 excimer_log_find_or_add_frame [depth=1 max_depth=5] add frame for foo_9 excimer_log_find_or_add_frame [depth=0 max_depth=5] add frame for foo_10 excimer_truncated;foo_5;foo_6;foo_7;foo_8;foo_9;foo_10 1
PHP 8.4
$ brew unlink php@8.2 && brew link php@8.4 … $ php --version PHP 8.4.8 excimer$ git clean -dffx && phpize && ./configure && make && make install && make test … excimer$ php -n -d extension_dir="$PWD/modules/" -d extension=excimer tests/maxDepth.php excimer_log_find_or_add_frame [depth=5 max_depth=5] calling excimer_log_get_truncation_marker excimer_log_find_or_add_frame [depth=5 max_depth=5] add frame for foo_6 excimer_log_find_or_add_frame [depth=4 max_depth=5] add frame for foo_7 excimer_log_find_or_add_frame [depth=3 max_depth=5] add frame for foo_8 excimer_log_find_or_add_frame [depth=2 max_depth=5] add frame for foo_9 excimer_log_find_or_add_frame [depth=1 max_depth=5] add frame for foo_10 excimer_truncated;foo_6;foo_7;foo_8;foo_9;foo_10 1
Observations
Firstly, iteration depth=5 seemingly runs twice on both versions. That surprises me.
Secondly, it seems we're actually iterating upward and starting from the middle. My understanding so far is that the stack starts at the current function, and is (or is similar to) a linked list where we don't know how far it goes unless we follow the chain. So the fact that we seem know exactly where to start (the deepest we're allowed) and then go back up, is very elegant and helpful. I imagine this isn't the default, but something Tim made so that we can get the output we need by simply appending each chunk, building it up from left to right. However, I haven't yet found where we give us this magic starting point.
Thirdly, on PHP 8.4 we're ending (or starting) at depth=1 instead of depth=0. That's the obvious surface-level difference and will presumably point to a root cause.
Comment Actions
So it seems on PHP 8.4, we have an extra execute_data layer on top at depth 0 that is non-null, but lacks function data. And so we have essentially a null frame that we don't show but occupies an iteration none-the-less. This new phantom frame does have a prev_execute_data pointer, and it points to the top frame that we wanted to start at. So nothing is actually missing from the stack, but we have this extra one that we need to step through?
!execute_data->func || !ZEND_USER_CODE(execute_data->func->common.type))
I don't know what that means yet.
$ php --version PHP 8.2.27 $ (compile) … $ php -n -d extension_dir="$PWD/modules/" -d extension=excimer tests/maxDepth.php excimer_log_find_or_add_frame [depth=5 max_depth=5] calling excimer_log_get_truncation_marker excimer_log_find_or_add_frame [depth=5 max_depth=5] add frame for foo_5 excimer_log_find_or_add_frame [depth=4 max_depth=5] add frame for foo_6 excimer_log_find_or_add_frame [depth=3 max_depth=5] add frame for foo_7 excimer_log_find_or_add_frame [depth=2 max_depth=5] add frame for foo_8 excimer_log_find_or_add_frame [depth=1 max_depth=5] add frame for foo_9 excimer_log_find_or_add_frame [depth=0 max_depth=5] add frame for foo_10 excimer_truncated;foo_5;foo_6;foo_7;foo_8;foo_9;foo_10 1
$ php --version PHP 8.4.8 $ php -n -d extension_dir="$PWD/modules/" -d extension=excimer tests/maxDepth.php excimer_log_find_or_add_frame [depth=5 max_depth=5] calling excimer_log_get_truncation_marker excimer_log_find_or_add_frame [depth=5 max_depth=5] add frame for foo_6 excimer_log_find_or_add_frame [depth=4 max_depth=5] add frame for foo_7 excimer_log_find_or_add_frame [depth=3 max_depth=5] add frame for foo_8 excimer_log_find_or_add_frame [depth=2 max_depth=5] add frame for foo_9 excimer_log_find_or_add_frame [depth=1 max_depth=5] add frame for foo_10 excimer_log_find_or_add_frame [depth=0 max_depth=5] stop, no execute_data-func excimer_truncated;foo_6;foo_7;foo_8;foo_9;foo_10 1
excimer_log_find_or_add_frame [depth=0 max_depth=5] stop, no execute_data-func
Debugging diff
diff --git a/excimer_log.c b/excimer_log.c index ba1c7fe12c..b472f49ac7 100644 --- a/excimer_log.c +++ b/excimer_log.c @@ -188,10 +188,13 @@ static uint32_t excimer_log_find_or_add_frame(excimer_log *log, { uint32_t prev_index; if (!execute_data) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] stop, no execute_data\n", depth, log->max_depth); return 0; } else if (!execute_data->prev_execute_data) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] assume prev=0, no execute_data-prev\n", depth, log->max_depth); prev_index = 0; } else if (log->max_depth && depth >= log->max_depth) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] calling excimer_log_get_truncation_marker\n", depth, log->max_depth); prev_index = excimer_log_get_truncation_marker(log); } else { prev_index = excimer_log_find_or_add_frame(log, @@ -200,6 +203,7 @@ static uint32_t excimer_log_find_or_add_frame(excimer_log *log, if (!execute_data->func || !ZEND_USER_CODE(execute_data->func->common.type)) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] stop, no execute_data-func\n", depth, log->max_depth); return prev_index; } else { zend_function *func = execute_data->func; @@ -218,6 +222,7 @@ static uint32_t excimer_log_find_or_add_frame(excimer_log *log, if (func->common.function_name) { frame.function_name = func->common.function_name; + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] add frame for %s\n", depth, log->max_depth, ZSTR_VAL(frame.function_name)); zend_string_addref(frame.function_name); } diff --git a/tests/maxDepth.phpt b/tests/maxDepth.phpt index e09c6e8de4..84b1b4630c 100644 --- a/tests/maxDepth.phpt +++ b/tests/maxDepth.phpt @@ -10,24 +10,49 @@ $profiler->setEventType(EXCIMER_REAL); $profiler->setPeriod(0.1); $profiler->setMaxDepth(5); -function foo( $depth ) { +function foo() { + foo_1(); +} +function foo_1() { + foo_2(); +} +function foo_2() { + foo_3(); +} +function foo_3() { + foo_4(); +} +function foo_4() { + foo_5(); +} +function foo_5() { + foo_6(); +} +function foo_6() { + foo_7(); +} +function foo_7() { + foo_8(); +} +function foo_8() { + foo_9(); +} +function foo_9() { + foo_10(); +} +function foo_10() { global $profiler; - - if ( $depth > 0 ) { - foo( $depth - 1 ); - } else { - $profiler->start(); - while (!count($profiler->getLog())) { - usleep(10000); - } - $profiler->stop(); + $profiler->start(); + while (!count($profiler->getLog())) { + usleep(10000); } + $profiler->stop(); } -foo( 20 ); +foo(); $log = $profiler->flush(); echo $log->formatCollapsed() . "\n"; --EXPECTF-- -excimer_truncated;foo;foo;foo;foo;foo;foo %d +excimer_truncated;foo_5;foo_6;foo_7;foo_8;foo_9;foo_10 %d
Comment Actions
The top-most mystery frame on PHP 8.4 is usleep().
$ php --versioon PHP 8.4.8 $ php -n -d extension_dir="$PWD/modules/" -d extension=excimer tests/maxDepth.php excimer_log_find_or_add_frame [depth=5 max_depth=5] calling excimer_log_get_truncation_marker excimer_log_find_or_add_frame [depth=5 max_depth=5] add frame for foo_6 excimer_log_find_or_add_frame [depth=4 max_depth=5] add frame for foo_7 excimer_log_find_or_add_frame [depth=3 max_depth=5] add frame for foo_8 excimer_log_find_or_add_frame [depth=2 max_depth=5] add frame for foo_9 excimer_log_find_or_add_frame [depth=1 max_depth=5] add frame for foo_10 excimer_log_find_or_add_frame [depth=0 max_depth=5] stop, non-user fn: usleep excimer_truncated;foo_6;foo_7;foo_8;foo_9;foo_10 1
Debugging diff
diff --git a/excimer_log.c b/excimer_log.c index ba1c7fe12c..fa0988b2f6 100644 --- a/excimer_log.c +++ b/excimer_log.c @@ -188,18 +188,27 @@ static uint32_t excimer_log_find_or_add_frame(excimer_log *log, { uint32_t prev_index; if (!execute_data) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] stop, no execute_data\n", depth, log->max_depth); return 0; } else if (!execute_data->prev_execute_data) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] assume prev=0, no execute_data-prev\n", depth, log->max_depth); prev_index = 0; } else if (log->max_depth && depth >= log->max_depth) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] calling excimer_log_get_truncation_marker\n", depth, log->max_depth); prev_index = excimer_log_get_truncation_marker(log); } else { prev_index = excimer_log_find_or_add_frame(log, execute_data->prev_execute_data, depth + 1); } - if (!execute_data->func - || !ZEND_USER_CODE(execute_data->func->common.type)) - { + if (!execute_data->func) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] stop, no execute_data-func\n", depth, log->max_depth); + return prev_index; + } else if (!ZEND_USER_CODE(execute_data->func->common.type)) { + if (!execute_data->func->common.function_name) { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] stop, unnamed non-user fn\n", depth, log->max_depth); + } else { + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] stop, non-user fn: %s\n", depth, log->max_depth, ZSTR_VAL(execute_data->func->common.function_name)); + } return prev_index; } else { zend_function *func = execute_data->func; @@ -218,6 +227,7 @@ static uint32_t excimer_log_find_or_add_frame(excimer_log *log, if (func->common.function_name) { frame.function_name = func->common.function_name; + printf("excimer_log_find_or_add_frame [depth=%d max_depth=%d] add frame for %s\n", depth, log->max_depth, ZSTR_VAL(frame.function_name)); zend_string_addref(frame.function_name); } diff --git a/tests/maxDepth.phpt b/tests/maxDepth.phpt index e09c6e8de4..84b1b4630c 100644 --- a/tests/maxDepth.phpt +++ b/tests/maxDepth.phpt @@ -10,24 +10,49 @@ $profiler->setEventType(EXCIMER_REAL); $profiler->setPeriod(0.1); $profiler->setMaxDepth(5); -function foo( $depth ) { +function foo() { + foo_1(); +} +function foo_1() { + foo_2(); +} +function foo_2() { + foo_3(); +} +function foo_3() { + foo_4(); +} +function foo_4() { + foo_5(); +} +function foo_5() { + foo_6(); +} +function foo_6() { + foo_7(); +} +function foo_7() { + foo_8(); +} +function foo_8() { + foo_9(); +} +function foo_9() { + foo_10(); +} +function foo_10() { global $profiler; - - if ( $depth > 0 ) { - foo( $depth - 1 ); - } else { - $profiler->start(); - while (!count($profiler->getLog())) { - usleep(10000); - } - $profiler->stop(); + $profiler->start(); + while (!count($profiler->getLog())) { + usleep(10000); } + $profiler->stop(); } -foo( 20 ); +foo(); $log = $profiler->flush(); echo $log->formatCollapsed() . "\n"; --EXPECTF-- -excimer_truncated;foo;foo;foo;foo;foo;foo %d +excimer_truncated;foo_5;foo_6;foo_7;foo_8;foo_9;foo_10 %d
Comment Actions
I've traced the call to ExcimerProfiler_event, which in turn is called from excimer_timer_init via the Zend vm_interrupt.
I've not run git-blame on upstream PHP as I'd rather not sidetrack into compiling PHP myself. But I did check some upstream places for anything obvious in relation to "interrupt", call "stack", back "traces":
- https://github.com/php/php-src/blob/php-8.4.8/NEWS: Nope.
- https://github.com/php/php-src/blob/php-8.4.8/UPGRADING.INTERNALS: Nothing stands out.
- Pull requests and issues:
- https://github.com/php/php-src/pull/14627: Yep, I think that's it.
This patch did update UPGRADING.INTERNALS but I missed it. I see it now.
So this seems intentional at least. And could be interesting to explore, but apart from leafs, I do see value in continuing to ignore these as you'd otherwise, presumably, have more noise mid-way in traces from things like array_map. I'll leave that to a future change to explore.
To make this test pass, I don't think we want to omit this from the count as that would open us up to traversing a potentially very deep stack without enforcing a limit. So that leaves loosening the "EXPECT" pattern to accomodate older PHP versions returning one more frame than PHP 8.4+. I'm not sure how feature rich this assertion pattern is, but from what I read at https://www.phpinternalsbook.com/tests/phpt_file_structure.html the only thing we can do is allow for a wildcard %s to be present. Something like:
excimer_truncated;%sfoo_6;foo_7;foo_8;foo_9;foo_10 %d
The downside of this is that it basically means we're not asserting that it limits the stack because that %s could obscure 1 frame (like we want) or all 5 frames. I think what I'll do is name the functions a bit more creatively, and assert excimer_truncated;foo_%s;foo_7 where foo_5 and foo_6 are named as today and so either one or both of them may be there, but foo_1 through foo_4 I'll rename to not start with "foo" so we'll know it definitely stopped after the 5th.
Comment Actions
Change #1157103 had a related patch set uploaded (by Krinkle; author: Krinkle):
[mediawiki/php/excimer@master] tests: Accomodate PHP 8.4 support for internal frames
Comment Actions
Change #1157104 had a related patch set uploaded (by Krinkle; author: Krinkle):
[integration/config@master] zuul: Enable php-compile-php84 for Excimer repo
Comment Actions
Change #1157104 merged by jenkins-bot:
[integration/config@master] zuul: Enable php-compile-php84 for Excimer repo
Comment Actions
Change #1157103 merged by jenkins-bot:
[mediawiki/php/excimer@master] tests: Accomodate PHP 8.4 support for internal frames
Comment Actions
Just to check, the test changes above don't need a new release, right? If so, can this be deemed Resolved?
Comment Actions
I believe Remi (https://rpms.remirepo.net/) and Sury (https://deb.sury.org/) both package these for PHP 8.4, and that involves passing make test. For example, Remi reported an issue from their pipeline preventing the publishing of the package for PHP 8.4 last year, at https://github.com/wikimedia/mediawiki-php-excimer/pull/8, due to a different issue that we since fixed.
I've not heard from either of them since then. In the past that sometimes meant they've stopped building it and not retried yet (which would be bad for us, stale/missing package).
Looking at it now, they both seem to publish the latest version (php-excimer 1.2.5) in their respective php84 channels. I'm not sure how, but I guess that means we don't need to release this.
https://rpms.remirepo.net/wizard/
Fedora 42 with PHP 8.4 from Remirepo
$ docker run --rm --interactive --tty /bin/sh fedora:42 -c "bash" # dnf install https://rpms.remirepo.net/fedora/remi-release-42.rpm … # dnf config-manager setopt remi.enabled=1 # dnf module reset php # dnf module enable php:remi-8.4 # dnf install php-cli … # dnf install php-excimer … php-pecl-excimer aarch64 1.2.5-1.fc42.remi.8.4 remi-modular …
Ubuntu 24 with PHP 8.4 from Sury
$ docker run --rm --interactive --tty /bin/sh ubuntu:24.04 -c "bash" # add-apt-repository ppa:ondrej/php … # apt info php8.4-excimer Package: php8.4-excimer Version: 1.2.5-1+ubuntu24.04.1+deb.sury.org+1 … # apt install php8.4-excimer … # php -i | grep excimer /etc/php/8.4/cli/conf.d/20-excimer.ini, excimer excimer support => enabled excimer version => 1.2.5 …