Opcache is generating different observer output

@dstogov

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

@mvorisek

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?

@dstogov

@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) {

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

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

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.

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.

@dstogov

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

@bwoebi

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

@dstogov

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

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.

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.

@bwoebi

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

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

@dstogov

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

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

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

Navigation Menu

Repository navigation

Opcache is generating different observer output #10782

Description

PHP Version

Operating System

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Opcache is generating different observer output #10782

Description

Description

PHP Version

Operating System

Activity

dstogov commented on Mar 6, 2023

bwoebi commented on Mar 6, 2023

bwoebi commented on Mar 6, 2023

iluuu1994 commented on Mar 6, 2023

bwoebi commented on Mar 6, 2023

dstogov commented on Mar 6, 2023

bwoebi commented on Mar 6, 2023

dstogov commented on Mar 6, 2023

bwoebi commented on Mar 6, 2023

dstogov commented on Mar 6, 2023

bwoebi commented on Mar 6, 2023

dstogov commented on Mar 7, 2023

dstogov commented on Mar 7, 2023

bwoebi commented on Mar 9, 2023

arnaud-lb commented on May 14, 2025

arnaud-lb commented on May 14, 2025

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions