Over the past month on a webserver cluster running Apache and a custom Catalyst mod_perl application, there has been an increasing creep in sys% time. The problem went unbothered for a long time, until it hit the point where sys% matched user% percent for percent. This led to massive problems during the peak hours as the servers could no longer cope with load. In addition to reactive ordering of more servers, an investigation was initiated to determine the cause of this increase in sys%. This post will hopefully deliver some insight into a multi-disciplinarian (from a sysadmin and programmer's perspective) approach to problem-solving.

Two tools were used to determine the execution hotspots, oprofile and Apache::DProf.

A summary was first obtained with opreport with no command-line arguments (Table 1). The sys% reported by top is clearly confirmed. Before proceeding to inspect the kernelspace down to function granularity however, the debuginfo RPMs had to be installed. As RHEL4 does not provide these, the SRPM was downloaded and RPMs built from it, a fairly straightforward chore. Then, opreport -l -g was run and produced the output in Table 2. It can be seen that a significant portion of the time was spent with primitive concurrency control operations. Also listed are the files dcache.c and namei.c, of which an inspection shows calls to the said concurrency control ops.

Given this lead, it was postulated that the problem was caused by something performing a lot of filesystem operations, such as stat(). A possibility was that a directory used by the app grew in number of files, slowing down directory enumeration. The filesystem was then checked for unusually large directories, but none were found.

I was contemplating using gdb and strace to trace through mod_perl, but at this point the application programmer found something better - a high level profiler called Apache::DProf. The necessary code was added into the source, Apache left to run for a short while, then dprofpp -F run on the resulting profile dumps (Table 3). The top spot was taken by File::Find::find - which fits the kernel. Further investigation showed that the root problem was caused by the use of a Catalyst date formatting filter for each comment element in the generated page. The date formatter then recursively searches /usr/share/zoneinfo to obtain timezone information. This operation became unnecessarily expensive due to the large number of comments in the page.

Finally, a one-line solution was found which was to pass a timezone as an argument to the date formatter. This removed the need for the directory search, and completely solved the problem (Figure 1). Consequently, with the elimination of sys%, headroom was created for double the current peak demand and extra servers unnecessary for now.

Figure 1 - CPU utilization before and after changes