Idle Cpu

We are facing a issue for the past one month and I am still unsure of the reason. Will rollout a change next monday on all our webservers to see how my reasoning works.

Situation:

We have a dozen webservers behind a Load Balancer in one of our setups. Each webserver receives some 300  req/sec i.e our setup receives around 5000 req/sec. Each web server will have 1024 apache process waiting for connections. At any moment 600 apache process will be free. But at the start of every hour the number of free process dips and reaches even to zero. When number of idle process reaches zero, response time, memory used and contentions for resource will increase drastically and thereby hitting the performance.

Possible Reasons:

It is proved that this situation is reproduced whenever logrotate is run. Logrotate is scheduled to run at the start of every hour.

LogRotate:

We log each apache access and error details in a file, which comes in handy when the system is being attacked by some anonymous groups. So the log file will grow at a very faster rate since all accesses are written. So we rotate log files at the start of every hour and zip the old log files and dump them

Apache will have the file descriptor of the log files. So if I rotate log files Apache has to be restarted to make it aware of new file descriptors. But restarting Apache in a production environment is not an appreciable option.

So we were following a method called copy truncate.

Copy Truncate:

Lets take a log file named 'log'. Copy Truncate will copy the current log file 'log' as 'log1' and write /dev/null (makes the log file empty) to 'log'. The log will be empty for apache to write. Apache need not be restarted to make it aware of the change.

This system worked fine for some time. But now on 3 out of 12 boxes apache idle process decreases during log rotate.

Detective Work:

During the zeroth minute, logrotate copies the log file and then writes an empty file. But all apache process goes to Sleep state and Cpu idle percentage increases to 96%. The possible reason for Apache processes to sleep must be some deadlock. Copy gets a lock on a file, reads it and then writes to another file. Apache processes should be waiting for a lock to write on the log file which is not permitted. So now we are going to test a process cronolog instead of logrotate. 

Apache spawns a process called cronolog to write in the log file. Cronolog checks the time. If it is start of new hour, it creates a new log file or else append to the existing file thereby no contention for locks. This method has performed better during all test.

Failed Attempts:

Initially we thought it might be a disk issue. During the copy process lot of dirty pages will be in memory, pdflush(kernel process) will flush dirty pages to disk. But this was not the case as no process was in D state(IO wait read ps man page). FIO is an IO benchmarking tool which tests disk throughput.  Probably I will write a blog post about it. FIO results showed the disk throughput had no issues.

Next we came across BufferedLog an Apache process to write logs to memory and then to a disk after the PIPE BUFFER is full. This is of little use since we employ write back cache all writes will be at memory level by default and these pages continue to be recently used.

Its a week of detective work with operating system basics.