Why would brk() in strace output be taking several seconds?

We've been noticing a significant slowdown of one of our applications when migrated to Ubuntu Hardy, amd64. It runs perfectly well on Debian Sarge i386.

Running an 'strace -r' against the (Apache 1.3) httpd process has shown the following troubling section:

     0.000083 poll([{fd=8, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) = 1
     0.000026 recvfrom(8, "_323-412D\0\0\0000\0\2\0\0\0\17recueil-cours"..., 32727, 0, NULL, NULL) = 8192
     0.000061 poll([{fd=8, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) = 1
     0.000026 recvfrom(8, "\0\0\0000\0\2\0\0\0\17recueil-courses\0\0\0\23er2"..., 32767, 0, NULL, NULL) = 2369
     0.117422 brk(0x397a000)            = 0x397a000
     0.140721 brk(0x399b000)            = 0x399b000
     4.457037 brk(0x39bc000)            = 0x39bc000
     0.078792 stat("/opt/semantico/slot/nijhoff/3/sitecode/live/public_home.html", {st_mode=S_IFREG|0644, st_size=2194, ...}) = 0

Note the brk on the last-but-one line - implying that the brk(0x399b000) took 4.45 seconds!

I've checked out the man page for brk, which points at it being used for requesting a larger data segment/heap, but I can't find any reason why it would take so long.

Anyone got any ideas?

Solution 1:

brk() is how malloc expands its available memory pool. This means it that the kernel could be swapping or playing memory shell games to find a large enough new memory segment to hand back, so performance is... unpredictable. That said, you might want to look at some of the memory-use tunables (sysctl -a | grep ^vm should give you a good place to start looking) to change your memory allocation strategy some.

Solution 2:

It transpires that this issue was primarily down to my misunderstanding of the output of strace -r.

The '-r' option gives the time (in seconds) since the last system call, not the time that the last system call took to execute.

In this instance, the CPU was churning away performing some calculation, not processing the brk().

The issue here is now resolved - it was caused by an upgrade to perl 5.8.9 (from perl 5.8.8). We've backed out of the perl upgrade, and will look into the cause of the perl 5.8.9 slowdown later.