11

I have a 2.6.35 PREEMPT kernel running on moderate-speed ARMv7 processor. About once every 100 - 125s, something causes the kernel to fail to process some audio-related drivers sufficiently quickly to avoid underruns. The hold-up are generally in the range 15-30ms, but can be very much longer. It is not clear whether the hold-up is entirely in-kernel or may relate to the scheduling of a user process running with real-time priority (SCHED_RR, 2).

My guess is that there is a (at least one) driver that is not playing nice with preempt.

Some strace output from the user process illustrates some aspect of both normal and abnormal behaviour, although I am not certain how to interpret the various time reports?

Normal case:

     0.000518 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL, revents=POLLIN}], 1, 3415) = 1 
     0.010202 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL}, {fd=6, events=POLLOUT|POLLERR|POLLNVAL, revents=POLLOUT}], 2, 3404) = 1 
     0.000585 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL}, {fd=6, events=POLLOUT|POLLERR|POLLNVAL, revents=POLLOUT}], 2, 3404) = 1 
     0.000302 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL, revents=POLLIN}], 1, 3404) = 1 
     0.010706 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL}, {fd=6, events=POLLOUT|POLLERR|POLLNVAL, revents=POLLOUT}], 2, 3393) = 1 
     0.000480 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL}, {fd=6, events=POLLOUT|POLLERR|POLLNVAL, revents=POLLOUT}], 2, 3392) = 1

No blocking occurs on the poll for output on fd6 and, when only fd10 is polled for input, a block of around 10ms occurs. This is reflected both in the report of the duration of the system call and the interval between system calls (they are consistent).

Failure case (extreme example):

     0.000305 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL, revents=POLLIN}], 1, 3543) = 1 
     0.010730 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL}, {fd=6, events=POLLOUT|POLLERR|POLLNVAL, revents=POLLOUT}], 2, 3533) = 1 
     0.000475 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL}, {fd=6, events=POLLOUT|POLLERR|POLLNVAL, revents=POLLOUT}], 2, 3532) = 1 
     0.000329 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL, revents=POLLIN}], 1, 3532) = 1 
     0.953349 poll([{fd=10, events=POLLIN|POLLERR|POLLNVAL}, {fd=6, events=POLLOUT|POLLERR|POLLNVAL, revents=POLLOUT|POLLERR}], 2, 2578) = 1

Notice in this case that, even though the second-last call is recorded as taking 10ms (normal), it is 953ms before the last call.

What tools can I use to track down the culprit?

Damien
  • 748
  • 8
  • 14
awy
  • 301
  • 2
  • 6
  • 2
    Bonus points for the interesting question. I'm not sure how to answer it but I do have a question as to how to tracked it back to CPU usage (as opposed to spikes in iowait, for instance)? – Bratchley Apr 03 '13 at 16:45
  • 1
    First guess is if you are running JFFS2 or YAFFS on a large NAND flash, especially if you are recording. Disable anything that writes to flash and see if that helps. What's your process table look like? You can use ftrace as a last resort if you have a toolchain to build the kernel. – Jonathan Ben-Avraham May 02 '13 at 20:03
  • sar -bu might do it.. http://linux.die.net/man/1/sar – Grizly Jul 09 '13 at 00:43
  • There is some flash in use; an SD card with a mounted ext4 filesystem. And writes to it are indeed a possible source of these problems (but why, exactly?) but probably not the only one. – awy Aug 22 '13 at 06:25

2 Answers2

1

perf may be helpful for you. It is part of the linux kernel utilities.

For instance:

perf record -R -a -g fp -e cycles -e syscalls:sys_enter_poll -e syscalls:sys_exit_poll
#Just ctrl+c if you are done, and view ith
perf script

It will show all syscall enter/exit times and parameters (like strace), provide the name of the binary invoking the syscall and sample the callstack of each CPU at some frequency (including kernel symbols). So you can actually see what code was executed during the syscall. In a multiprocessor system you need to pay attention to the cpu id (e.g. [001]).

Zulan
  • 324
  • 1
  • 4
  • 11
0

Maybe atop can shed some light on your problem.

It can show processes that already exited, and it can show CPU, Memory, Disk and Network utilization.

You may run it interactive, let it write to a text file or run it like sar in a predefined interval, creating a binary history file that you can step through afterwards.

I use it to find hogs of all kinds that are hard to find :-)

trapicki
  • 101
  • 1