☰

지연이 드라이버로 인해 발생했는지 아니면 스케줄러로 인해 발생했는지 어떻게 확인할 수 있나요?

tag-icon • tag-icon strace uart latency
지연이 드라이버로 인해 발생했는지 아니면 스케줄러로 인해 발생했는지 어떻게 확인할 수 있나요?

오실로스코프를 사용하고 일부 핀을 전환하면 8바이트 UART 패킷 전송과 차단 읽기 반환 사이에 1~2초의 지연이 나타나는 경우가 있습니다. 패킷 지속 시간은 1초이며 몇 밀리초의 지터가 있습니다. 또한 (아래 참조)을 사용하여 시스템 호출 타이밍을 측정했으며 strace결과는 I/O 측정과 일치했습니다.

UART 드라이버에 이 지연이 존재하는지, 아니면 다른 작업이 내 작업에 영향을 미치는지(적당한 값은 -20임) 확인하려고 합니다. 드라이버에 대해 궁금한 이유는 이 코드의 이전 버전이 UART를 안정적으로 사용하여 초당 ~26kB 패킷을 전송했기 때문입니다(드라이버 버퍼는 4kB였습니다).

프로세스는 사용입니다 pyserial. 이 실패한 사례에서 strace보고된 시간 간격은 3초 이상 epoll_wait이었습니다 clock_gettime.

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

반복되는 작업은 다음과 같습니다. 8바이트 데이터 패킷을 수신하고 SPI를 통해 Linux에 N바이트를 읽도록 요청합니다. SPI를 실행합니다. 8바이트 패킷을 읽어 SPI 요청이 성공적으로 완료되었는지 확인합니다. SPI 전송에는 약 40ms가 소요됩니다. 요청 패킷과 결과 패킷 사이의 일반 모드는 약 40밀리초입니다. 다음 요청이 수신될 때까지 약 960밀리초가 소요됩니다.

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]

답변1

strace무슨 일이 일어나고 있는지 더 잘 보여주기 위해 SystemTap, sysdig 또는 유사한 커널 수준 디버깅이 필요할 수 있습니다. 예를 들어, SystemTap을 설치하고 필요한 모든 디버깅 정보와 설정 세부 사항을 처리한 후 다음을 시작할 수 있습니다.

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);
}

그리고 실행하여

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

이는 다음과 같은 경우에 유용합니다.직렬 테스트 프로그램그리고추가 Arduino나에게는 다음이 표시됩니다.

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
...

위의 내용이 지연 시간의 위치를 ​​표시하지 않으면 SystemTap Tapsets 설명서에서 다른 관심 지점(스케줄러, I/O 스케줄러, IRQ?)을 확인하는 것이 좋습니다. 그리고 이전 버전의 코드/드라이버/시스템과 시간을 비교할 수도 있습니다.

관련 정보