WK; this week

There has been quite a buzz at the Lowyat.NET forum over the recent Malaysian General Elections. I graphed out the posts in absolute and relative figures for 48 hours from March 08, 3am (Fig. 1, Fig. 2). Traffic picked up quickly from 7pm when ballots were counted, and peaked at 1am when it was clear that the incumbent party lost its 2/3rd majority. Following that, there continued to be latent interest throughout the day.

We hit an unprecedented number of visitors that evening, and I still find it amazing that a single topic can attract almost half of the entire forum's traffic.

Fig. 1 - Posts in the General Election topics (absolute)

Fig. 2 - Posts in the General Election topics versus other topics

A bag of five popular Malaysian websites were selected, all which have visitors originating largely from Malaysia. Their pageviews as estimated by Alexa were then graphed out (Fig. 1). There is clearly a dip in pageviews in the Chinese New Year week, which begins on 7 Feb this year.

Figure 1 - Pageviews of 5 popular Malaysian websites in Feb '08

In addition, public MRTG graphs from TWGate, a public peering point, were obtained (Fig. 2). A reduction in traffic of roughly 50% can be seen in week 5, i.e. the Chinese New Year week.

Figure 2 - MRTG graphs of TWGate-TMNet for Feb '08

It would be interesting to see whether the other major Malaysian festivity, Hari Raya Aidilfitri, will have the same profound effect on Malaysian web traffic when it happens in October.

I connected my network with my neighbor living 6 floors above, to share Internet access as well as downloaded files. There was fortunately an equally tall building about 30m across us, which we used to reflect the signal off. An 8dBi yagi was used with a PCI wireless card on my neighbor's end together with Vista's layer-3 bridging, and a Linksys WAG54G on my end. The setup (as can be seen in Fig. 1 and Fig. 2) is quite ghetto, with the antenna "mount" being made out of styrofoam and gaffer tape.

Speed tests were initially 50KB/s, but after a little fiddling a one sweet spot (+- 5 degrees?) was found where 1MB/s was achieved. Pretty shocking given that we were going to write it off already!

Figure 1 - 8dBi yagi at neighbor's

Figure 1 - ?dBi rubber ducky at my place

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

1) Not mentioned in the syslog-ng documentation on performance is the log_msg_size() setting. When follow_freq() is used on a logfile to emulate tail -f behavior, it is necessary for that log_msg_size() is large enough to accomodate all log messages for the reading interval.

2) I've been toying around with the idea of using syslog-ng as a plumbing tool to route logs as I wish. The flexibility it provides is excellent while retaining a simple configuration file, reminding me of the Exim MTA. Currently, I'm using syslog-ng to aggregate 1600 lines/s worth of squid logs. With this workload it consumes ~15% of one Xeon L5335 core.

It is currently quite cumbersome to pass the logs to external programs, requiring a named socket to be created for IPC. Perhaps a process spawner/manager could be hacked in to facilitate this?

Some possibilities to consider with the aggregated log:

a) Visualization, by piping it to a stream visualization tool, such as glTail.rb or Ganglia (with an appropriate wrapper to gmetric).

b) Out-of-band IDS, by piping it to a PHPIDS loop. The client headers can be extracted from the log line and exploded into the superglobals. An external trigger can be called to firewall off malicious clients.

c) Out-of-band DOS mitigator, by piping it to a script that watches for unusually high number of requests. Action can be taken as with (b).

I've finally made an effort at thawing this site. Put in a copy of Drupal and found a theme that has exactly the number of colors I want - none. Hopefully this "explosive" start (ooh.. the sarcasm burns!) will persist long enough for me to write about my tech interests and commentaries. We'll see how far this site goes before I let it rot again..