Dominic Cleal's Blog

Mon, 03 Mar 2008 23:52:51 GMT

permalink Microseconds, within a few orders of magnitude

In order to do a quick performance test against somebody else's program, I was firing packets at it to test how many it was dropping from a quick Perl script. While that was interesting, in that it was dropping a significant number of packets when under high load (probably close to that of production load at certain times of the day), another problem entertained me.

I was trying to introduce some small sleeps into the script to back off the load some more and turned to the Time::HiRes module for its usleep function. The first problem that I noticed was the script, which previously ran in a fraction of a second, now given a 1 s sleep time was taking about 10 seconds to perform 1,000 iterations. Hence 10ms per iteration and a few orders of magnitude more than I expected!

I tried running this on my local host and it ran as expected in a fraction of a second still. Checking the docs for usleep revealed that it will return the actual number of s that it slept for. This gives us the handy snippet:

perl -mTime::HiRes -e '$t+=Time::HiRes::usleep(0) for (1..1000);print ($t/1000); print "\n";'

The catch seems to be that I was running the test on a couple of Xen guests on older kernels. Some stats that I've recorded and got from people:

  • Linux 2.6.24, Ubuntu Gutsy, x86_64: 0.85 s

  • Linux 2.6.22, Kubuntu Gutsy, i686: 7.121 s

  • Linux 2.6.18, Debian Etch, x86_64: 3998.712 s

  • Xen (BitFolk), Linux 2.6.18, Debian Etch, i686: 4007.393 s

  • Xen (EC2), Linux 2.6.16, Fedora Core 4, i686: 8921.402 s

  • Virtual PC, Linux 2.6.22, Ubuntu Gutsy, i686: 9906.802 s

It seems to point at newer kernels being different - probably to do with the kernel ticks. I seem to remember reading about dynamic ticks being present in newer kernels...

Comments for this entry are now closed.