Table of Contents

Procesos en estado "D" (uninterruptible sleep) en ps y top

Un proceso en estado ininterrumpible (Estado D en herramientas como top y ps) se refiere a un proceso que se encuentra en una llamada de sistema (Una determinada función del núcleo) que no puede ser interrumpida por una señal. Veamos la diferencia entre llamadas al sistema que pueden ser interrumpidas y las que no.

Llamada al sistema interrumpible

La función I/O “read()” del núcleo puede ser usada como ejemplo de llamadas al sistema interrumpible. Se trata de una llamada de sistema que puede tardar mucho en terminar debido a que puede implicar giros de disco duro, cabezales, etc. Durante la mayor parte de este tiempo, el proceso estará durmiendo y bloqueado esperando a que el hardware responda.

Mientras el proceso está durmiendo en esa llamada al sistema que no termina de responder, puede recibir una señal asíncrona Unix (SIGINT o SIGTERM), y entonces la llamada al sistema termina de manera prematura enviando “EINTR” al espacio de usuario y permitiendo al proceso continuar trabajando.

Llamada de sistema no interrumpible / uninterrumpibles

Ejemplos del uso de este tipo de llamadas pueden verse en entornos de carpetas compartidas, por ejemplo NFS o SAMBA. Si los clientes implementan llamadas al sistema que no pueden ser interrumpidas debido a problemas de hardware, red, drivers, etc El proceso se quedará colgado.

Antiguamente, hasta el 2007 aproximadamente, cuando esto sucedía no había manera de matar el proceso, necesitando del apagado / reinicio del sistema. Desde el 2008 (Kernel 2.6.25), existe en el núcleo un nuevo estado “TASK_KILLABLE”. Un proceso en el estado TASK_KILLABLE todavía no puede ser interrumpido de manera habitual (es decir, no se puede forzar la llamada al sistema para que devuelva EINTR, que es el error que pueden devolver las llamadas de sistema interrumpibles). Sin embargo, los procesos en este estado pueden ser matados.

Esto significa que, por ejemplo, los procesos que hacen E/S sobre NFS pueden ser eliminados si entran en un estado de bloqueo “D”. No todas las llamadas al sistema implementan este estado, por lo que todavía es posible que se atasquen procesos no matables para algunas llamadas al sistema. Lo ideal sería usar siempre el estado TASK_KILLABLE y dejar el uso del estado TASK_UNINTERRUPTIBLE a operaciones que realmente lo necesiten.

Formas de averiguar qué está haciendo un proceso en estado no interrumpible

Encontrar procesos en estado durmiente puede deberse a interacciones con determinado hadware y su implementación de los drivers o tareas muy intensas con operaciones de entrada y salida (Almacenamiento y red mayormente). El que los procesos se queden bloqueados puede generar subidas de carga, picos de CPU, consumo de la pila de workers de servidores web disponibles, etc.

Como ya comentamos, el poder eliminar estos procesos mediante “kill -9” depende de como hayan sido implemetados, si el estado es TASK_KILLABLE se podrá solucionar el problema sin reiniciar.

Veamos un ejemplo, aquí tenemos unos procesos en python usados por Apache que están consumiendo cada vez más carga en el sistema. Se ejecuta ps y se descubren procesos en estado “D”. Para intentar averiguar qué pasa, podemos usar el campo “WCHAN” de ps y top para conocer el nombre de la función del kernel que atasca al proceso y así tener más información. 

ps -eo ppid,pid,user,stat,pcpu,comm,wchan | grep -i python
 
 PPID   PID   USER   STAT %CPU COMMAND         WCHAN
     1  26025 root   Ss    0.0 python-fpm      ep_poll
 26025  26032 www    D     0.1 python-fpm      samba_get_writer
 26025  26046 www    D     0.1 python-fpm      samba_get_writer
 30129  30131 www    Ds    0.0 python          samba_get_writer
 26025  30261 www    S     1.9 python-fpm      skb_wait_for_more_packets
 26025  30415 www    D     0.8 python-fpm      ntfs3g_get_writer
 26025  30417 www    R     2.4 python-fpm      -
 30850  30853 www    Ds    0.1 python          samba_get_writer
 31611  31613 www    Ds    0.2 python          samba_get_writer
 26025  31659 www    S     0.7 python-fpm      skb_wait_for_more_packets
 26025  31660 www    S     1.2 python-fpm      skb_wait_for_more_packets

Los procesos al parecer acceden a ficheros en una carpeta compartida mediante samba, por lo que parece que hay algún problema de entrada / salida con esa carpeta compartida. Esto podría ser desde algún mal funcionamiento del hardware de almacenamiento destino, hasta alguna actualización por parte del dueño de la carpeta compartida, ocasionando algún problema con el modulo del kernel encargado de interactuar con dicho punto de montaje.

La solución por tanto sería matar todos los procesos python y parar el propio apache. De esta manera se podía remontar la carpeta compartida samba sin que ningún proceso bloqueara el desmontado y ver qué pasa. Si cada vez que se monta el sistema no se tarda en producir problema, posiblemente haya algún problema, ya sea en el hardware o en el software (del lado cliente o servidor).

Como se ve el campo wchan puede ser muy útil, pero todavía es posible obtener más información sobre esos procesos usando las populares “Magic SysRq key” (“Linux Magic System Request Key Hacks”). “Magic SysRq” se refiere a un combo de teclas 'mágicas' que puede ser pulsadas obligando al núcleo a responderá, sin importar lo que esté haciendo (a menos que esté completamente bloqueado).

Para que el núcleo responda de la misma manera, pero sin usar complicadas combinaciones de teclas, se puede usar “/proc/sysrq-trigger”. Simplemente se le debe pasar la tecla por medio del comando echo de la siguiente manera.

Generar un volcado en logs de journal (dmesg, /var/log/messages) de todas las tareas en estado “sleeping uninterruptable”. 

echo w > /proc/sysrq-trigger

Documentación: https://www.kernel.org/doc/html/v4.11/admin-guide/sysrq.html

El volcado lógicamente genera mucha información. por lo tanto dependiendo del sistema habrá que purgar más o menos hasta encontrar la información referente a los procesos que realmente nos interesan. Pese a ello es una buena manera de poder indagar más en los procesos bloqueados.

Pequeño fragmento referido a la cpu7 de un volcado de tasks en estado durmiente. 

...

[Fri Dec  4 00:47:52 2008] cpu#7, 2299.812 MHz                                   
[Fri Dec  4 00:47:52 2008]   .nr_running                    : 0
[Fri Dec  4 00:47:52 2008]   .load                          : 0
[Fri Dec  4 00:47:52 2008]   .nr_switches                   : 19094974475
[Fri Dec  4 00:47:52 2008]   .nr_load_updates               : 6596891657
[Fri Dec  4 00:47:52 2008]   .nr_uninterruptible            : 2927454
[Fri Dec  4 00:47:52 2008]   .next_balance                  : 16820.377246
[Fri Dec  4 00:47:52 2008]   .curr->pid                     : 0
[Fri Dec  4 00:47:52 2008]   .clock                         : 50101940549.625396
[Fri Dec  4 00:47:52 2008]   .cpu_load[0]                   : 0
[Fri Dec  4 00:47:52 2008]   .cpu_load[1]                   : 0
[Fri Dec  4 00:47:52 2008]   .cpu_load[2]                   : 0
[Fri Dec  4 00:47:52 2008]   .cpu_load[3]                   : 0
[Fri Dec  4 00:47:52 2008]   .cpu_load[4]                   : 0
[Fri Dec  4 00:47:52 2008]   .yld_count                     : -270972343
[Fri Dec  4 00:47:52 2008]   .sched_count                   : -1772192948
[Fri Dec  4 00:47:52 2008]   .sched_goidle                  : 1544129975
[Fri Dec  4 00:47:52 2008]   .avg_idle                      : 1000000
[Fri Dec  4 00:47:52 2008]   .ttwu_count                    : -121656011
[Fri Dec  4 00:47:52 2008]   .ttwu_local                    : 1075977514
...
[Fri Dec  4 00:47:52 2008]task:mount.ntfs      state:D stack:    0 pid: 7302 ppid:     1 flags:0x00000080
[Fri Dec  4 00:47:52 2008]Call Trace:
[Fri Dec  4 00:47:52 2008] __schedule+0x292/0x830
[Fri Dec  4 00:47:52 2008] schedule+0x46/0xf0
[Fri Dec  4 00:47:52 2008] schedule_timeout+0x99/0x170
[Fri Dec  4 00:47:52 2008] ? __next_timer_interrupt+0x100/0x100
[Fri Dec  4 00:47:52 2008] io_schedule_timeout+0x4b/0x80
[Fri Dec  4 00:47:52 2008] balance_dirty_pages+0x32f/0xe80
[Fri Dec  4 00:47:52 2008] ? __mod_memcg_state.part.0+0x78/0xe0
[Fri Dec  4 00:47:52 2008] ? percpu_counter_add_batch+0x81/0xb0
[Fri Dec  4 00:47:52 2008] balance_dirty_pages_ratelimited+0x2f5/0x400
[Fri Dec  4 00:47:52 2008] generic_perform_write+0x149/0x1e0
[Fri Dec  4 00:47:52 2008] __generic_file_write_iter+0xf9/0x1d0
[Fri Dec  4 00:47:52 2008] blkdev_write_iter+0xd1/0x170
[Fri Dec  4 00:47:52 2008] new_sync_write+0x156/0x1f0
[Fri Dec  4 00:47:52 2008] vfs_write+0x1a9/0x210
[Fri Dec  4 00:47:52 2008] __x64_sys_pwrite64+0x8d/0xc0
[Fri Dec  4 00:47:52 2008] do_syscall_64+0x33/0x40
[Fri Dec  4 00:47:52 2008] entry_SYSCALL_64_after_hwframe+0x44/0xa9
...
[Fri Dec  4 00:47:52 2008] runnable tasks:
[Fri Dec  4 00:47:52 2008]             task   PID         tree-key  switches  prio     exec-runtime         sum-exec        sum-sleep
[Fri Dec  4 00:47:52 2008] ----------------------------------------------------------------------------------------------------------
[Fri Dec  4 00:47:52 2008]             init     1   6525642.219040 131207947   120   6525642.219040  49418257.774385 50047841297.896132 0 /autogroup-2
[Fri Dec  4 00:47:52 2008]          rcuos/4    12 97238421944.594713 673800802   120 97238421944.594713 108516167.623698 49972493437.748306 0 /
[Fri Dec  4 00:47:52 2008]       watchdog/7    57        -8.973971  12525291     0        -8.973971   2203792.889398         0.004279 0 /
[Fri Dec  4 00:47:52 2008]      migration/7    58         0.000000  71652010     0         0.000000   3881055.534062         0.003094 0 /
[Fri Dec  4 00:47:52 2008]      ksoftirqd/7    59 97238421890.094322 405247151   120 97238421890.094322 115596489.350976 49945444918.473422 0 /
[Fri Dec  4 00:47:52 2008]     kworker/7:0H    61       -13.048576         4   100       -13.048576         0.004743       110.149401 0 /
[Fri Dec  4 00:47:52 2008]  ext4-rsv-conver   195       485.299676         2   100       485.299676         0.219683         0.044722 0 /
[Fri Dec  4 00:47:52 2008]         ttm_swap   458      1896.346181         2   100      1896.346181         0.138267         0.084872 0 /
[Fri Dec  4 00:47:52 2008]           nfsiod   898      2383.163055         2   100      2383.163055         0.088797         0.089984 0 /
[Fri Dec  4 00:47:52 2008]        in:imklog  1005   1217184.131403      7532   120   1217184.131403      1589.600870 49065029336.482540 0 /autogroup-173
[Fri Dec  4 00:47:52 2008]   systemd-logind  1016     79311.466624    143728   120     79311.466624    609497.740566 50101161949.693662 0 /autogroup-175
[Fri Dec  4 00:47:52 2008]              atd  1171       267.398527     13922   120       267.398527      1633.880569 50101201628.925149 0 /autogroup-213
[Fri Dec  4 00:47:52 2008]            named  1228    192050.198544   2165573   120    192050.198544    551780.226811 50101171787.076117 0 /autogroup-223
[Fri Dec  4 00:47:52 2008]           mysqld  1332   8599835.976202 101417507   120   8599835.976202  10421504.651275 50086358021.272285 0 /autogroup-224
[Fri Dec  4 00:47:52 2008]           mysqld  1337   8599836.203155 101119171   120   8599836.203155  10268077.489687 50086237783.242699 0 /autogroup-224
[Fri Dec  4 00:47:52 2008]           mysqld  1340   8599836.379168 101325155   120   8599836.379168  10313235.075724 50086154963.913792 0 /autogroup-224
[Fri Dec  4 00:47:52 2008]           mysqld  1507   8599824.325708  10021432   120   8599824.325708   1125987.938967 50099306193.811183 0 /autogroup-224
[Fri Dec  4 00:47:52 2008]           mysqld  1548   8599822.387562      5559   120   8599822.387562      1528.427255  42761918.193222 0 /autogroup-224
[Fri Dec  4 00:47:52 2008]      authdaemond  1851     18975.669892    166995   120     18975.669892     30631.393708 50101239886.058278 0 /autogroup-277
[Fri Dec  4 00:47:52 2008]      authdaemond  1916     18975.140522    177128   120     18975.140522     37979.978701 50101464018.058859 0 /autogroup-277
[Fri Dec  4 00:47:52 2008]      authdaemond  1917     18975.683647    177187   120     18975.683647     38556.259320 50101459181.581841 0 /autogroup-277
[Fri Dec  4 00:47:52 2008]           master  2130   7286004.205570  99109527   120   7286004.205570  32477525.257812 50063597850.341904 0 /autogroup-291
[Fri Dec  4 00:47:52 2008]           celery  2553       324.890883        52   120       324.890883       127.946630       465.852688 0 /autogroup-229
[Fri Dec  4 00:47:52 2008]         beam.smp  4661       148.615230         2   120       148.615230         0.175959        36.279222 0 /autogroup-467
[Fri Dec  4 00:47:52 2008]         beam.smp  4670  95303162.853028       516   120  95303162.853028        84.644530 44331375442.342236 0 /autogroup-467

...