Php – Strace Apache process output showing 24 seconds wait?What can be the reason

apache-2.2max-file-descriptorsPHPstrace

Performed strace on one one of the apache children and its showing 24 seconds between two system calls.How can i determine what is the cause of this behavior.It looks like both children are taking almost same amound of time(24.7 and 23.92) seconds.

we are using apache prefork with php5 and mysql 5

/var/lib/php5/ is the php session folder

strace output of apache children1 with processid -20539

ps -u www-data | grep apache2 | awk '{print"-p " $1}' | xargs strace -o /strace/strace.log -ff -s4096 -r

20539 0.000064 close(13) = 0

20539 0.000060
open("/var/lib/php5/sess_9t2cvnvdoruh666rjpm515idm0", O_RDWR|O_CREAT,
0600) = 13

20539 0.000065 flock(13, LOCK_EX) = 0

20539 24.711888 fcntl(13, F_SETFD, FD_CLOEXEC) = 0

20539 0.000056 fstat(13, {st_mode=S_IFREG|0600, st_size=211,
…}) = 0

20539 0.000080 lseek(13, 0, SEEK_SET) = 0

strace output of apache children2 with processid – 20556

20556 0.000056 close(13) = 0

20556 0.000058
open("/var/lib/php5/sess_9t2cvnvdoruh666rjpm515idm0", O_RDWR|O_CREAT,
0600) = 13

20556 0.000062 flock(13, LOCK_EX) = 0

20556 23.928294 fcntl(13, F_SETFD, FD_CLOEXEC) = 0

20556 0.000055 fstat(13, {st_mode=S_IFREG|0600, st_size=211,
…}) = 0

20556 0.000083 lseek(13, 0, SEEK_SET) = 0

Can it be a problem with file that file descriptor(13) called??
is there anything wrong with my understanding of strace output.

Best Answer

On the process take a look at the lsof -p <pid>

Notably you're looking for FD 13

i.e. from one of my httpd deployments.

httpd 10865 apache 13w REG 8,5 1113187 59310687 /var/log/httpd/some_site.log

I'd look at contention with obtaining an exclusive lock on the file, noted in FD 13 in this case, if other processes are contending for locks, as noted by fcntl then this would explain your long wait.

Related Topic