내 Python 앱이 여러 스레드에서 최대 10초 이상 동안 100% '시스템' CPU 시간을 사용하는 데 어려움을 겪고 있습니다. 나의 (제한된) 이해는 '시스템' CPU 시간이 커널에서 소비된 시간이라는 것입니다. strace어떤 커널 호출이 수행되고 있는지와 (선택적으로) 소요 시간이 표시됩니다. 이러한 일시 중지 중 하나에서 strace를 한 스레드에서 실행할 수 있었지만 strace 출력에는 해당 기간 동안 공백이 있었고 해당 공백의 양쪽 호출은 매우 짧은 시간으로 표시됩니다.
어떤 커널 호출이 발생하고 있는지 파악하기 위해 strace를 올바르게 실행하려면 어떻게 해야 합니까?
내 Python 앱에서는 별도의 스레드를 사용하여 psutil시스템 CPU가 높은 스레드를 확인한 다음 로그아웃합니다. 일단 확인되면 다음 명령줄을 사용하여 strace를 시작합니다.
strace -tT -o ~/strace.log -p <PID of thread>
내 앱에서 로깅( psutil내부적으로 사용):
2015-05-19 08:05:47,025 WARNING:log.cpu Logging paused for 0.34s to 08:05:46.985768 - longer than expected - other threads probably delayed as well
2015-05-19 08:05:47,026 WARNING:log.cpu This process utilization (CPUs) user: 0.1, system: 52.4 | OS (%) scputimes(user=0.4, nice=0.0, system=80.2, idle=19.3, iowait=0.0, irq=0.0, softirq=0.0, steal=0.0, guest=0.0, guest_nice=0.0), memory used: 16.6, threads: 101, fds: 70
2015-05-19 08:05:47,027 WARNING:log.cpu Thread 47441 utilization (CPUs) user: 0.0, system: 1.0
2015-05-19 08:05:47,512 WARNING:log.cpu This process utilization (CPUs) user: 0.1, system: 61.4 | OS (%) scputimes(user=0.5, nice=0.0, system=99.4, idle=0.1, iowait=0.0, irq=0.0, softirq=0.0, steal=0.0, guest=0.0, guest_nice=0.0), memory used: 16.6, threads: 101, fds: 70
2015-05-19 08:05:47,516 WARNING:log.cpu Thread 47441 utilization (CPUs) user: 0.0, system: 0.9
2015-05-19 08:05:47,995 WARNING:log.cpu This process utilization (CPUs) user: 0.3, system: 63.7 | OS (%) scputimes(user=0.8, nice=0.0, system=99.2, idle=0.0, iowait=0.0, irq=0.0, softirq=0.0, steal=0.0, guest=0.0, guest_nice=0.0), memory used: 16.6, threads: 101, fds: 70
2015-05-19 08:05:47,995 WARNING:log.cpu Thread 47441 utilization (CPUs) user: 0.0, system: 0.8
2015-05-19 08:05:48,495 WARNING:log.cpu This process utilization (CPUs) user: 0.3, system: 63.8 | OS (%) scputimes(user=0.7, nice=0.0, system=99.3, idle=0.0, iowait=0.0, irq=0.0, softirq=0.0, steal=0.0, guest=0.0, guest_nice=0.0), memory used: 16.6, threads: 101, fds: 70
2015-05-19 08:05:48,496 WARNING:log.cpu Thread 47441 utilization (CPUs) user: 0.0, system: 0.8
2015-05-19 08:05:52,140 WARNING:log.cpu Logging paused for 3.12s to 08:05:52.103363 - longer than expected - other threads probably delayed as well
2015-05-19 08:05:52,153 WARNING:log.cpu This process utilization (CPUs) user: 0.0, system: 63.6 | OS (%) scputimes(user=0.3, nice=0.0, system=98.5, idle=1.2, iowait=0.0, irq=0.0, softirq=0.0, steal=0.0, guest=0.0, guest_nice=0.0), memory used: 16.6, threads: 101, fds: 70
2015-05-19 08:05:52,180 WARNING:log.cpu Thread 47441 utilization (CPUs) user: 0.0, system: 1.0
해당 스레드 ID 47441에서 동일한 기간 동안 strace 로그:
08:05:46 futex(0x7f7b46b305ac, FUTEX_WAKE, 1) = 1 <0.000030>
08:05:46 sched_yield() = 0 <0.000016>
08:05:46 sched_yield() = 0 <0.000017>
08:05:46 sched_yield() = 0 <0.000021>
08:05:46 sched_yield() = 0 <0.000053>
08:05:46 sched_yield() = 0 <0.000023>
08:05:46 sched_yield() = 0 <0.000020>
08:05:46 sched_yield() = 0 <0.000019>
08:05:46 sched_yield() = 0 <0.000021>
08:05:46 futex(0x7f7b46b3202c, FUTEX_WAIT, 2, NULL) = 0 <0.000574>
08:05:46 futex(0x7f7b46b30f2c, FUTEX_WAKE, 1) = 1 <0.000019>
08:05:46 futex(0x7f7b46b3072c, FUTEX_WAKE, 1) = 1 <0.000028>
08:05:46 sched_yield() = 0 <0.000022>
08:05:46 futex(0x7f7b46b3202c, FUTEX_WAIT, 2, NULL) = 0 <0.000305>
08:05:46 futex(0x7f7b46b31fac, FUTEX_WAKE, 1) = 1 <0.000119>
08:05:46 futex(0x7f7b46b319ac, FUTEX_WAKE, 1) = 1 <0.000073>
08:05:46 futex(0x7f7b46b3202c, FUTEX_WAIT, 2, NULL) = 0 <0.000474>
08:05:46 futex(0x7f7b46b31f2c, FUTEX_WAKE, 1) = 1 <0.000094>
08:05:46 futex(0x7f7b46b30dac, FUTEX_WAKE, 1) = 1 <0.000096>
08:05:46 futex(0x7f7b46b3202c, FUTEX_WAIT, 2, NULL) = 0 <0.001139>
08:05:46 futex(0x7f7b46b31eac, FUTEX_WAKE, 1) = 1 <0.000156>
08:05:46 futex(0x7f7b46b303ac, FUTEX_WAKE, 1) = 1 <0.000059>
08:05:52 sched_yield() = 0 <0.000081>
08:05:52 sched_yield() = 0 <0.000050>
08:05:52 futex(0x7f7b46b3202c, FUTEX_WAIT, 2, NULL) = 0 <0.001603>
08:05:52 futex(0x7f7b46b31d2c, FUTEX_WAKE, 1) = 1 <0.000318>
08:05:52 futex(0x7f7b46b30f2c, FUTEX_WAKE, 1) = 1 <0.000259>
08:05:52 sched_yield() = 0 <0.000048>
08:05:52 sched_yield() = 0 <0.000060>
08:05:52 sched_yield() = 0 <0.000203>
08:05:52 futex(0x7f7b46b3202c, FUTEX_WAIT, 2, NULL) = 0 <0.000148>
08:05:52 sched_yield() = 0 <0.000036>
08:05:52 sched_yield() = 0 <0.000164>
08:05:52 futex(0x7f7b46b3202c, FUTEX_WAIT, 2, NULL) = 0 <0.003125>
08:05:52 sched_yield() = 0 <0.000053>
08:05:52 sched_yield() = 0 <0.000052>
08:05:52 sched_yield() = 0 <0.000023>
08:05:52 futex(0x7f7b46b3202c, FUTEX_WAIT, 2, NULL) = 0 <0.002264>
08:05:52 futex(0x7f7b46b3122c, FUTEX_WAKE, 1) = 1 <0.000119>
strace가 초당 100개의 항목을 기록하고 6초 동안 아무 것도 기록되지 않는 방법을 참고하세요. 그러나 몇 밀리초 이상 걸리는 호출은 표시되지 않습니다. 그러면 해당 스레드가 어떻게 '시스템' CPU 시간을 100% 표시했습니까?
나는 top그것이 psutil정확한 숫자를 보고하고 있는지 확인하곤 했습니다. 그리고 6초의 간격이 psutil이 기록한 높은 CPU 시간과 정확히 일치하기 때문에 올바른 스레드를 추적했다고 확신합니다.
이 커널/시스템 시간의 원인을 파악하기 위해 사용할 수 있는 다른 도구에 대한 도움도 감사하겠습니다.
환경: - Python 3.4.3(Python 2.7에서도 나타나는 문제) - CentOS 7 커널 3.10.0-229.1.2.el7.x86_64(Ubuntu 12 LTS에서도 나타나는 문제) - 64 코어 AMD 시스템