re-use sprintf() optimisation for printf()

[realFlowControl]

This PR piggybacks on #14546

test.php:

<?php$a = 'foo';
$b = 'bar';
ob_start();
for ($i = 0; $i < 100_000_000; $i++) {
printf("%s-%s", $a, $b);
ob_clean();
}
ob_end_clean();

See hyperfine run, where php-orig is without this patch:

hyperfine './php-orig -d opcache.enable_cli=1 test.php' './sapi/cli/php -d opcache.enable_cli=1 test.php'
Benchmark 1: ./php-orig -d opcache.enable_cli=1 test.php
Time (mean ± σ): 10.490 s ± 0.053 s [User: 10.421 s, System: 0.038 s]
Range (min … max): 10.443 s … 10.621 s 10 runs
Benchmark 2: ./sapi/cli/php -d opcache.enable_cli=1 test.php
Time (mean ± σ): 8.207 s ± 0.135 s [User: 8.100 s, System: 0.035 s]
Range (min … max): 8.077 s … 8.489 s 10 runs
Summary
./sapi/cli/php -d opcache.enable_cli=1 test.php ran
1.28 ± 0.02 times faster than ./php-orig -d opcache.enable_cli=1 test.php

The generated opcodes before optimizer:

./sapi/cli/php -d opcache.enable_cli=1 -d opcache.opt_debug_level=0x10000 test.php $_main:
; (lines=21, args=0, vars=3, tmps=13)
; (before optimizer)
; /usr/local/src/php/php-src/test.php:1-12
; return [] RANGE[0..0]
0000 ASSIGN CV0($a) string("foo")
0001 ASSIGN CV1($b) string("bar")
0002 INIT_FCALL 0 80 string("ob_start")
0003 DO_ICALL
0004 ASSIGN CV2($i) int(0)
0005 JMP 0016
0006 T8 = ROPE_INIT 3 CV0($a)
0007 T8 = ROPE_ADD 1 T8 string("-")
0008 T7 = ROPE_END 2 T8 CV1($b)
0009 T10 = COPY_TMP T7
0010 ECHO T7
0011 T11 = STRLEN T10
0012 FREE T11
0013 INIT_FCALL 0 80 string("ob_clean")
0014 DO_ICALL
0015 PRE_INC CV2($i)
0016 T14 = IS_SMALLER CV2($i) int(100000000)
0017 JMPNZ T14 0006
0018 INIT_FCALL 0 80 string("ob_end_clean")
0019 DO_ICALL
0020 RETURN int(1)

... and after optimizer:

./sapi/cli/php -d opcache.enable_cli=1 -d opcache.opt_debug_level=0x20000 test.php
$_main:
; (lines=18, args=0, vars=3, tmps=3)
; (after optimizer)
; /usr/local/src/php/php-src/test.php:1-12
0000 ASSIGN CV0($a) string("foo")
0001 ASSIGN CV1($b) string("bar")
0002 INIT_FCALL 0 80 string("ob_start")
0003 DO_ICALL
0004 ASSIGN CV2($i) int(0)
0005 JMP 0013
0006 T4 = ROPE_INIT 3 CV0($a)
0007 T4 = ROPE_ADD 1 T4 string("-")
0008 T3 = ROPE_END 2 T4 CV1($b)
0009 ECHO T3
0010 INIT_FCALL 0 80 string("ob_clean")
0011 DO_ICALL
0012 PRE_INC CV2($i)
0013 T3 = IS_SMALLER CV2($i) int(100000000)
0014 JMPNZ T3 0006
0015 INIT_FCALL 0 80 string("ob_end_clean")
0016 DO_ICALL
0017 RETURN int(1)

[realFlowControl]

There is one failing test now:

========DIFF========
001- Fatal error: Uncaught Error: Undefined constant "A" in %s:%d
002- Stack trace:
003- #0 %s(%d): getA()
004- #1 {main}
005- thrown in %s on line %d
001+ A=hello
========DONE========
FAIL Bug #66251 (Constants get statically bound at compile time when Optimized) [ext/opcache/tests/bug66251.phpt] 

That test got introduced in https://bugs.php.net/bug.php?id=66251 and honestly I am not sure about what that test is actually testing ...

OPcodes for the test before this PR:

$ php -d opcache.enable=1 -d opcache.enable_cli=1 -d opcache.optimization_level=-1 -d opcache.opt_debug_level=0x20000 test_bug66251.php
$_main:
; (lines=8, args=0, vars=0, tmps=1)
; (after optimizer)
; /Users/florian.engelhardt/Work/php-src/test_bug66251.php:1-5
0000 INIT_FCALL 2 112 string("printf")
0001 SEND_VAL string("A=%s
") 1
0002 INIT_FCALL 0 96 string("geta")
0003 V0 = DO_UCALL
0004 SEND_VAR V0 2
0005 DO_ICALL
0006 DECLARE_CONST string("A") string("hello")
0007 RETURN int(1)
getA:
; (lines=2, args=0, vars=0, tmps=1)
; (after optimizer)
; /Users/florian.engelhardt/Work/php-src/test_bug66251.php:4-4
0000 T0 = FETCH_CONSTANT string("A")
0001 RETURN T0

and after:

./sapi/cli/php -d opcache.enable=1 -d opcache.enable_cli=1 -d opcache.optimization_level=-1 -d opcache.opt_debug_level=0x20000 test_bug66251.php
$_main:
; (lines=8, args=0, vars=0, tmps=3)
; (after optimizer)
; /Users/florian.engelhardt/Work/php-src/test_bug66251.php:1-5
0000 INIT_FCALL 0 80 string("geta")
0001 V0 = DO_UCALL
0002 T1 = ROPE_INIT 3 string("A=")
0003 T1 = ROPE_ADD 1 T1 V0
0004 T0 = ROPE_END 2 T1 string("\n")
0005 ECHO T0
0006 DECLARE_CONST string("A") string("hello")
0007 RETURN int(1)
LIVE RANGES:
0: 0002 - 0003 (tmp/var)
1: 0002 - 0004 (rope)
getA:
; (lines=1, args=0, vars=0, tmps=0)
; (after optimizer)
; /Users/florian.engelhardt/Work/php-src/test_bug66251.php:4-4
0000 RETURN string("hello")

[realFlowControl]

I just see that the sprintf() optimisation triggers the same behaviour (just replace the printf() call with a call to sprintf())

[realFlowControl]

@dstogov do you have an idea why the printf() opcode changes trigger the optimisation in the getA() function from:

0000 T0 = FETCH_CONSTANT string("A")

to

0000 RETURN string("hello")

[realFlowControl]

This is happening in pass1

php-src/Zend/Optimizer/pass1.c

Lines 149 to 161 in d25687b

	if (opline->op2_type==IS_CONST&&
	Z_TYPE(ZEND_OP2_LITERAL(opline)) ==IS_STRING) {
	/* substitute persistent constants */
	if (!zend_optimizer_get_persistent_constant(Z_STR(ZEND_OP2_LITERAL(opline)), &result, 1)) {
	if (!ctx->constants|| !zend_optimizer_get_collected_constant(ctx->constants, &ZEND_OP2_LITERAL(opline), &result)) {
	break;
	}
	}
	if (Z_TYPE(result) ==IS_CONSTANT_AST) {
	break;
	}
	replace_by_const_or_qm_assign(op_array, opline, &result);
	}

The problem seems to be that the ROPE optimisation removes the DO_ICALL which resets collect_constants to 0 in pass1.c, I played a bit with it and:

diff --git a/Zend/Optimizer/pass1.c b/Zend/Optimizer/pass1.c
index fe92db583fc..e83a87de5b8 100644
--- a/Zend/Optimizer/pass1.c+++ b/Zend/Optimizer/pass1.c@@ -264,6 +264,12 @@ void zend_optimizer_pass1(zend_op_array *op_array, zend_optimizer_ctx *ctx)
collect_constants = 0;
break;
}
+ case ZEND_DO_UCALL:+ case ZEND_DO_FCALL:+ case ZEND_DO_FCALL_BY_NAME:+ collect_constants = 0;+ break;
case ZEND_STRLEN:
if (opline->op1_type == IS_CONST &&
zend_optimizer_eval_strlen(&result, &ZEND_OP1_LITERAL(opline)) == SUCCESS) {

solves the issue, although this might have side effects beyond my understanding ..

I've applied this patch in 1526406 and CI is green, yet I fear that this has some consequences CI does not cover 😉

[realFlowControl]

So as expected, with 1526406 the behaviour changes for

<?phpechogetA();
constA="hello";
functiongetA() {return A;}

from:

$ php -d opcache.enable=1 -d opcache.enable_cli=1 -d opcache.optimization_level=-1 -d opcache.opt_debug_level=0x20000 test_bug66251.php
$_main:
; (lines=5, args=0, vars=0, tmps=1)
; (after optimizer)
; /Users/florian.engelhardt/Work/php-src/test_bug66251.php:1-5
0000 INIT_FCALL 0 80 string("geta")
0001 V0 = DO_UCALL
0002 ECHO V0
0003 DECLARE_CONST string("A") string("hello")
0004 RETURN int(1)
getA:
; (lines=1, args=0, vars=0, tmps=0)
; (after optimizer)
; /Users/florian.engelhardt/Work/php-src/test_bug66251.php:4-4
0000 RETURN string("hello")
hello% 

to:

./sapi/cli/php -d opcache.enable=1 -d opcache.enable_cli=1 -d opcache.optimization_level=-1 -d opcache.opt_debug_level=0x20000 test_bug66251.php
$_main:
; (lines=5, args=0, vars=0, tmps=1)
; (after optimizer)
; /Users/florian.engelhardt/Work/php-src/test_bug66251.php:1-5
0000 INIT_FCALL 0 96 string("geta")
0001 V0 = DO_UCALL
0002 ECHO V0
0003 DECLARE_CONST string("A") string("hello")
0004 RETURN int(1)
getA:
; (lines=2, args=0, vars=0, tmps=1)
; (after optimizer)
; /Users/florian.engelhardt/Work/php-src/test_bug66251.php:4-4
0000 T0 = FETCH_CONSTANT string("A")
0001 RETURN T0
Fatal error: Uncaught Error: Undefined constant "A" in /Users/florian.engelhardt/Work/php-src/test_bug66251.php:4
Stack trace:
#0 /Users/florian.engelhardt/Work/php-src/test_bug66251.php(2): getA()
#1 {main}
thrown in /Users/florian.engelhardt/Work/php-src/test_bug66251.php on line 4

[arnaud-lb]

This looks good to me. I will merge after 8.5 is branched if there are no other comments.

[kamil-tekiela]

@arnaud-lb Is this ready to be merged?

[TimWolla]

Can't comment on the Optimizer changes, the compiler changes LGTM.

[arnaud-lb]

Merged just now. Thank you @realFlowControl!