내 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%
Top
write
나중에 sys 호출을 사용하여 모든 로그를 인쇄하여 sync
버퍼를 지우고 모든 데이터를 즉시 파일에 커밋하기 시작했습니다. 여기서 wa%
IO 작업의 데이터가 예상보다 훨씬 높고 CPU가 대부분 절전 모드인 것을 확인했습니다.
결론적으로:
- 터미널은 디스크 I/O와 동일하지 않으며 더 느립니다.
- 시스템 호출을 통해 작성된 I/O 함수는
write
파일 시스템 버퍼로 인해 디스크 쓰기 오버헤드를 반드시 증가시키지는 않지만 컨텍스트 전환을 증가시키고 커널 공간에서 CPU 주기를 소비합니다.