У меня возникли трудности с моим приложением Python, которое достигает 100% 'системного' времени ЦП в нескольких потоках в течение более 10 секунд. Мое (ограниченное) понимание заключается в том, что 'системное' время ЦП - это время, проведенное в ядре. straceпоказывает, какие вызовы ядра выполняются и (необязательно) сколько времени они занимают. Мне удалось запустить strace в одном потоке во время одной из таких пауз, но в выводе strace есть только пробел для этого периода, а вызовы по обе стороны от этого пробела отображаются с очень коротким временем.
Как правильно запустить strace, чтобы выяснить, какой вызов ядра происходит?
В моем приложении Python я использую отдельный поток и psutilпроверяю наличие потоков с высокой загрузкой ЦП, а затем выхожу из системы. Как только я вижу один поток, я использую следующую командную строку для запуска 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
Журнал strace за тот же период в теме с идентификатором 47441:
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 регистрирует сотни записей в секунду, а затем следует 6-секундный перерыв. Но ни один вызов не отображается как требующий больше пары миллисекунд. Так как же этот поток показал 100% 'системного' времени ЦП?
Я использовал topдля подтверждения того, что psutilсообщает правильные цифры. И я уверен, что отследил правильный поток, потому что 6-секундный разрыв точно соответствует высокому времени ЦП, зафиксированному psutil.
Также признателен за помощь с тем, какие еще инструменты я могу использовать, чтобы выяснить, что вызывает это время ядра/системы?
Окружение: - Python 3.4.3 (проблема также наблюдается в Python 2.7) - Ядро CentOS 7 3.10.0-229.1.2.el7.x86_64 (проблема также наблюдается в Ubuntu 12 LTS) - 64-ядерный компьютер AMD