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 ...