PHP include and lstat64

lstat64 or stat is not a slow system call. On most enterprise system it takes 0.000024 seconds. The issue is that when you have a software system which uses a lot of includes you could have ~10000 calls for a simple page.

Just take a look at the strace

[root@radio9 ~]# strace -T -p 15481
Process 15481 attached – interrupt to quit
accept(948, {sa_family=AF_INET, sin_port=htons(2220), sin_addr=inet_addr(“67.72.16.195”)}, [16]) = 5 <21.731254>
rt_sigaction(SIGUSR1, {SIG_IGN}, {0x814391c, [], SA_RESTORER|SA_INTERRUPT, 0x6ab908}, 8) = 0 <0.000018>
fcntl64(5, F_SETFD, FD_CLOEXEC) = 0 <0.000016>
getsockname(5, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr(“67.72.16.237”)}, [16]) = 0 <0.000018>
setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.000017>
read(5, “GET /tran_frame/blank.html HTTP/”…, 4096) = 788 <0.000020>
rt_sigaction(SIGUSR1, {SIG_IGN}, {SIG_IGN}, 8) = 0 <0.000016>
time(NULL) = 1255840869 <0.000015>
gettimeofday({1255840869, 688159}, NULL) = 0 <0.000114>
stat64(“/export/home/phpuser/docrootx/wfan/tran_frame/blank.html”, {st_mode=S_IFREG|0644, st_size=0, …}) = 0 <0.000068>
open(“/export/home/phpuser/docrootx/wfan/.htaccess”, O_RDONLY) = 6 <0.000197>
fstat64(6, {st_mode=S_IFREG|0644, st_size=1808, …}) = 0 <0.000014>
fstat64(6, {st_mode=S_IFREG|0644, st_size=1808, …}) = 0 <0.000010>
mmap2(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6459000 <0.000016>
read(6, “Redirect /photos http://www.wfan”…, 32768) = 1808 <0.000023>
read(6, “”, 32768) = 0 <0.000014>
close(6) = 0 <0.000015>
munmap(0xb6459000, 32768) = 0 <0.000018>
open(“/export/home/phpuser/docrootx/wfan/tran_frame/.htaccess”, O_RDONLY) = -1 ENOENT (No such file or directory) <0.000025>
open(“/export/home/phpuser/docrootx/wfan/tran_frame/blank.html”, O_RDONLY) = 6 <0.000026>
select(6, [5], NULL, NULL, {0, 0}) = 0 (Timeout) <0.000017>
write(5, “HTTP/1.1 304 Not Modified\r\nDate:”…, 198) = 198 <0.000020>
gettimeofday({1255840869, 690153}, NULL) = 0 <0.000015>
times({tms_utime=4062, tms_stime=1083, tms_cutime=35, tms_cstime=175}) = 412413935 <0.000012>
close(6) = 0 <0.000014>
rt_sigaction(SIGUSR1, {0x814391c, [], SA_RESTORER|SA_INTERRUPT, 0x6ab908}, {SIG_IGN}, 8) = 0 <0.000011>
read(5, “GET /ajax.js HTTP/1.0\r\nAccept: *”…, 4096) = 273 <0.103926>
rt_sigaction(SIGUSR1, {SIG_IGN}, {0x814391c, [], SA_RESTORER|SA_INTERRUPT, 0x6ab908}, 8) = 0 <0.000015>
time(NULL) = 1255840869 <0.000014>
gettimeofday({1255840869, 795202}, NULL) = 0 <0.000012>
stat64(“/export/home/phpuser/docrootx/mtro/ajax.js”, {st_mode=S_IFREG|0755, st_size=15708, …}) = 0 <0.000029>
umask(077) = 022 <0.000011>
umask(022) = 077 <0.000011>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0 <0.000016>
rt_sigaction(SIGPROF, {0x80db134, [PROF], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x80db134, [PROF], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000015>
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0 <0.000011>
rt_sigaction(SIGSEGV, {0xd2f85c, [SEGV], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x81438b3, [SEGV], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000011>
rt_sigaction(SIGFPE, {0xd2f85c, [FPE], SA_RESTORER|SA_RESTART, 0x6ab908}, {SIG_DFL}, 8) = 0 <0.000011>
rt_sigaction(SIGBUS, {0xd2f85c, [BUS], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x81438b3, [BUS], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000013>
rt_sigaction(SIGILL, {0xd2f85c, [ILL], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x81438b3, [ILL], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000011>
rt_sigaction(SIGABRT, {0xd2f85c, [ABRT], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x81438b3, [ABRT], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000011>
getcwd(“/”, 4095) = 2 <0.000015>
chdir(“/export/home/phpuser/docrootx/mtro”) = 0 <0.000022>
stat64(“/usr/local/lib/reset_remote_addr.php”, {st_mode=S_IFREG|0644, st_size=621, …}) = 0 <0.000020>
time(NULL) = 1255840869 <0.000010>
stat64(“/usr/local/lib/reset_remote_addr.php”, {st_mode=S_IFREG|0644, st_size=621, …}) = 0 <0.000017>
stat64(“/export/home/phpuser/docrootx/mtro/ajax.js”, {st_mode=S_IFREG|0755, st_size=15708, …}) = 0 <0.000020>
time(NULL) = 1255840869 <0.000011>
stat64(“/home/phpuser/docrootx/mtro/ajax.js”, {st_mode=S_IFREG|0755, st_size=15708, …}) = 0 <0.000020>
writev(5, [{“HTTP/1.1 200 OK\r\nDate: Sun, 18 O”…, 199}, {“\r\nvar playWindowFlashUrl=\”\”;url=”…, 15708}], 2) = 15907 <0.001050>
chdir(“/”) = 0 <0.000016>
rt_sigaction(SIGSEGV, {0x81438b3, [SEGV], SA_RESTORER|SA_RESTART, 0x6ab908}, {0xd2f85c, [SEGV], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000011>
rt_sigaction(SIGFPE, {SIG_DFL}, {0xd2f85c, [FPE], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000013>
rt_sigaction(SIGBUS, {0x81438b3, [BUS], SA_RESTORER|SA_RESTART, 0x6ab908}, {0xd2f85c, [BUS], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000011>
rt_sigaction(SIGILL, {0x81438b3, [ILL], SA_RESTORER|SA_RESTART, 0x6ab908}, {0xd2f85c, [ILL], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000010>
rt_sigaction(SIGABRT, {0x81438b3, [ABRT], SA_RESTORER|SA_RESTART, 0x6ab908}, {0xd2f85c, [ABRT], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000011>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0 <0.000095>
umask(022) = 022 <0.000018>
gettimeofday({1255840869, 799974}, NULL) = 0 <0.000018>
times({tms_utime=4062, tms_stime=1083, tms_cutime=35, tms_cstime=175}) = 412413946 <0.000016>
shutdown(5, 1 /* send */) = 0 <0.000025>
select(6, [5], NULL, NULL, {2, 0}) = 1 (in [5], left {1, 934000}) <0.065777>
read(5, “”, 512) = 0 <0.000054>
close(5) = 0 <0.000063>
rt_sigaction(SIGUSR1, {0x814391c, [], SA_RESTORER|SA_INTERRUPT, 0x6ab908}, {SIG_IGN}, 8) = 0 <0.000053>
accept(948, {sa_family=AF_INET, sin_port=htons(2427), sin_addr=inet_addr(“67.72.16.195”)}, [16]) = 5 <22.399492>
rt_sigaction(SIGUSR1, {SIG_IGN}, {0x814391c, [], SA_RESTORER|SA_INTERRUPT, 0x6ab908}, 8) = 0 <0.000053>
fcntl64(5, F_SETFD, FD_CLOEXEC) = 0 <0.000056>
getsockname(5, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr(“67.72.16.237”)}, [16]) = 0 <0.000016>
setsockopt(5, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.000017>
read(5, “GET /pages/wmkk2_alt.css HTTP/1.”…, 4096) = 847 <0.000018>
rt_sigaction(SIGUSR1, {SIG_IGN}, {SIG_IGN}, 8) = 0 <0.000016>
time(NULL) = 1255840892 <0.000015>
gettimeofday({1255840892, 267350}, NULL) = 0 <0.000014>
stat64(“/export/home/phpuser/docrootx/wmkk2/pages/wmkk2_alt.css”, {st_mode=S_IFREG|0755, st_size=5620, …}) = 0 <0.000233>
open(“/export/home/phpuser/docrootx/wmkk2/pages/wmkk2_alt.css”, O_RDONLY) = 6 <0.000645>
select(6, [5], NULL, NULL, {0, 0}) = 0 (Timeout) <0.000054>
write(5, “HTTP/1.1 304 Not Modified\r\nDate:”…, 202) = 202 <0.000056>
gettimeofday({1255840892, 269050}, NULL) = 0 <0.000050>
times({tms_utime=4062, tms_stime=1083, tms_cutime=35, tms_cstime=175}) = 412416193 <0.000055>
close(6) = 0 <0.000053>
rt_sigaction(SIGUSR1, {0x814391c, [], SA_RESTORER|SA_INTERRUPT, 0x6ab908}, {SIG_IGN}, 8) = 0 <0.000052>
read(5, “GET /pages/wmkk2_navigation_2724″…, 4096) = 858 <0.070096>
rt_sigaction(SIGUSR1, {SIG_IGN}, {0x814391c, [], SA_RESTORER|SA_INTERRUPT, 0x6ab908}, 8) = 0 <0.000051>
time(NULL) = 1255840892 <0.000051>
gettimeofday({1255840892, 340205}, NULL) = 0 <0.000051>
stat64(“/export/home/phpuser/docrootx/wmkk2/pages/wmkk2_navigation_2724.css”, {st_mode=S_IFREG|0644, st_size=778, …}) = 0 <0.000384>
open(“/export/home/phpuser/docrootx/wmkk2/pages/wmkk2_navigation_2724.css”, O_RDONLY) = 6 <0.000667>
select(6, [5], NULL, NULL, {0, 0}) = 0 (Timeout) <0.000054>
write(5, “HTTP/1.1 304 Not Modified\r\nDate:”…, 201) = 201 <0.000055>
gettimeofday({1255840892, 342070}, NULL) = 0 <0.000049>
times({tms_utime=4062, tms_stime=1083, tms_cutime=35, tms_cstime=175}) = 412416200 <0.000050>
close(6) = 0 <0.000051>
rt_sigaction(SIGUSR1, {0x814391c, [], SA_RESTORER|SA_INTERRUPT, 0x6ab908}, {SIG_IGN}, 8) = 0 <0.000057>
read(5, “GET /topic/cbs_video.php?guid=12″…, 4096) = 974 <0.025003>
rt_sigaction(SIGUSR1, {SIG_IGN}, {0x814391c, [], SA_RESTORER|SA_INTERRUPT, 0x6ab908}, 8) = 0 <0.000422>
time(NULL) = 1255840892 <0.000012>
gettimeofday({1255840892, 369178}, NULL) = 0 <0.000014>
stat64(“/export/home/phpuser/docrootx/knx/topic/cbs_video.php”, {st_mode=S_IFREG|0644, st_size=80067, …}) = 0 <0.000094>
open(“/export/home/phpuser/docrootx/knx/.htaccess”, O_RDONLY) = 6 <0.002898>
fstat64(6, {st_mode=S_IFREG|0644, st_size=608, …}) = 0 <0.000013>
fstat64(6, {st_mode=S_IFREG|0644, st_size=608, …}) = 0 <0.000014>
mmap2(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6459000 <0.000040>
read(6, “Redirect /itm http://www.interte”…, 32768) = 608 <0.000040>
read(6, “”, 32768) = 0 <0.000030>
close(6) = 0 <0.000016>
munmap(0xb6459000, 32768) = 0 <0.000020>
open(“/export/home/phpuser/docrootx/knx/topic/.htaccess”, O_RDONLY) = -1 ENOENT (No such file or directory) <0.000039>
umask(077) = 022 <0.000013>
umask(022) = 077 <0.000023>
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0 <0.000014>
rt_sigaction(SIGPROF, {0x80db134, [PROF], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x80db134, [PROF], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000014>
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0 <0.000011>
rt_sigaction(SIGSEGV, {0xd2f85c, [SEGV], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x81438b3, [SEGV], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000015>
rt_sigaction(SIGFPE, {0xd2f85c, [FPE], SA_RESTORER|SA_RESTART, 0x6ab908}, {SIG_DFL}, 8) = 0 <0.000011>
rt_sigaction(SIGBUS, {0xd2f85c, [BUS], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x81438b3, [BUS], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000021>
rt_sigaction(SIGILL, {0xd2f85c, [ILL], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x81438b3, [ILL], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000025>
rt_sigaction(SIGABRT, {0xd2f85c, [ABRT], SA_RESTORER|SA_RESTART, 0x6ab908}, {0x81438b3, [ABRT], SA_RESTORER|SA_RESTART, 0x6ab908}, 8) = 0 <0.000012>
getcwd(“/”, 4095) = 2 <0.000014>
chdir(“/export/home/phpuser/docrootx/knx/topic”) = 0 <0.000037>
stat64(“/usr/local/lib/reset_remote_addr.php”, {st_mode=S_IFREG|0644, st_size=621, …}) = 0 <0.000036>
time(NULL) = 1255840892 <0.000014>
stat64(“/usr/local/lib/reset_remote_addr.php”, {st_mode=S_IFREG|0644, st_size=621, …}) = 0 <0.000022>
stat64(“/export/home/phpuser/docrootx/knx/topic/cbs_video.php”, {st_mode=S_IFREG|0644, st_size=80067, …}) = 0 <0.000043>
time(NULL) = 1255840892 <0.000014>
open(“/home/tmp/mmcache/mmcache-91.51077621”, O_RDONLY) = 6 <0.000032>
flock(6, LOCK_SH) = 0 <0.000076>
read(6, “MMCACHE\0\6B \0\0\”\20\0\3\”@\0\234}\1\0gp\331J\375\214b\353”, 32) = 32 <0.000032>
time(NULL) = 1255840892 <0.000012>
read(6, “\344r\234\n\23\0\0\0\0\0\0\0\227o\301\0\3038\1\0gp\331J\0\0\0\0\234}\1\0″…, 97692) = 97692 <0.000114>
flock(6, LOCK_UN) = 0 <0.000019>
close(6) = 0 <0.000018>
stat64(“/mnt/nasnyc2/docrootx/l2cache/knx/784724.php”, {st_mode=S_IFREG|0644, st_size=80067, …}) = 0 <0.000028>
gettimeofday({1255840892, 378261}, NULL) = 0 <0.000013>
open(“/export/home/phpuser/docrootx//includes//stn_page_display_functions.lib”, O_RDONLY) = 6 <0.000024>
getcwd(“/mnt/nasnyc2/docrootx/l2cache/knx/topic”, 4096) = 40 <0.000022>
lstat64(“/export”, {st_mode=S_IFDIR|0755, st_size=4096, …}) = 0 <0.000015>
lstat64(“/export/home”, {st_mode=S_IFLNK|0777, st_size=6, …}) = 0 <0.000016>
readlink(“/export/home”, “/home/”, 4096) = 6 <0.000018>
lstat64(“/home”, {st_mode=S_IFDIR|0755, st_size=4096, …}) = 0 <0.000022>
lstat64(“/home/phpuser”, {st_mode=S_IFDIR|0755, st_size=4096, …}) = 0 <0.000016>
lstat64(“/home/phpuser/docrootx”, {st_mode=S_IFDIR|0755, st_size=69632, …}) = 0 <0.000016>
lstat64(“/home/phpuser/docrootx/includes”, {st_mode=S_IFDIR|0755, st_size=12288, …}) = 0 <0.000017>
lstat64(“/home/phpuser/docrootx/includes/stn_page_display_functions.lib”, {st_mode=S_IFREG|0644, st_size=54874, …}) = 0 <0.000019>
fstat64(6, {st_mode=S_IFREG|0644, st_size=54874, …}) = 0 <0.000017>
time(NULL) = 1255840892 <0.000010>
close(6) = 0 <0.000029>
open(“./globals.lib”, O_RDONLY) = -1 ENOENT (No such file or directory) <0.000020>
open(“/export/home/phpuser/docroot/includes/globals.lib”, O_RDONLY) = 6 <0.000026>

So from what we see we have ~10000-20000 lstat64 calls for the same page. If we look at any page our system generates there are atleast 2500 calls so if you sum those it takes 5-8 seconds in system calls.

So a couple of options

1. Make lstat faster. That is sort of tough since it is highly optimized on most system. lstat though do depend on the speed of the harddrives so a difference of 10000rpm vs 150000 rpm drives could make the difference .

2. If you are using php5 they have an odd “hack” where they maintain a cache on the lstat result realpath_cache_size and realpath_cache_ttl . So we can increase the size of the cache or the ttl so that effectively we reduce the number of calls.

3. Reduce the number of include calls in the system. But then all we get is huge code bloat.

4. Change our calls from include_once to include. As you would find out (maybe the hard way) is that to maintain include_once to have its correct function php essentially does an lstat64 on each part of the path of the include — what a waste. But that is needed to get the realpath of the file. So if we change to just doing include it would reduce the calls.

Now here is the tricky part developers like include_once because then can maintain a tree include system, with include you are limited to a list. But lets be creative all include_once is doing is maintaining a hash system to see if it needs to include the file again. We can do that with a little bit more code by surrounding the include with an if clause which looks at a whether the file has already been included. With this we essentially start keep our our own hash table of the included files.

I am in no way arguing for #4 but it is another approach to think about.