Uno de los Web developers de la organización me comentó que una consulta en una aplicación Web estaba demorando demasiado (muchos minutos). Era necesario analizar el consumo de memoria, disco y CPU en los servidores (particularmente el de base de datos) para determinar en qué estado se encontraban durante la ejecución de la misma. Se trata de una aplicación desarrollada por terceros, implementada utilizando Java (corriendo sobre un servidor Glassfish) y bases de datos MySQL.
Al verificar el estado del sistema y los procesos en el servidor de aplicación (Glassfish), no se detectó un consumo elevado de CPU, memoria, ni disco. En cambio, al monitorear el estado del servidor de bases de datos MySQL (utilizando la herramienta atop) se detectó un elevado consumo de CPU y lecturas a disco (correspondiente a una larga consulta SELECT, como demostraré más adelante).
MySQL utiliza un hilo de ejecución para cada conexión al motor de base de datos. Desde la consola de MySQL es posible listar los hilos en ejecución mediante la consulta SHOW PROCESSLIST:
mysql> show processlist; +-------+------------+----------------------------------+---------------+---------+------+--------------+-----------------------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +-------+------------+----------------------------------+---------------+---------+------+--------------+-----------------------------------------------------------------+ | 24631 | usr_basura | basura-appsrv.linuxito.com:36032 | data_16 | Sleep | 1589 | | NULL | | 24767 | root | it07.intranet.linuxito.com:1122 | db1_duplicado | Sleep | 10 | | NULL | | 24782 | usr_basura | basura-appsrv.linuxito.com:36219 | db1 | Query | 108 | Sending data | SELECT T.terrible_id, PRA.anio_publica, T.terrible, PUB.frut | | 24783 | usr_basura | basura-appsrv.linuxito.com:36221 | db1 | Sleep | 315 | | NULL | | 24784 | usr_basura | basura-appsrv.linuxito.com:36222 | db1 | Sleep | 315 | | NULL | | 24785 | usr_basura | basura-appsrv.linuxito.com:36223 | db1 | Sleep | 315 | | NULL | | 24786 | usr_basura | basura-appsrv.linuxito.com:36224 | db1 | Sleep | 315 | | NULL | | 24787 | usr_basura | basura-appsrv.linuxito.com:36225 | db1 | Sleep | 315 | | NULL | | 24788 | usr_basura | basura-appsrv.linuxito.com:36226 | db1 | Sleep | 315 | | NULL | | 24789 | usr_basura | basura-appsrv.linuxito.com:36227 | db1 | Sleep | 315 | | NULL | | 24790 | root | localhost | NULL | Query | 0 | NULL | show processlist | +-------+------------+----------------------------------+---------------+---------+------+--------------+-----------------------------------------------------------------+ 11 rows in set (0,00 sec)
Cada fila representa una conexión. Se observa que la aplicación Java en cuestión mantiene 8 conexiones a la base de datos "db1", desde el servidor Glassfish. Y sobre una de las conexiones (cuyo "Id" de hilo es "24782") se está ejecutando la consulta que provoca la demora en la respuesta desde el servidor Web Glassfish.
La consulta SHOW PROCESSLIST sólo muestra los primeros caracteres de la consulta en el campo "Info". Para ver la consulta completa, ejecutar SHOW FULL PROCESSLIST.
Es posible terminar conexiones utilizando el comando KILL especificando el "Id" de thread, por ejemplo:
mysql> kill 24782; Query OK, 0 rows affected (0,00 sec)
Se observa que la conexión en cuestión ha sido finalizada:
mysql> show processlist; +-------+------------+----------------------------------+---------------+---------+------+-------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +-------+------------+----------------------------------+---------------+---------+------+-------+------------------+ | 24631 | usr_basura | basura-appsrv.linuxito.com:36032 | data_16 | Sleep | 1736 | | NULL | | 24767 | root | it07.intranet.linuxito.com:1122 | db1_duplicado | Sleep | 17 | | NULL | | 24783 | usr_basura | basura-appsrv.linuxito.com:36221 | db1 | Sleep | 462 | | NULL | | 24784 | usr_basura | basura-appsrv.linuxito.com:36222 | db1 | Sleep | 462 | | NULL | | 24785 | usr_basura | basura-appsrv.linuxito.com:36223 | db1 | Sleep | 462 | | NULL | | 24786 | usr_basura | basura-appsrv.linuxito.com:36224 | db1 | Sleep | 462 | | NULL | | 24787 | usr_basura | basura-appsrv.linuxito.com:36225 | db1 | Sleep | 462 | | NULL | | 24788 | usr_basura | basura-appsrv.linuxito.com:36226 | db1 | Sleep | 462 | | NULL | | 24789 | usr_basura | basura-appsrv.linuxito.com:36227 | db1 | Sleep | 462 | | NULL | | 24790 | root | localhost | NULL | Query | 0 | NULL | show processlist | +-------+------------+----------------------------------+---------------+---------+------+-------+------------------+ 10 rows in set (0,01 sec)
Lógicamente, este comando, además de finalizar la consulta, cierra la conexión con el cliente. Por ende se provocan errores en el servidor de aplicación:
bostanet.framework.error.CException: org.hibernate.exception.JDBCConnectionException: could not prepare statement
Por esta razón, probablemente será necesario reiniciar la aplicación (en este caso reiniciar el servidor Glassfish). Esto implica que el comando KILL sólo debe ser utilizado como una medida drástica para recuperar un servidor de bases de datos comprometido o sobrecargado. Por otro lado, si se ejecuta el comando KILL a una conexión en la cual se está ejecutando una consulta REPAIR_TABLE u OPTIMIZE_TABLE sobre una tabla MyISAM, se provocará la corrupción o destrucción de dicha tabla.
Cuando ejecuté show full processlist (antes de haber matado el hilo):
mysql> show full processlist;
Pude comprobar que la consulta ejecutada era la siguiente (para mantener la confidencialidad de la aplicación modifiqué los nombres de todas las bases de datos, tablas, campos y valores):
SELECT T.terrible_id, PRA.anio_publica, T.terrible, PUB.fruta, PRA.revista, PRA.biblioteca,T.usuario_banana, (SUM( (IF(bosta IS NULL, 0, bosta) - IF(PT2.es_ignorado IS NULL, 0, PT2.es_ignorado) )* (IF(bosta IS NULL, 0, bosta) - IF(PT1.es_ignorado IS NULL, 0, PT1.es_ignorado) )* (IF(bosta IS NULL, 0, bosta) - IF(PT.es_ignorado IS NULL, 0, PT.es_ignorado)) ) > 0) AS es_bosta, PT.es_ignorado, GROUP_CONCAT(DISTINCT CONCAT(PER.username, ', ', PER.nn) SEPARATOR '; ') AS ingresado_por, GROUP_CONCAT(DISTINCT PA.vendehumo ORDER BY PA.id) AS lalala, MAX(T.is_kill) AS is_kill, T.fecha_fin_campo as fecha_fin_campo FROM ( SELECT P.id AS terrible_id, P.terrible, P.persona_id, NONSENSE.es_bosta AS bosta, 0 is_kill, NONSENSE.dos_imposible_id AS bosta_id, P.fecha_fin_campo, P.usuario_banana FROM ESCALABILIDAD_JAJAJA P LEFT JOIN ( basura_duplicado.DUPLICADO_INUTIL_SEL NONSENSE JOIN ESCALABILIDAD_JAJAJA P_INUTIL ON (NONSENSE.dos_imposible_id = P_INUTIL.id AND P_INUTIL.fecha_fin_campo IS NULL) ) ON (NONSENSE.es_bosta = 1 AND NONSENSE.tipo_dos_id = 1 AND NONSENSE.dos_menor_id = P.id) WHERE P.id IN (782534,355363,523563,624563,778344,136345,124581,246123,392346,246353,722344,126788,7235710,724111,672733,989996,557240,781451,161235,7823471) AND P.tipo_origen_id <> 3 UNION SELECT PC.id AS terrible_id, PC.terrible, P.persona_id, NONSENSE.es_bosta AS bosta, 1 is_kill, NONSENSE.dos_imposible_id AS bosta_id, PC.fecha_fin_campo, PC.usuario_banana FROM ESCALABILIDAD_JAJAJA P JOIN destruccion C ON (C.terrible_id = P.id) JOIN ESCALABILIDAD_JAJAJA PC ON (PC.id = C.kill_id AND PC.fecha_fin_campo IS NULL) LEFT JOIN ( basura_duplicado.DUPLICADO_INUTIL_SEL NONSENSE) ON (NONSENSE.es_bosta = 1 AND NONSENSE.tipo_dos_id = 1 AND NONSENSE.dos_menor_id = P.id) LEFT JOIN destruccion C_INUTIL ON (NONSENSE.dos_imposible_id = C_INUTIL.terrible_id AND C_INUTIL.kill_id = C.kill_id) WHERE C_INUTIL.id IS NULL AND PC.id IN (782534,355363,523563,624563,778344,136345,124581,246123,392346,246353,722344,126788,7235710,724111,672733,989996,557240,781451,161235,7823471) AND P.fecha_fin_campo IS NULL UNION SELECT P.id AS terrible_id, P.terrible, P.persona_id, tablitap.es_bosta AS bosta, 0 is_kill, tablitap.dos_menor_id AS bosta_id, P.fecha_fin_campo, P.usuario_banana FROM ESCALABILIDAD_JAJAJA P LEFT JOIN ( basura_duplicado.DUPLICADO_INUTIL_SEL tablitap JOIN ESCALABILIDAD_JAJAJA P_INUTIL ON (tablitap.dos_menor_id = P_INUTIL.id AND P_INUTIL.fecha_fin_campo IS NULL) ) ON (tablitap.es_bosta = 1 AND tablitap.tipo_dos_id = 1 AND tablitap.dos_imposible_id = P.id) WHERE P.id IN (782534,355363,523563,624563,778344,136345,124581,246123,392346,246353,722344,126788,7235710,724111,672733,989996,557240,781451,161235,7823471) AND P.tipo_origen_id <> 3 UNION SELECT PC.id AS terrible_id, PC.terrible, P.persona_id, tablitap.es_bosta AS bosta, 1 is_kill, tablitap.dos_menor_id AS bosta_id, PC.fecha_fin_campo, PC.usuario_banana FROM ESCALABILIDAD_JAJAJA P JOIN destruccion C ON (C.terrible_id = P.id) JOIN ESCALABILIDAD_JAJAJA PC ON (PC.id = C.kill_id AND PC.fecha_fin_campo IS NULL) LEFT JOIN ( basura_duplicado.DUPLICADO_INUTIL_SEL tablitap ) ON (tablitap.es_bosta = 1 AND tablitap.tipo_dos_id = 1 AND tablitap.dos_imposible_id = P.id) LEFT JOIN destruccion C_INUTIL ON (tablitap.dos_menor_id = C_INUTIL.terrible_id AND C_INUTIL.kill_id = C.kill_id) WHERE C_INUTIL.id IS NULL AND PC.id IN (782534,355363,523563,624563,778344,136345,124581,246123,392346,246353,722344,126788,7235710,724111,672733,989996,557240,781451,161235,7823471) AND P.fecha_fin_campo IS NULL ) AS T LEFT JOIN ESCALABILIDAD_JAJAJA_CRAP PT ON (PT.terrible_id = T.terrible_id AND PT.DoSyourDB_id = 823) LEFT JOIN ESCALABILIDAD_JAJAJA_CRAP PT1 ON (PT1.terrible_id = T.bosta_id AND PT1.DoSyourDB_id = 823) LEFT JOIN ( destruccion C JOIN ESCALABILIDAD_JAJAJA P_COMP ON (P_COMP.id = C.kill_id AND P_COMP.fecha_fin_campo IS NULL ) JOIN ESCALABILIDAD_JAJAJA_CRAP PT2 ON ( PT2.terrible_id = C.kill_id AND PT2.DoSyourDB_id = 823 AND PT2.es_ignorado = 1 ) )ON (C.terrible_id = T.bosta_id) LEFT JOIN PARTICIPACION_ESCALABILIDAD_JAJAJA PP ON (PP.terrible_id = T.terrible_id) LEFT JOIN PARTICIPACION PA ON (PA.id = PP.vendehumo_id) JOIN PR_ARTICULO PRA ON (T.terrible_id = PRA.terrible_id) LEFT JOIN PERSONA PER ON (PER.id = T.persona_id) LEFT JOIN PUBLICACION PUB ON (PUB.id = PRA.fruta_id) LEFT JOIN ESCALABILIDAD_JAJAJA P_INUTIL ON (T.bosta_id = P_INUTIL.id AND P_INUTIL.fecha_fin_campo IS NOT NULL) WHERE P_INUTIL.id IS NULL GROUP BY T.terrible_id ORDER BY terrible ASC
¡¡¡En total 3 UNION y 23 JOIN!!! ¡Pero anda! (Nos decía un profesor en la Universidad cuando nos explicaba "Calidad de Software", burlándose de aquellos programas carentes de escalabilidad, eficiencia, y otras calidades.)
Cuando alertamos sobre este inconveniente, la respuesta de los responsables de esta aplicación fue: "Necesitan discos más rápidos". ¡No! Lo que necesitamos es que optimicen sus tablas y consultas SQL.
Estos son los developers que bastardean la profesión, y estas son las cosas con las que tiene que lidiar un sysadmin en el día a día.
A modo de catarsis, y para ponerle un poco de humor al asunto, decidimos formatear e imprimir en nuestra oficina, junto al calendario, "La Consultita" que nos volteó uno de los servidores MySQL en producción. Para la posteridad jeje.
Utilizamos 3 hojas tamaño A4.
Referencias
