php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #63160 Lot of fstat call during include
Submitted: 2012-09-25 08:09 UTC Modified: 2019-07-17 12:58 UTC
Votes:1
Avg. Score:4.0 ± 0.0
Reproduced:1 of 1 (100.0%)
Same Version:0 (0.0%)
Same OS:0 (0.0%)
From: remi@php.net Assigned: nikic (profile)
Status: Closed Package: Performance problem
PHP Version: 5.4.7 OS: GNU/Linux
Private report: No CVE-ID: None
 [2012-09-25 08:09 UTC] remi@php.net
Description:
------------
Hi,

Each "include" statement call fstat 3 time, which can be "slow" in some cluster environment (usgin GFS2 p.e.)

Already open as #49383 (but closed as "not a bug")

The fstat cache is only available inside "plain_wrapper".
A solution could be to expose a stream_cached_stat (in _php_stream_wrapper_ops) and use it during open process (or a additionnal parameter to stream_stat).

But this will introduce a important bc break.

Test script:
---------------
Trivial test code:
test1.php: <?php include('test2.php'); echo "done\n";
test2.php: irrevelant, can even be empty

$ strace php test1.php

Expected result:
----------------
...
open("xxx/test2.php", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=20, ...}) = 0
mmap(NULL, 20, PROT_READ, MAP_SHARED, 3, 0) = 0x7f0d595da000
munmap(0x7f0d595da000, 20)              = 0
close(3)    
...



Actual result:
--------------
...
open("xxx/test2.php", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=20, ...}) = 0
fstat(3, {st_mode=S_IFREG|0664, st_size=20, ...}) = 0
fstat(3, {st_mode=S_IFREG|0664, st_size=20, ...}) = 0
mmap(NULL, 20, PROT_READ, MAP_SHARED, 3, 0) = 0x7f0d595da000
munmap(0x7f0d595da000, 20)              = 0
close(3)    
...



Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2012-09-25 08:10 UTC] remi@php.net
Here is the backtrace for each fstat call

Breakpoint 1, do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=0) at /usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
138	{
(gdb) bt
#0  do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=0) at /usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
#1  0x0000000000581d0b in _php_stream_fopen (filename=<optimized out>, mode=0x6a3831 "rb", opened_path=0x7fffffffa7d0, options=<optimized out>) at /usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:967
#2  0x000000000057d4f2 in _php_stream_open_wrapper_ex (path=0x7ffff7fcb238 "/home/rcollet/test/test2.php", path@entry=0x7ffff7eba2e0 "test2.php", mode=mode@entry=0x6a3831 "rb", options=16520, 
    opened_path=opened_path@entry=0x7fffffffa7d0, context=context@entry=0x0) at /usr/src/debug/php-5.4.7/main/streams/streams.c:2049
#3  0x0000000000562a21 in php_stream_open_for_zend_ex (filename=0x7ffff7eba2e0 "test2.php", handle=0x7fffffffa7c0, mode=<optimized out>) at /usr/src/debug/php-5.4.7/main/main.c:1303
#4  0x00000000005d919c in zend_stream_fixup (file_handle=file_handle@entry=0x7fffffffa7c0, buf=buf@entry=0x7fffffffa500, len=len@entry=0x7fffffffa508) at /usr/src/debug/php-5.4.7/Zend/zend_stream.c:187
#5  0x000000000058de66 in open_file_for_scanning (file_handle=file_handle@entry=0x7fffffffa7c0) at Zend/zend_language_scanner.l:486
#6  0x000000000058e0f2 in compile_file (file_handle=0x7fffffffa7c0, type=2) at Zend/zend_language_scanner.l:569
#7  0x00007ffff01bbf5a in phar_compile_file (file_handle=0x7fffffffa7c0, type=2) at /usr/src/debug/php-5.4.7/ext/phar/phar.c:3388
#8  0x000000000058e2e0 in compile_filename (type=type@entry=2, filename=filename@entry=0x7ffff7fcc960) at Zend/zend_language_scanner.l:625
#9  0x00000000006079fb in ZEND_INCLUDE_OR_EVAL_SPEC_CONST_HANDLER (execute_data=0x7ffff7f97060) at /usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:2592
#10 0x0000000000623c47 in execute (op_array=0x7ffff7fcbaa8) at /usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:410
#11 0x00000000005c4a3c in zend_execute_scripts (type=type@entry=8, retval=retval@entry=0x0, file_count=file_count@entry=3) at /usr/src/debug/php-5.4.7/Zend/zend.c:1286
#12 0x00000000005645bd in php_execute_script (primary_file=primary_file@entry=0x7fffffffcd80) at /usr/src/debug/php-5.4.7/main/main.c:2473
#13 0x000000000066c5c6 in do_cli (argc=2, argv=0x7fffffffe218) at /usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:988
#14 0x0000000000425aaa in main (argc=2, argv=0x7fffffffe218) at /usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:1364
(gdb) c
Continuing.

Breakpoint 1, do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=1) at /usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
138	{
(gdb) bt
#0  do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=1) at /usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
#1  0x00000000005807fa in php_stdiop_stat (stream=<optimized out>, ssb=0x7fffffffa360) at /usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:546
#2  0x000000000056132f in php_zend_stream_fsizer (handle=handle@entry=0x7ffff7fcbfa0) at /usr/src/debug/php-5.4.7/main/main.c:1286
#3  0x0000000000562aaf in php_stream_open_for_zend_ex (filename=0x7ffff7eba2e0 "test2.php", handle=0x7fffffffa7c0, mode=<optimized out>) at /usr/src/debug/php-5.4.7/main/main.c:1318
#4  0x00000000005d919c in zend_stream_fixup (file_handle=file_handle@entry=0x7fffffffa7c0, buf=buf@entry=0x7fffffffa500, len=len@entry=0x7fffffffa508) at /usr/src/debug/php-5.4.7/Zend/zend_stream.c:187
#5  0x000000000058de66 in open_file_for_scanning (file_handle=file_handle@entry=0x7fffffffa7c0) at Zend/zend_language_scanner.l:486
#6  0x000000000058e0f2 in compile_file (file_handle=0x7fffffffa7c0, type=2) at Zend/zend_language_scanner.l:569
#7  0x00007ffff01bbf5a in phar_compile_file (file_handle=0x7fffffffa7c0, type=2) at /usr/src/debug/php-5.4.7/ext/phar/phar.c:3388
#8  0x000000000058e2e0 in compile_filename (type=type@entry=2, filename=filename@entry=0x7ffff7fcc960) at Zend/zend_language_scanner.l:625
#9  0x00000000006079fb in ZEND_INCLUDE_OR_EVAL_SPEC_CONST_HANDLER (execute_data=0x7ffff7f97060) at /usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:2592
#10 0x0000000000623c47 in execute (op_array=0x7ffff7fcbaa8) at /usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:410
#11 0x00000000005c4a3c in zend_execute_scripts (type=type@entry=8, retval=retval@entry=0x0, file_count=file_count@entry=3) at /usr/src/debug/php-5.4.7/Zend/zend.c:1286
#12 0x00000000005645bd in php_execute_script (primary_file=primary_file@entry=0x7fffffffcd80) at /usr/src/debug/php-5.4.7/main/main.c:2473
#13 0x000000000066c5c6 in do_cli (argc=2, argv=0x7fffffffe218) at /usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:988
#14 0x0000000000425aaa in main (argc=2, argv=0x7fffffffe218) at /usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:1364
(gdb) c
Continuing.

Breakpoint 1, do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=1) at /usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
138	{
(gdb) bt
#0  do_fstat (d=d@entry=0x7ffff7fcbed0, force=force@entry=1) at /usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:138
#1  0x00000000005807fa in php_stdiop_stat (stream=<optimized out>, ssb=0x7fffffffa3a0) at /usr/src/debug/php-5.4.7/main/streams/plain_wrapper.c:546
#2  0x000000000056132f in php_zend_stream_fsizer (handle=<optimized out>) at /usr/src/debug/php-5.4.7/main/main.c:1286
#3  0x00000000005d94b7 in zend_stream_fsize (file_handle=<optimized out>) at /usr/src/debug/php-5.4.7/Zend/zend_stream.c:115
#4  zend_stream_fixup (file_handle=file_handle@entry=0x7fffffffa7c0, buf=buf@entry=0x7fffffffa500, len=len@entry=0x7fffffffa508) at /usr/src/debug/php-5.4.7/Zend/zend_stream.c:222
#5  0x000000000058de66 in open_file_for_scanning (file_handle=file_handle@entry=0x7fffffffa7c0) at Zend/zend_language_scanner.l:486
#6  0x000000000058e0f2 in compile_file (file_handle=0x7fffffffa7c0, type=2) at Zend/zend_language_scanner.l:569
#7  0x00007ffff01bbf5a in phar_compile_file (file_handle=0x7fffffffa7c0, type=2) at /usr/src/debug/php-5.4.7/ext/phar/phar.c:3388
#8  0x000000000058e2e0 in compile_filename (type=type@entry=2, filename=filename@entry=0x7ffff7fcc960) at Zend/zend_language_scanner.l:625
#9  0x00000000006079fb in ZEND_INCLUDE_OR_EVAL_SPEC_CONST_HANDLER (execute_data=0x7ffff7f97060) at /usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:2592
#10 0x0000000000623c47 in execute (op_array=0x7ffff7fcbaa8) at /usr/src/debug/php-5.4.7/Zend/zend_vm_execute.h:410
#11 0x00000000005c4a3c in zend_execute_scripts (type=type@entry=8, retval=retval@entry=0x0, file_count=file_count@entry=3) at /usr/src/debug/php-5.4.7/Zend/zend.c:1286
#12 0x00000000005645bd in php_execute_script (primary_file=primary_file@entry=0x7fffffffcd80) at /usr/src/debug/php-5.4.7/main/main.c:2473
#13 0x000000000066c5c6 in do_cli (argc=2, argv=0x7fffffffe218) at /usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:988
#14 0x0000000000425aaa in main (argc=2, argv=0x7fffffffe218) at /usr/src/debug/php-5.4.7/sapi/cli/php_cli.c:1364
 [2012-09-25 09:27 UTC] laruence@php.net
the simple way is make the plain stream stat not force, like:
diff --git a/main/streams/plain_wrapper.c b/main/streams/plain_wrapper.c
index 80c22ce..2bc81a5 100644
--- a/main/streams/plain_wrapper.c
+++ b/main/streams/plain_wrapper.c
@@ -543,7 +543,7 @@ static int php_stdiop_stat(php_stream *stream, 
php_stream_statbuf *ssb TSRMLS_DC
 
 	assert(data != NULL);
 
-	ret = do_fstat(data, 1);
+	ret = do_fstat(data, 0);
 	memcpy(&ssb->sb, &data->sb, sizeof(ssb->sb));
 	return ret;
 }


but, this might introduce some unexpected issues. so, run with apc :)
 [2012-09-25 11:59 UTC] remi@php.net
I agree, APC is interesting (for lot of other reasons) and it reduces the 3 "fstat" calls to 2 "stat" calls.

Droping the "force" option doesn't seems acceptable ;)
 [2019-07-17 12:58 UTC] nikic@php.net
-Status: Open +Status: Closed -Assigned To: +Assigned To: nikic
 [2019-07-17 12:58 UTC] nikic@php.net
This is fixed in PHP 7.4. One goes away because we no longer use mmap and the other is removed in https://github.com/php/php-src/commit/07a4d134abd07690f9921eb0d0c7eeb671b0b875 by avoiding the "force" just for includes, where we don't need it.
 
PHP Copyright © 2001-2024 The PHP Group
All rights reserved.
Last updated: Fri Mar 29 09:01:28 2024 UTC