Opcache is generating different observer output

[mvorisek]

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:
<!-- init TestClass::{closure}() --> shown 3x

But I expected this output instead:
<!-- init TestClass::{closure}() --> 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

[dstogov]

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]

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

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

[iluuu1994]

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]

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]

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]

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

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

[bwoebi]

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

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.