Opcache is generating different observer output #10782

mvorisek · 2023-03-04T19:41:47Z

Description

The following code:

--TEST--
Observer: Basic observability of userland methods
--EXTENSIONS--
zend_test
--INI--
zend_test.observer.enabled=1
zend_test.observer.observe_all=1
--FILE--
<?php
class TestClass
{
    private function bar()
    {
        echo 'Bar' . PHP_EOL;
        var_dump(array_reduce([1, 2, 3], fn ($a, $b) => $a + $b));
    }

    public function foo()
    {
        echo 'Foo' . PHP_EOL;
        $this->bar();
    }
}

$test = new TestClass();
$test->foo();
$test->foo();
$test->foo();

echo 'DONE' . PHP_EOL;
?>

Resulted in this output:
 shown 3x

But I expected this output instead:
 shown only once (as when run without opcache)

CI: https://github.com/php/php-src/actions/runs/4332385117/jobs/7564838868#step:10:156

/cc @dstogov

PHP Version

master with opcache

Operating System

any

The text was updated successfully, but these errors were encountered:

dstogov · 2023-03-06T08:46:51Z

I've run you test with and without JIT (php master branch), and I don't see any difference

$ php -d opcache.jit=0 -d zend_test.observer.enabled=1 -d zend_test.observer.observe_all=1 test.php >1.log
$ php -d opcache.jit=1205 -d zend_test.observer.enabled=1 -d zend_test.observer.observe_all=1 test.php >2.log
$ diff 1.log 2.log

So the problem is not related to JIT.
Some how I see a different output when I run the same test without opcache

$ php -n -d zend_test.observer.enabled=1 -d zend_test.observer.observe_all=1 test.php >3.log
$ diff -u 1.log 3.log
--- 1.log	2023-03-06 11:28:28.789999393 +0300
+++ 3.log	2023-03-06 11:33:03.102818834 +0300
@@ -27,7 +27,6 @@
     <TestClass::bar>
 Bar
       <array_reduce>
-        <!-- init TestClass::{closure}() -->
         <TestClass::{closure}>
         </TestClass::{closure}>
         <TestClass::{closure}>
@@ -45,7 +44,6 @@
     <TestClass::bar>
 Bar
       <array_reduce>
-        <!-- init TestClass::{closure}() -->
         <TestClass::{closure}>
         </TestClass::{closure}>
         <TestClass::{closure}>

@mvorisek please verify and correct the bug report.
It seems the problem is related to observer API and opcache integration.
I have no idea what this <!-- init means, and how it's cached by observer.
@bwoebi can you take a look?

bwoebi · 2023-03-06T10:35:24Z

@dstogov The difference is that with opcache all instances have a different run_time_cache, and the init method of the observer API is called for each run_time_cache individually (which is expected).

Now, as to why this happens: with opcache func->common.fn_flags & ZEND_ACC_IMMUTABLE is true and in that case we cannot store the scope on the zend_op_array struct if it's different and thus not create a shared run_time_cache for that scope in zend_create_closure_ex.

It however indicates that we're incidentally de-optimizing Closures in opcache as they, when used in class context, will always have scope = NULL when compiled and thus not have a shared run_time_cache.

With this one-liner fix, it should behave as expected:

diff --git a/Zend/zend_compile.c b/Zend/zend_compile.c
index 711f33b568..cdbf13224a 100644
--- a/Zend/zend_compile.c
+++ b/Zend/zend_compile.c
@@ -7463,6 +7463,7 @@ static void zend_compile_func_decl(znode *result, zend_ast *ast, bool toplevel)
 
        if (decl->kind == ZEND_AST_CLOSURE || decl->kind == ZEND_AST_ARROW_FUNC) {
                op_array->fn_flags |= ZEND_ACC_CLOSURE;
+               op_array->scope = CG(active_class_entry);
        }
 
        if (is_method) {

bwoebi · 2023-03-06T10:36:37Z

I haven't verified right now, but checking the code of prior versions that issue seems to exist since forever?

iluuu1994 · 2023-03-06T12:12:39Z

Simplified test-case:

--TEST--
GH-10782: Multiple closure init calls when opcache is enabled
--EXTENSIONS--
zend_test
--INI--
zend_test.observer.enabled=1
zend_test.observer.observe_functions=1
--FILE--
<?php
class TestClass {
    public function foo() {
        (function () {})();
    }
}

$test = new TestClass();
$test->foo();
$test->foo();
?>
--EXPECTF--
<!-- init '%sobserver_gh10782.php' -->
<!-- init TestClass::foo() -->
<TestClass::foo>
  <!-- init TestClass::{closure}() -->
  <TestClass::{closure}>
  </TestClass::{closure}>
</TestClass::foo>
<TestClass::foo>
  <TestClass::{closure}>
  </TestClass::{closure}>
</TestClass::foo>

I can verify Bobs patch fixes the test but does break these tests:

Zend/tests/closure_033.phpt
Zend/tests/nested_method_and_function.phpt
Zend/tests/no_class_const_propagation_in_closures.phpt

bwoebi · 2023-03-06T13:27:05Z

Yes, I assume in a couple places we need to explicitly check against ZEND_ACC_CLOSURE to ignore the constant evaluation in compiler/opcache then. Was just a quick and dirty suggestion to point out where the issue lies.

dstogov · 2023-03-06T19:30:48Z

The difference in output with and without opcache caused by zend_create_closure_ex(). For muttable op_arrays we use scope and run_time_cache to cache the last used values, but we can't store anything in scope for immutable ones. It's possible change this to always behave like with opcache, but not in the other direction.

bwoebi · 2023-03-06T21:07:57Z

@dstogov Not quite - if we default to the scope the closure will have on creation, which is the class the closure is created in, then opcache and non-opcache behaviour match. The only time this will not be the case is with Closures declared in trait methods.

dstogov · 2023-03-06T21:28:09Z

@bwoebi also take into account Closure::bind() that may change the scope of closure.

bwoebi · 2023-03-06T21:30:16Z

@dstogov That's right, but that happens on already instantiated Closures - i.e. Closures which initially had the scope of their containing class. In that case also without opcache we'll instantiate a new run_time_cache.

dstogov · 2023-03-06T23:00:13Z

I seems this may be fixed by the following patch.

diff --git a/Zend/Optimizer/zend_optimizer.c b/Zend/Optimizer/zend_optimizer.c
index 956a13d658..864de05f18 100644
--- a/Zend/Optimizer/zend_optimizer.c
+++ b/Zend/Optimizer/zend_optimizer.c
@@ -817,6 +817,7 @@ zend_class_entry *zend_optimizer_get_class_entry_from_op1(
 		}
 	} else if (opline->op1_type == IS_UNUSED && op_array->scope
 			&& !(op_array->scope->ce_flags & ZEND_ACC_TRAIT)
+			&& !(op_array->fn_flags & ZEND_ACC_CLOSURE)
 			&& (opline->op1.num & ZEND_FETCH_CLASS_MASK) == ZEND_FETCH_CLASS_SELF) {
 		return op_array->scope;
 	}
diff --git a/Zend/zend_compile.c b/Zend/zend_compile.c
index 711f33b568..0d803a0e10 100644
--- a/Zend/zend_compile.c
+++ b/Zend/zend_compile.c
@@ -7564,6 +7564,12 @@ static void zend_compile_func_decl(znode *result, zend_ast *ast, bool toplevel)
 
 	CG(active_op_array) = orig_op_array;
 	CG(active_class_entry) = orig_class_entry;
+
+	if ((op_array->fn_flags & ZEND_ACC_CLOSURE)
+	 && CG(active_class_entry)
+	 && !(CG(active_class_entry)->ce_flags & ZEND_ACC_TRAIT)) {
+		op_array->scope = CG(active_class_entry);
+	}
 }
 /* }}} */

but I'm not sure if this may lead to other problem uncovered by the tests.
As this won't make behaviour with and without opcache completely equivalent, I'm not sure if we should try to fix this at all.

bwoebi · 2023-03-06T23:02:22Z

I still think it's worth fixing it as it allows run_time_cache reuse at all in the generic case for closures (in class scope where 90% of PHP code lives today), less because it fixes this particular issue. I consider it more a performance fix than a correctness fix.

dstogov · 2023-03-07T13:01:32Z

@bwoebi I see your concern and it makes sense. I just don't like introducing a quick incomplete fix.

Closures are not statically bind to some scope, this is why originally they have op_array->scope == NULL. If we set it during compilation, that may trigger some unexpected code generation or optimization in PHP compiler, optimizer and JIT. Of course, we may fix all possible places by adding !(op_array->fn_flags & ZEND_ACC_CLOSURE) check. But anyway, this won't work if closure is defined in a trait.

It would be great to think about a more general fix. E.g. keeping scope + run_time_cache somewhere else. May be in a polymorphic cache slots of the caller's DECLARE_LAMBDA_FUNCTION, may be storing "scope" in the first slot of the closure's run_time_cache. May be I'm wrong and the simple patch above is good enough.

dstogov · 2023-03-07T13:03:49Z

It's also possible to delay closure->scope initialization until persistence in opcache.

bwoebi · 2023-03-09T20:16:23Z

@dstogov I'm totally fine with having a proper thought out fix.

A polymorphic cache slot does not work trivially, as run_time_cache memory does not have a destructor and that would leak (unless you store the run_time_caches somewhere else to be freed, but then it gets overly complicated...).

I think, actually, just storing the scope late in compiler and skipping scope-based optimizations in opcache is going to be the most straightforward way. I think that's less brittle than it seems.

arnaud-lb · 2025-05-14T13:18:51Z

Unfortunately, storing the scope late in compiler will still affect JIT assumptions. It would require to add !(op_array->fn_flags & ZEND_ACC_CLOSURE) checks in JIT.

storing "scope" in the first slot of the closure's run_time_cache

I think this would work

arnaud-lb · 2025-05-14T16:12:14Z

I've experimented storing the scope in the closure's run_time_cache: #18556. Unfortunately this results in a small performance regression.

mvorisek added Bug Status: Needs Triage labels Mar 4, 2023

mvorisek mentioned this issue Mar 4, 2023

Allow CTE on more CTE safe functions #10771

Closed

mvorisek changed the title ~~Opcache JIT is generating different observer output~~ Opcache is generating different observer output Mar 6, 2023

mvorisek mentioned this issue Mar 6, 2023

Fix zend_compile_func_decl scope #10794

Closed

Girgias added the Extension: opcache label Dec 5, 2023

mvorisek mentioned this issue May 9, 2024

Omit FETCH_THIS in closures #14181

Closed

mvorisek mentioned this issue May 14, 2025

zend_compile: Set op_array->scope for Closures as compile time #18552

Closed

TimWolla marked this as a duplicate of #18546 May 14, 2025

arnaud-lb mentioned this issue May 14, 2025

Allow Closures to reuse their run_time_cache when opcache is enabled #18556

Draft

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Opcache is generating different observer output #10782

Opcache is generating different observer output #10782

mvorisek commented Mar 4, 2023 •

edited

Loading

dstogov commented Mar 6, 2023

bwoebi commented Mar 6, 2023 •

edited

Loading

bwoebi commented Mar 6, 2023 •

edited

Loading

iluuu1994 commented Mar 6, 2023

bwoebi commented Mar 6, 2023 •

edited

Loading

dstogov commented Mar 6, 2023

bwoebi commented Mar 6, 2023

dstogov commented Mar 6, 2023

bwoebi commented Mar 6, 2023

dstogov commented Mar 6, 2023

bwoebi commented Mar 6, 2023 •

edited

Loading

dstogov commented Mar 7, 2023 •

edited

Loading

dstogov commented Mar 7, 2023

bwoebi commented Mar 9, 2023

arnaud-lb commented May 14, 2025

arnaud-lb commented May 14, 2025

Opcache is generating different observer output #10782

Opcache is generating different observer output #10782

Comments

mvorisek commented Mar 4, 2023 • edited Loading

Description

PHP Version

Operating System

dstogov commented Mar 6, 2023

bwoebi commented Mar 6, 2023 • edited Loading

bwoebi commented Mar 6, 2023 • edited Loading

iluuu1994 commented Mar 6, 2023

bwoebi commented Mar 6, 2023 • edited Loading

dstogov commented Mar 6, 2023

bwoebi commented Mar 6, 2023

dstogov commented Mar 6, 2023

bwoebi commented Mar 6, 2023

dstogov commented Mar 6, 2023

bwoebi commented Mar 6, 2023 • edited Loading

dstogov commented Mar 7, 2023 • edited Loading

dstogov commented Mar 7, 2023

bwoebi commented Mar 9, 2023

arnaud-lb commented May 14, 2025

arnaud-lb commented May 14, 2025

mvorisek commented Mar 4, 2023 •

edited

Loading

bwoebi commented Mar 6, 2023 •

edited

Loading

bwoebi commented Mar 6, 2023 •

edited

Loading

bwoebi commented Mar 6, 2023 •

edited

Loading

bwoebi commented Mar 6, 2023 •

edited

Loading

dstogov commented Mar 7, 2023 •

edited

Loading