Skip to main content

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.
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.
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.


Popular posts from this blog

How we have systematically improved the roads our packets travel to help data imports and exports flourish

This blog post is an account of how we have toiled over the years to improve the throughput of our interDC tunnels. I joined this company around 2012. We were scaling aggressively then. We quickly expanded to 4 DCs with a mixture of AWS and colocation. Our primary DC is connected to all these new DCs via IPSEC tunnels established from SRX. The SRX model we had, had an IPSEC throughput of 350Mbps. Around December 2015 we saturated the SRX. Buying SRX was an option on the table. Buying one with 2Gbps throughput would have cut the story short. The tech team didn't see it happening.

I don't have an answer to the question, "Is it worth spending time in solving a problem if a solution is already available out of box?" This project helped us in improving our critical thinking and in experiencing the theoretical network fundamentals on live traffic, but also caused us quite a bit of fatigue due to management overhead. Cutting short the philosophy, lets jump to the story.


Lessons from Memory

Started debugging an issue where Linux started calling OOM reaper despite tons of memory is used as Linux cached pages. My assumption was if there is a memory pressure, cache should shrink and leave way for the application to use. This is the documented and expected behavior. OOM reaper is called when few number of times page allocation has failed consequently. If for example mysql wants to grow its buffer and it asks for a page allocation and if the page allocation fails repeatedly, kernel invokes oom reaper. OOM reaper won't move out pages, it sleeps for some time and sees if kswapd or a program has freed up caches/application pages. If not it will start doing the dirty job of killing applications and freeing up memory. In our mysql setup, mysql is the application using most of the Used Memory, so no other application can free up memory for mysql to use. Cached pages are stored as 2 lists in Linux kernel viz active and inactive.
More details here…

The server, me and the conversation

We were moving a project from AWS to our co-located DC. We have setup KVMs scheduled by Cloudstack for each of the component in the architecture. The KVMs used local storage. The VMs are provisioned with more than required resources because we have the opinion that in our DC scaling during peak load and then downscaling doesn't offer much benefits financially as we are anyways paying for the hardware in advance and its also powered on. Its going to be idle if not used. Now we found something interesting our latency in co-located DC was 2 times more than in AWS. The time for first byte at our load balancer in aws was 60ms average and at our DC was 112ms. We started our debugging mission, Mission Conquer-AWS. All the servers are newer Dell hardwares. So the initially intuition was virtualisation is causing the issue.

Conversation with the Hypervisor We started with CPU optimisation, we started using the host-passthrough mode of CPU in libvirt so VMs dont see QEMU emulated CPUs, the…