Tengo dificultades para que mi aplicación Python alcance el 100 % del tiempo de CPU del 'sistema' en varios subprocesos durante más de 10 segundos. Mi comprensión (limitada) es que el tiempo de CPU del 'sistema' es el tiempo invertido en el kernel. stracemuestra qué llamadas al kernel se están realizando y (opcionalmente) cuánto tiempo tardan. Logré ejecutar strace en un hilo durante una de estas pausas, pero la salida de strace solo tiene un espacio para ese período y las llamadas a ambos lados de ese espacio se muestran en un tiempo muy corto.
¿Cómo ejecuto strace correctamente para saber qué llamada al kernel está ocurriendo?
En mi aplicación Python, uso un subproceso separado psutilpara verificar si hay subprocesos con una CPU alta del sistema y luego cerrar sesión. Una vez que veo uno, uso la siguiente línea de comando para iniciar strace:
strace -tT -o ~/strace.log -p <PID of thread>
Iniciar sesión desde mi aplicación (se usa psutilbajo el 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
registro de seguimiento durante el mismo período en ese hilo ID 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 cómo strace registra cientos de entradas por segundo y luego hay un intervalo de 6 segundos sin nada. Pero no se muestra que ninguna llamada demore más de un par de milisegundos. Entonces, ¿cómo es que ese hilo mostró un tiempo de CPU del 100% del "sistema"?
Solía topconfirmar que psutilestá informando números correctos. Y estoy seguro de haber rastreado el hilo correcto porque el intervalo de 6 segundos corresponde exactamente al alto tiempo de CPU registrado por psutil.
También se agradece la ayuda con qué otras herramientas podría usar para determinar qué está causando este tiempo del kernel/sistema.
Entorno: - Python 3.4.3 (problema observado también en Python 2.7) - Kernel CentOS 7 3.10.0-229.1.2.el7.x86_64 (problema observado también en Ubuntu 12 LTS) - Máquina AMD de 64 núcleos