strace não mostrando nada para thread em 100% 'system' CPU

Question

Estou com dificuldades em meu aplicativo Python atingir 100% do tempo de CPU do "sistema" em vários segmentos por até mais de 10 segundos. Meu (limitado) entendimento é que o tempo de CPU do 'sistema' é o tempo gasto no kernel. strace mostra quais chamadas do kernel estão sendo feitas e (opcionalmente) quanto tempo elas levam. Eu consegui executar strace em um thread durante uma dessas pausas, mas a saída strace apenas tem uma lacuna para esse período e as chamadas de cada lado dessa lacuna são mostradas com um tempo muito curto.

Como eu corro strace corretamente para descobrir qual chamada do kernel está acontecendo?

No meu aplicativo Python, eu uso um thread separado e psutil para verificar se há threads com alta CPU do sistema e, em seguida, faça o logout deles. Quando vejo um, uso a seguinte linha de comando para iniciar o strace:

strace -tT -o ~/strace.log -p <PID of thread>

Fazendo login no meu aplicativo (usa psutil no capô):

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 log durante o mesmo período no ID de segmento 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>

Observe como strace está registrando 100 entradas por segundo e depois há uma lacuna de 6 segundos de nada. Mas nenhuma chamada é mostrada como tendo mais do que um par de milissegundos. Então, como esse segmento mostrou 100% do tempo de CPU do 'sistema'?

Eu usei top para confirmar que psutil está relatando números corretos. E tenho certeza que rastreei o segmento correto porque o intervalo de 6 segundos corresponde exatamente ao alto tempo de CPU registrado pelo psutil.

Ajuda também apreciado com que outras ferramentas eu poderia usar para descobrir o que está causando esse tempo de kernel / sistema?

Ambiente: - Python 3.4.3 (problema também visto no Python 2.7) - kernel do CentOS 7 3.10.0-229.1.2.el7.x86_64 (problema também encontrado no Ubuntu 12 LTS) - máquina AMD de 64 núcleos