ESX VM: 2 vCPUs. RedHat Ent 5.6. Apache 2.2.3/ python cgi and a J2EE app.
We have a monitor script pulling a page from this Apache, which calls a simple python cgi script, every minute, using curl, with max-time set to 30 seconds.
Everyday, at 9 am, the NetBackup software kick in, which increases a CPU and I/O load on the system for about 20 minutes or so.... quite often, the monitor would fail, saying it did not get anything in 30 seconds, maybe every other day or so....
I would like to figure out exactly what the problem is...
Apache logs the request was handled fine. The cgi python that was called also logged that everything went fine and quick.
CPU during the backup shows 40% I/O wait, 40% user some 10% idle.
Disk read ops do peak at that time, but disk read time does not go up by much at all.
I run strace on the httpd processes, during the backup time, and got lucky capturing a trace of one such failed monitor probe. The odd thing is, the trace shows the request was completed in about 1.3 seconds... but the client never received the response data in the 30 seconds it waited for it.
I did not take a tcpdump during this straced probe, but did previously and did notice indeed, that the system simply takes 10, 20 and more, seconds, to send the data packets, while apache would have logged that it was done with the response.
strace looks like this:
28259 09:25:01.617226 accept(6, {sa_family=AF_INET, sin_port=htons(34106), sin_addr=inet_addr("192.168.151.84")}, [17179869200]) = 24 <0.000045>
...
18130 09:25:01.670991 execve("/var/path/to/script.py",
...
28259 09:25:01.661924 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x2b8bf4a3c3d0) = 18130 <0.003602>
...
18130 09:25:02.965223 write(1, "content-type: text/html\n\n1001 Missing Required Parameter \r\n", 88) = 88 <0.000084>
28259 09:25:02.965408 <... epoll_wait resumed> {{EPOLLIN, {u32=261317976, u64=47880556733784}}}, 2, 300000) = 1 <1.297266>
18130 09:25:02.966161 exit_group(0) = ?
28259 09:25:02.966299 read(29, "content-type: text/html\n\n1001 Missing Required Parameter \r\n", 8000) = 88 <0.002616>
28259 09:25:02.969791 epoll_wait(27,
My question is how do I debug this further? Where was the response stuck? Could more vCPUs be what this system needs to deal with the increase in I/O ops? is it I/O ops issue?
Also, How could apache log a request finished with 200 status code, when the client never received the data and ended up actively closing the TCP connection?
This might not be the case actually. might be that Apache did not log the request at all.