Início / unix / Perguntas / 419449
Accepted
Kenny
Asked: 2018-01-25 12:29:09 +0800 CST

Como posso determinar se uma latência é devida a um driver ou ao agendador?

  • 772

Usando um osciloscópio e alternando alguns pinos, às vezes vejo latências de 1 a 2 segundos desde o momento em que um pacote UART de 8 bytes é transmitido até o retorno de uma leitura de bloqueio. Os pacotes são de 1 segundo com alguns milissegundos de jitter. Eu também medi o tempo para as chamadas do sistema (veja abaixo) usando stracee os resultados concordaram com minhas medições de I/O.

Estou tentando determinar se essa latência está no driver UART ou se outras tarefas estão atrapalhando minha tarefa, que tem um valor de gentileza de -20. O motivo pelo qual estou pensando sobre o driver é que uma versão anterior desse código usava o UART de maneira confiável para transmitir pacotes de aproximadamente 26 kB por segundo (o buffer do driver é de 4 kB).

O processo é um script Python que está usando pyserial. Neste caso de falha, stracerelata o tempo entre epoll_waite clock_gettimecomo mais de 3 segundos.

0.000883 epoll_ctl(3, EPOLL_CTL_ADD, 7, {EPOLLIN, {u32=7, u64=8589934599}}) = -1 EEXIST (File exists)
0.000681 clock_gettime(CLOCK_MONOTONIC, {92406, 209555006}) = 0
0.000655 epoll_wait(3, {}, 64, 98) = 0
3.004082 clock_gettime(CLOCK_MONOTONIC, {92409, 214251206}) = 0

As ações repetidas são: Receber pacote de 8 bytes para solicitar que o Linux leia o número N de bytes via SPI. Execute o SPI. Leia o pacote de 8 bytes para ver se a solicitação SPI foi concluída com sucesso. A transferência SPI leva cerca de 40 ms. O padrão saudável é de aproximadamente 40 ms entre o pacote de solicitação e o pacote de resultado. E ~960 ms até receber a próxima solicitação.

Duchess: strace -r -e read -p 7564
Process 7564 attached
     0.000000 read(7, "\355\336\255\336\20d\0\0", 8) = 8
     0.049142 read(7, "\255\336\355\336\1\0\0\0", 8) = 8
     0.950381 read(7, "\355\336\255\336\20d\0\0", 8) = 8
     0.050035 read(7, "\255\336\355\336\1\0\0\0", 8) = 8
     0.949962 read(7, "\355\336\255\336\20d\0\0", 8) = 8
     0.049601 read(7, "\255\336\355\336\1\0\0\0", 8) = 8
     0.950417 read(7, "\355\336\255\336\20d\0\0", 8) = 8
     0.049654 read(7, "\255\336\355\336\1\0\0\0", 8) = 8
     0.950507 read(7, "\355\336\255\336\20d\0\0", 8) = 80.950516 read(7, "\355\336\255\336\20d\0\0", 8) = 8 [SPI Request]
     0.049944 read(7, "\255\336\355\336\1\0\0\0", 8) = 8 [Success]
     2.196903 read(7, "\355\336\255\336\20d\0\0", 8) = 8 [SPI Request]
     0.048876 read(7, "\255\336\355\336\0\0\0\0", 8) = 8 [Failure]
     0.015570 read(7, "\355\336\255\336\20d\0\0", 8) = 8 [SPI Request]
     0.053889 read(7, "\255\336\355\336\0\0\0\0", 8) = 8 [Failure]
     0.634720 read(7, "\355\336\255\336\20d\0\0", 8) = 8 [SPI Request]
     0.050070 read(7, "\255\336\355\336\1\0\0\0", 8) = 8 [Success]
strace uart

1 respostas

  1. Best Answer

    straceprovavelmente não fornecerá o nível necessário de detalhes; você provavelmente precisará de SystemTap, sysdig ou depuração semelhante no nível do kernel para mostrar melhor quando o que está acontecendo. Por exemplo, com o SystemTap instalado e todas as informações de depuração e detalhes de configuração necessários, pode-se começar com:

    probe begin
{
        printf("%-16s %s\n", "TIME", "WHAT");
}

probe tty.{ioctl,receive}
{
        if (pid() != target()) next;
        printf("%d ttyx    %s\n", gettimeofday_us(), name);
}

probe tty.poll
{
        if (pid() != target()) next;
        printf("%d ttypoll %s\n", gettimeofday_us(), file_name);
}

probe tty.{read,write}
{
        if (pid() != target()) next;
        printf("%d ttyio   %s %d\n", gettimeofday_us(), file_name, nr);
}

probe syscall.{read,write,epoll_*}
{
        if (pid() != target()) next;
        printf("%d syscall %s\tenter\n", gettimeofday_us(), name);
}

probe syscall.{read,write,epoll_*}.return
{
        if (pid() != target()) next;
        printf("%d syscall %s\treturn\n", gettimeofday_us(), name);
}

    e executá-lo via

    $ sudo stap -x "$(pidof ...)" filecontainingtheabovecode.stp

    que para um programa de teste serial e um Arduino anexado para mim mostra:

    TIME             WHAT
1516997916648359 syscall read   enter
1516997916648366 ttyio   ttyACM0 4096
1516997916652456 syscall read   return
1516997916652465 syscall read   enter
1516997916652470 ttyio   ttyACM0 4096
1516997916656459 syscall read   return
1516997916656497 syscall write  enter
1516997916656503 ttyio   4 21
1516997916656511 syscall write  return
...

    Você também pode precisar consultar a documentação dos tapsets do SystemTap para outros pontos de interesse da sonda (agendador, agendador de E/S, IRQs?) se o acima não mostrar onde está o atraso. E possivelmente para comparar os tempos com a versão antiga do código/driver/sistema...

    • 2

relate perguntas