쓰기 시스템 호출이 너무 많을 때 top이 높은 %wa를 보고하지 않는 이유

쓰기 시스템 호출이 너무 많을 때 top이 높은 %wa를 보고하지 않는 이유

내 HTTP 애플리케이션이 갑자기 시작하는 데 추가 시간이 걸리기 시작했습니다. 이 단계에서는 디스크의 데이터를 메모리 내 데이터 구조로 로드합니다.

이는 마지막 변경 중 루프 내부의 과도한 로깅 때문인 것으로 의심되지만 병목 현상이 IO인지 확인하려면 몇 가지 증거가 필요합니다.

내가 한 것은 strace너무 많은 시스템 write호출을 보여주었고 예상대로 그것의 처음 몇 줄이 여기에 인쇄되었습니다.

ubuntu@hemu-mcahine:~$ sudo strace -p 109374
[sudo] password for ubuntu:
strace: Process 109374 attached
write(1, "s1 size:, %!i(int=338632)\n", 26) = 26
futex(0x93a7d8, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0xc00003c948, FUTEX_WAKE_PRIVATE, 1) = 1
--- SIGURG {si_signo=SIGURG, si_code=SI_TKILL, si_pid=109374, si_uid=1001} ---
rt_sigreturn({mask=[]})                 = 1
write(1, "s1 size:, %!i(int=338633)\n", 26) = 26
write(1, "s1 size:, %!i(int=338634)\n", 26) = 26
write(1, "s1 size:, %!i(int=338635)\n", 26) = 26
write(1, "s1 size:, %!i(int=338636)\n", 26) = 26
write(1, "s1 size:, %!i(int=338637)\n", 26) = 26
write(1, "s1 size:, %!i(int=338638)\n", 26) = 26
write(1, "s1 size:, %!i(int=338639)\n", 26) = 26
write(1, "s1 size:, %!i(int=338640)\n", 26) = 26
write(1, "s1 size:, %!i(int=338641)\n", 26) = 26
write(1, "s1 size:, %!i(int=338642)\n", 26) = 26
write(1, "s1 size:, %!i(int=338643)\n", 26) = 26
write(1, "s1 size:, %!i(int=338644)\n", 26) = 26
write(1, "s1 size:, %!i(int=338645)\n", 26) = 26
write(1, "s1 size:, %!i(int=338646)\n", 26) = 26
write(1, "s1 size:, %!i(int=338647)\n", 26) = 26
write(1, "s1 size:, %!i(int=338648)\n", 26) = 26
write(1, "s1 size:, %!i(int=338649)\n", 26) = 26
...

"top"에 대한 출력이 높은 "%wa"로 표시될 것으로 예상했지만 주로 두 CPU가 상당한 대기 시간이나 컴퓨팅 시간 없이 유휴 상태인 것으로 표시됩니다. 이유는 무엇입니까?

이것은 상단의 출력입니다. 첫 번째 프로세스는 내 애플리케이션을 나타냅니다.

top - 08:21:58 up 5 days, 21:32,  2 users,  load average: 0.00, 0.00, 0.00
Tasks: 140 total,   1 running, 138 sleeping,   0 stopped,   1 zombie
%Cpu0  :  0.3 us,  1.3 sy,  0.0 ni, 98.0 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
%Cpu1  :  0.7 us,  1.0 sy,  0.0 ni, 98.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
MiB Mem :   3925.3 total,   2310.1 free,    831.4 used,    783.9 buff/cache
MiB Swap:      0.0 total,      0.0 free,      0.0 used.   2861.2 avail Mem

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
 109374 ubuntu    20   0 1084416 118780   5392 S   1.7   3.0   0:01.77 server
 108671 ubuntu    20   0   14836   7020   4304 S   0.7   0.2   0:06.71 sshd
    841 root      20   0  402468  30328   8916 S   0.3   0.8   6:07.89 python3
  86001 root      20   0       0      0      0 I   0.3   0.0   0:06.41 kworker/0:3-events
  88908 ubuntu    20   0 1029916  77444  33692 S   0.3   1.9   0:39.35 node
 109196 root      20   0       0      0      0 I   0.3   0.0   0:00.74 kworker/u4:0-events_unbound
 109280 root      20   0       0      0      0 I   0.3   0.0   0:00.44 kworker/u4:1-events_power_efficient
 109398 ubuntu    20   0   11276   4224   3548 R   0.3   0.1   0:00.01 top
      1 root      20   0  168972  13052   8312 S   0.0   0.3   0:15.16 systemd
      2 root      20   0       0      0      0 S   0.0   0.0   0:00.04 kthreadd
      3 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_gp
      4 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_par_gp
      5 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 netns
      7 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 kworker/0:0H-events_highpri
      9 root       0 -20       0      0      0 I   0.0   0.0   0:08.76 kworker/0:1H-events_highpri
     10 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mm_percpu_wq
     11 root      20   0       0      0      0 S   0.0   0.0   0:00.00 rcu_tasks_rude_
     12 root      20   0       0      0      0 S   0.0   0.0   0:00.00 rcu_tasks_trace
     13 root      20   0       0      0      0 S   0.0   0.0   0:00.77 ksoftirqd/0
     14 root      20   0       0      0      0 I   0.0   0.0   0:33.30 rcu_sched
     15 root      rt   0       0      0      0 S   0.0   0.0   0:02.53 migration/0

내 코드가 계속 로깅하고 서버 속도가 느려지는 경우 유휴 시간이 긴 이유와 "%wa"가 너무 많지 않은 이유를 어떻게 알 수 있습니까?

답변1

몇 가지 시나리오에 대해 몇 가지 실험을 했고 이제 답을 얻은 것 같습니다.

뒤쪽에@소토의견과 인터넷 검색에 따르면 터미널에 인쇄하는 것은 디스크에 쓰는 것과 다르다는 것을 알았습니다. 전자는 추가 처리가 필요하고 스레드는 데이터가 터미널에 인쇄될 때까지 기다려야 하며 터미널의 버퍼링은 동일하게 작동합니다. 디스크 I/O와 같은 방식입니다. 이 답변은 그것을 아주 잘 설명합니다https://stackoverflow.com/questions/6338812/printing-to-the-console-vs-writing-to-a-file-speed.

또한 stdout 대신 파일에 로그를 보내는 것이 더 빠르지만 명령 에 의해 증가하는 sy대신 커널 공간 시간이 증가합니다 . 나는 이것이 sys 호출이 디스크의 파일에 직접 쓰지 않고 대신 파일 시스템의 버퍼로 보내서 가능한 최선의 방법으로 디스크에 쓰기를 처리하기 때문이라는 것을 알았습니다.wa%Topwrite

나중에 sys 호출을 사용하여 모든 로그를 인쇄하여 sync버퍼를 지우고 모든 데이터를 즉시 파일에 커밋하기 시작했습니다. 여기서 wa%IO 작업의 데이터가 예상보다 훨씬 높고 CPU가 대부분 절전 모드인 것을 확인했습니다.

결론적으로:

  • 터미널은 디스크 I/O와 동일하지 않으며 더 느립니다.
  • 시스템 호출을 통해 작성된 I/O 함수는 write파일 시스템 버퍼로 인해 디스크 쓰기 오버헤드를 반드시 증가시키지는 않지만 컨텍스트 전환을 증가시키고 커널 공간에서 CPU 주기를 소비합니다.

관련 정보