12.3. Find a BaselineSet a Goal

12.3. Find a Baseline/Set a Goal

Once again, the first step is to determine the current state of the problem.

However, in this case, it is not so easy to do. We do not know when the problem will begin or how long it will last, so we cannot really set a baseline without more investigation. As far as a goal, ideally we would like the problem to disappear completely, but the problem might be caused by essential OS functions, so eliminating it entirely might not be possible.

First, we need to do a little more investigation into why this problem is happening to figure out a reasonable baseline. The initial step is to run top as the slowdown is happening. This gives us a list of processes that may be causing the problem, or it may even point at the kernel itself.

In this case, as shown in Listing 12.1, we run top and ask it to show only nonidle processes (by pressing <I> as top runs).

Listing 12.1.

 top - 12:03:40 up 12 min,  7 users,  load average: 1.35, 0.98, 0.53 Tasks:  86 total,   2 running,  84 sleeping,   0 stopped,     0 zombie Cpu(s):  2.3% us,  5.0% sy,  1.7% ni,  0.0% id, 91.0% wa,  0.0% hi,  0.0% si Mem:    320468k total,   317024k used,     3444k free,    24640k buffers Swap:   655192k total,        0k used,   655192k free,   183620k cached   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND  5458 root      34  19  4920 1944 2828 R  1.7  0.6   0:01.13 prelink  5389 ezolt     17   0  3088  904 1620 R  0.7  0.3   0:00.70 top 

The top output in Listing 12.1 has several interesting properties. First, we notice that no process is hogging the CPU; both nonidle tasks are using less than 2 percent of the total CPU time. Second, the system is spending 91 percent waiting for I/O to happen. Third, the system is not using any of the swap space, so the grinding disk is NOT caused by swapping. Finally, an unknown process, prelink, is running when the problem happens. It is unclear what this prelink command is, so we will remember that application name and investigate it later.

Our next step is to run vmstat to see what the system is doing. Listing 12.2 shows the result of vmstat and confirms what we saw with top. That is, ~90 percent of the time the system is waiting for I/O. It also tells us that the disk subsystem is reading in about 1,000 blocks a second of data. This is a significant amount of disk I/O.

Listing 12.2.

 [ezolt@localhost ezolt]$ vmstat 1 10 procs -----------memory---------- ---swap-- -----io----  --system-- ----cpu----  r  b   swpd   free   buff  cache   si   so    bi    bo    in    cs us sy id wa  0  1      0   2464  24568 184992    0    0   689    92  1067   337  5  4 45 46  0  1      0   2528  24500 185060    0    0  1196     0  1104  1324  6 10  0 84  0  1      0   3104  24504 184276    0    0   636   684  1068   967  3  7  0 90  0  1      0   3160  24432 184348    0    0  1300     0  1096  1575  4 10  0 86  0  2      0   3488  24336 184444    0    0  1024     0  1095  1498  5  9  0 86  0  1      0   2620  24372 185188    0    0   980     0  1096  1900  6 12  0 82  0  1      0   3704  24216 184304    0    0  1480     0  1120   500  1  7  0 92  0  1      0   2296  24256 185564    0    0  1384   684  1240  1349  6  8  0 86  2  1      0   3320  24208 184572    0    0   288     0  1211  1206 63  7  0 30  0  1      0   3576  24148 184632    0    0  1112     0  1153   850 19  7  0 74 

Now that we know that the disk is being heavily used, the kernel is spending a significant amount of time waiting for I/O, and an unknown application, prelink, is running, we can begin to figure out exactly what the system is doing.

We do not know for certain that prelink is causing the problem, but we suspect that it is. The easiest way to determine whether prelink is causing the disk I/O is to "kill" the prelink process and see whether the disk usage goes away. (This might not be possible on a production machine, but since we are working on a personal desktop we can be more fast and loose.) Listing 12.3 shows the output of vmstat, where halfway through this output, we killed the prelink process. As you can see, the blocks read in drop to zero after prelink is killed.

Listing 12.3.

 procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----  r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy id wa  0  1 122208   3420  13368  84508    0    0  1492   332 1258  1661 15 11  0 74  0  1 122516   3508  13404  85780    0  308  1188   308 1134  1163  5  7  0 88  0  2 123572   2616  13396  86860    0 1056  1420  1056 1092   911  4  6  0 90  0  1 126248   3064  13356  86656    0 2676   316  2676 1040   205  1  2  0 97  0  2 126248   2688  13376  87156    0    0   532   528 1057   708  2  5  0 93  0  0 126248   3948  13384  87668    0    0   436     4 1043   342  3  3 43 51  1  0 126248   3980  13384  87668    0    0     0     0 1154   426  3  1 96  0  0  0 126248   3980  13384  87668    0    0     0     0 1139   422  2  1 97  0 12  0 126248   4020  13384  87668    0    0     0     0 1023   195  9  0 91  0 

Because prelink looks like the guilty application, we can start investigating exactly what it is and why it is run. In Listing 12.4, we ask rpm to tell us which files are part of the package that prelink is part of.

Listing 12.4.

 [root@localhost root]# rpm -qlf 'which prelink' /etc/cron.daily/prelink /etc/prelink.conf /etc/rpm/macros.prelink /etc/sysconfig/prelink /usr/bin/execstack /usr/sbin/prelink /usr/share/doc/prelink-0.3.2 /usr/share/doc/prelink-0.3.2/prelink.pdf /usr/share/man/man8/execstack.8.gz /usr/share/man/man8/prelink.8.gz 

First, we note that the prelink package has a cron job that runs daily. This explains why the performance problem occurs periodically. Second, we note that prelink has a man page and documentation that describe its function. The man page describes prelink as an application that can prelink executables and libraries so that their startup times decrease. (It is just a little ironic that an application that is meant to boost performance is slowing down our system.) The prelink application can be run in two modes. The first mode causes all of the specified executables and libraries to be prelinked even if it has already been done. (This is specified by the --force or -f option). The second mode is a quick mode, where prelink just checks the mtimes and ctimes of the libraries and executables to see whether anything has changed since the last prelinking. (This is specified by the --quick or -q option.) Normally, prelink writes all the mtimes and ctimes of the prelinked executable to its own cache. It then uses that information in quick mode to avoid prelinking those executables that have already been linked.

Examining the cron entry from the prelink package shows that, by default, the Fedora system uses prelink in both modes. It calls prelink in the full mode every 14 days. However, for every day between that, prelink runs in the quick mode.

Timing prelink in both full and quick mode tells us how slow the worst case is (full prelinking) and how much performance increases when using the quick mode. We have to be careful when timing prelink, because different runs may yield radically different times. When running an application that uses a significant amount of disk I/O, it is necessary to run it several times to get an accurate indication of its baseline performance. The first time a disk-intensive application is run, much of the data from its I/O is loaded into the cache. The second time the application is run, performance is much greater, because the data it is using is in the disk caches, and it does not need to read from the disk. If you use the first run as the baseline, you can be misled into believing that performance has increased after a performance tweak when the real cause of the performance boost was the warm caches. By just running the application several times, you can warm up the caches and get an accurate baseline. Listing 12.5 shows the results of prelink in both modes after it has been run several times.

Listing 12.5.

 [root@localhost root]# time prelink -f -a .... real    4m24.494s user    0m9.552s sys     0m14.322s [root@localhost root]# time prelink -q -a .... real    3m18.136s user    0m3.187s sys     0m3.663s 

The first fact to note from Listing 12.5 is that the quick mode is not all that quicker than the full mode. This is suspicious and needs more investigation. The second fact reinforces what top reported. prelink spends only a small amount of CPU time; the rest is spent waiting for disk I/O.

Now we have to pick a reasonable goal. The PDF file that was installed in the prelink package describes the process of prelinking. It also says that the full mode should take several minutes, and the quick mode should take several seconds. As a goal, let's try to reduce the quick mode's time to under a minute. Even if we could optimize the quick mode, we would still have significant disk grinding every 14 days, but the daily runs would be much more tolerable.