Localizar hog de kernel de CPU ocasional

Question

Eu tenho um kernel PREEMPT 2.6.35 rodando em processador ARMv7 de velocidade moderada. Cerca de uma vez a cada 100 - 125s, algo faz com que o kernel falhe em processar alguns drivers relacionados a áudio com bastante rapidez para evitar déficits. O hold-up geralmente está na faixa de 15 a 30 ms, mas pode ser muito mais longo. Não está claro se o hold-up é inteiramente in-kernel ou pode estar relacionado ao escalonamento de um processo do usuário executando com prioridade em tempo real (SCHED_RR, 2).

Meu palpite é que há um (pelo menos um) driver que não está jogando bem com preempção.

Algumas saídas strace do processo do usuário ilustram algum aspecto do comportamento normal e anormal, embora eu não esteja certo de como interpretar os vários relatórios de tempo?

Caso normal:

     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 

Nenhum bloqueio ocorre na pesquisa para saída em fd6 e, quando somente fd10 é pesquisado para entrada, ocorre um bloco de aproximadamente 10ms. Isso é refletido no relatório da duração da chamada do sistema e no intervalo entre as chamadas do sistema (elas são consistentes).

Caso de falha (exemplo extremo):

     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 

Observe que, neste caso, mesmo que a segunda última chamada seja gravada como 10 ms (normal), ela será 953 ms antes da última chamada.

Quais ferramentas posso usar para rastrear o culpado?

    

Answer 1

perf pode ser útil para você. Faz parte dos utilitários de kernel do linux.

Por exemplo:

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 

Ele mostrará todos os horários e parâmetros de entrada / saída syscall (como strace), fornecerá o nome do binário que invoca o syscall e amostrará o callstack de cada CPU em alguma frequência (incluindo símbolos de kernel). Então você pode realmente ver qual código foi executado durante o syscall. Em um sistema multiprocessador, você precisa prestar atenção ao id da cpu (por exemplo, [001]).

    

Answer 2

Talvez atop possa esclarecer seu problema.

Pode mostrar processos que já saíram, e pode mostrar CPU , Memória , Disco e Rede utilização.

Você pode executá-lo interativo, deixá-lo gravar em um arquivo de texto ou executá-lo como sar em um intervalo predefinido, criando um arquivo de histórico binário que você pode percorrer depois.

Eu uso para encontrar porcos de todos os tipos que são difíceis de encontrar: -)