#49383 [Bgs->Ana]: Lots of empty fstat() calls slow performance

ID: 49383 Updated by: rasmus@php.net Reported By: olga at metacafe dot com -Status: Bogus +Status: Analyzed Bug Type: Performance problem Operating System: Red Hat 3.4.6-10 PHP Version: 5.3, 6 New Comment: Still surprised these fstats take that long on your system. Note also that if you install APC, they completely go away. If you are down to caring about performance at the syscall level like that and you are not running a decent opcode cache, you are kind of confused. Here is a backtrace of those 3 fstats: #1 0x0137642f in do_fstat () #2 0x0137768f in _php_stream_fopen () #3 0x013719ba in _php_stream_open_wrapper_ex () #4 0x0135a1a3 in php_stream_open_for_zend_ex () #5 0x0135a2e0 in php_stream_open_for_zend () #6 0x013ca05f in zend_stream_fixup () #7 0x01383ae7 in open_file_for_scanning () #8 0x01383c8d in compile_file () #9 0x011eb8f7 in phar_compile_file () #10 0x013b4fa7 in zend_execute_scripts () #11 0x0135be38 in php_execute_script () #1 0x0137642f in do_fstat () #2 0x01376ee1 in php_stdiop_stat () #3 0x0135a148 in php_zend_stream_fsizer () #4 0x0135a206 in php_stream_open_for_zend_ex () #5 0x0135a2e0 in php_stream_open_for_zend () #6 0x013ca05f in zend_stream_fixup () #7 0x01383ae7 in open_file_for_scanning () #8 0x01383c8d in compile_file () #9 0x011eb8f7 in phar_compile_file () #10 0x013b4fa7 in zend_execute_scripts () #11 0x0135be38 in php_execute_script () #1 0x0137642f in do_fstat () #2 0x01377189 in php_stdiop_set_option () #3 0x0136fc8e in _php_stream_set_option () #4 0x0137dcec in _php_stream_mmap_range () #5 0x0135a295 in php_stream_open_for_zend_ex () #6 0x0135a2e0 in php_stream_open_for_zend () #7 0x013ca05f in zend_stream_fixup () #8 0x01383ae7 in open_file_for_scanning () #9 0x01383c8d in compile_file () #10 0x011eb8f7 in phar_compile_file () #11 0x013b4fa7 in zend_execute_scripts () #12 0x0135be38 in php_execute_script () The do_fstat() function has a cache, but those 3 calls set the 'force' flag to ignore the cached stat struct. We need to track down whether it is possible to not force these. It seems like it should be possible to get rid of at least one of those, if not 2. But again, install an opcode cache, and this stops being a problem. Previous Comments: ------------------------------------------------------------------------ [2009-09-03 12:59:44] olga at metacafe dot com Turning all messages on/off didn't change the behavior. We tend eliminate the notices on the development stage. Can you please look at the system calls summary below? fstat() takes 25% of the total time. This doesn't happen in PHP 5.2.9. % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 24.85 33.820248 256 131908 fstat 13.54 18.431644 263 70002 66 lstat 9.81 13.346466 259 51520 mmap 9.72 13.223388 258 51175 munmap 9.39 12.775102 264 48450 192 stat 8.83 12.014341 265 45383 10 open 8.72 11.866944 257 46154 close 3.47 4.724639 255 18530 396 read 3.26 4.430927 256 17297 lseek 1.88 2.557480 244 10477 poll 1.59 2.170520 261 8326 recvfrom 1.52 2.073135 259 7994 sendto ... ------ ----------- ----------- --------- --------- ---------------- 100.00 136.108580 526555 1324 total In 5.2.9 fstat() takes about 8% of total time. ------------------------------------------------------------------------ [2009-09-01 18:27:31] rasmus@php.net You need to do proper profiling to determine that. Start by turning on all warning messages. If you are throwing warnings or notices, even if you are not displaying or logging them anywhere, it is going to slow you down and there are a bunch of new ones in 5.3. Set your error reporting to something like 16777215 (0xffffff) which will catch all current and future error levels and fix anything you see. Then check your performance again. ------------------------------------------------------------------------ [2009-09-01 18:13:05] olga at metacafe dot com When I compare 5.2.9 with 5.3, I see that (a) 5.3 is slower. According to release notes, I was expecting performance improvement, or at least the same performance as in previous version. (b) top 5 system calls in 5.3 take more time that in 5.2.9 lstat() calls are reduced, but fstat(), mmap() and munmap() are used much more than before. Maybe I'm wrong about fstat(), but that's the only difference I found so far. What else could have caused this performance problem? ------------------------------------------------------------------------ [2009-09-01 15:01:17] rasmus@php.net You suppose it is because of fstat? I seriously doubt that. fstat is really fast because it doesn't need to touch the disk at all. It simply grabs the stat struct from an already open file descriptor. If you can show me some profiling numbers where fstat is anywhere on the radar, I'll take a look, but I am highly suspicious that fstat would have anything to do with any performance issues. Disk-touching stats like lstat are the ones you need to worry about. ------------------------------------------------------------------------ [2009-09-01 14:48:03] olga at metacafe dot com Any PHP code does it. The code: <?php echo "Hello!"; ?> The strace: open("[path]/test.php", O_RDONLY) = 16 fstat(16, {st_mode=S_IFREG|0644, st_size=82, ...}) = 0 fstat(16, {st_mode=S_IFREG|0644, st_size=82, ...}) = 0 fstat(16, {st_mode=S_IFREG|0644, st_size=82, ...}) = 0 mmap(NULL, 82, PROT_READ, MAP_SHARED, 16, 0) = 0x2a9a8b4000 munmap(0x2a9a8b4000, 82) = 0 close(16) = 0 ------------------------------------------------------------------------ The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at http://bugs.php.net/49383 -- Edit this bug report at http://bugs.php.net/?id=49383&edit=1