Thursday, January 26, 2012

Wasting the time.

NIX knows how to record the worst/total/number of waiting times for each lock used in the kernel. Including queueing locks and other types of lock. This lets us retrieve from /dev a list of the ones where programs waste their time (be that for useful work or not). These are the winners as of today, as reported by the kernel


what pc #times maxtime tottime where meantime
lock 0xfffffffff017d490 50 12710074 215909070 /sys/src/nix/port/page.c:560 4318181
lock 0xfffffffff017d486 4 6326408 16216101 /sys/src/nix/port/page.c:560 4054025
lock 0xfffffffff017ce18 112 6763350 293233176 /sys/src/nix/port/page.c:309 2618153
lock 0xfffffffff017cbc3 78 12051128 126828266 /sys/src/nix/port/page.c:222 1626003
lock 0xfffffffff01620c0 162 1366053 14176025 /sys/src/nix/port/devmnt.c:1052 87506
qlock 0xfffffffff01773cc 581 1009266 40825474 /sys/src/nix/port/qio.c:1187 70267
qlock 0xfffffffff012cf2e 155 1238110 10673584 /sys/src/nix/k10/ether82563.c:893 68861
qlock 0xfffffffff01402af 376 574149 24205418 /sys/src/nix/ip/tcp.c:547 64376
qlock 0xfffffffff0143bee 350 492911 14229109 /sys/src/nix/ip/tcp.c:2118 40654
lock 0xfffffffff0119308 593 1121568 18533782 /sys/src/nix/k10/qmalloc.c:275 31254
lock 0xfffffffff0119a17 11183 1365890 294252474 /sys/src/nix/k10/qmalloc.c:500 26312
lock 0xfffffffff016226b 80 459279 1898897 /sys/src/nix/port/devmnt.c:1101 23736

The list is not interesting unless you are optimizing the kernel, but it shows how powerful this simple instrument can be. It's easy to spot some parts which are responsible for making the programs wait, perhaps more than really needed.