Deuda técnica, parte 3: refactoricé una vista de 1.000 líneas… y debajo había una consulta escaneando toda la tabla de logs
ContenidoContents
Tercera y última parte de la serie de deuda técnica en mi plugin de Jitsi para Moodle. En la parte 1 troceé dos “archivos-dios”; en la parte 2 desmonté la función de 924 líneas de la videollamada. Quedaba el último monstruo: view.php, la página que ve el alumno o el profesor al entrar en la actividad. 971 líneas que lo mezclaban todo.
La refactoricé con la receta de siempre. Pero esta vez el refactor en sí es lo de menos —es el mismo patrón de las partes anteriores—. Lo interesante fue lo que apareció al levantar las alfombras: una consulta escaneando la tabla de logs de todo el sitio, un caché que la tapaba, un N+1, un bug que dejaba grabar y emitir a la vez, y un par de “cápsulas del tiempo” enterradas en el código.
El refactor, en cuatro fases (lo rápido)
view.php era el clásico fat controller. Lo partí en cuatro pasos, validando cada uno en un Moodle real:
- V1 — Limpieza: SQL parametrizado, fuera código muerto, y unificar el
$context(se reasignaba a mitad de archivo, evaluando un permiso en el contexto equivocado). - V2 — JavaScript a módulos: las ~500 líneas de JS incrustado en PHP → cuatro módulos ES6 con su linter. (El patrón ya lo conté en la parte 2: el PHP deja de fabricar comportamiento y pasa a entregar datos.)
- V3 — HTML a plantillas: el HTML disperso → tres plantillas Mustache. El PHP decide, la plantilla pinta.
- V4 — Sacar el CRUD de la vista: la lógica que mutaba la base de datos se movió a una clase testeable, dejando controladores delgados.
Resultado: de 971 a 455 líneas (−53%) y cero JavaScript incrustado. Hasta aquí, lo esperable. Ahora lo bueno.
El caché que escondía una consulta cara
Había un contador —“minutos totales del usuario”— que se mostraba estático: solo cambiaba al recargar. Quise refrescarlo cada 15 segundos, y al abrir la función que lo calcula me encontré con un caché de 2 minutos. ¿Por qué cachear algo así?
Lo puso un commit de septiembre de 2024, “Add caching to getminutes functions”. No era capricho: la consulta contaba filas en logstore_standard_log —la tabla de logs de todo el Moodle— y se llamaba en bucle. El caché estaba ahí tapando el problema, no resolviéndolo. Y esa es la pista de oro: un caché casi siempre esconde una consulta cara. Antes de quitarlo, hay que entender qué oculta.
21× más rápido con una columna en el WHERE
Saqué el EXPLAIN ANALYZE y ahí estaba, en negro sobre blanco:
1ANTES — SELECT * ... WHERE userid AND contextinstanceid AND action
2Seq Scan on mdl_logstore_standard_log
3 Rows Removed by Filter: 14803 ← escanea TODA la tabla
4 Buffers: shared hit=444
5Execution Time: 5.913 ms
Dos cambios: COUNT(*) en vez de traer todas las filas, y —la clave— añadir contextlevel al WHERE. Con esa columna, la consulta usa un índice compuesto que ya existía y que antes no se aprovechaba:
1DESPUÉS — SELECT COUNT(*) ... WHERE userid AND contextlevel AND contextinstanceid AND action
2Index Scan using mdl_logsstanlog_useconconcr_ix
3 Buffers: shared hit=31
4Execution Time: 0.274 ms
5,913 ms → 0,274 ms (~21× más rápido), 444 → 31 buffers. Y eso con solo ~15.000 filas de log en local; el Seq Scan escala con el total de la tabla (en producción, millones), mientras que el Index Scan solo con las filas de ese usuario. El índice ya estaba; solo le faltaba que la consulta le diera el contextlevel.
Con la consulta ya barata, el contador en vivo se refresca de verdad cada 15 segundos sin caché y sin penalización.
El N+1 que se multiplicaba con el anterior
De paso, el informe de asistencia llamaba a esa función de minutos dos veces por cada usuario conectado. Con 30 alumnos, 60 consultas. El clásico N+1. Lo cambié por dos consultas agregadas con GROUP BY:
1ANTES 60 consultas · 36,55 ms
2DESPUÉS 2 consultas · 5,02 ms → 30× menos consultas, 7,3× más rápido
Y ojo: el factor real en producción es mayor, porque cada una de esas 60 consultas era además el Seq Scan de antes. Los dos arreglos se multiplican.
El bug de los dos botones
Un regalo que no buscaba. Probando en vivo: al pulsar Grabar, durante los segundos que tarda Jitsi en confirmar, el botón de Emitir en directo seguía pulsable —y al revés—. Se podían lanzar las dos a la vez. La causa: cada manejador se deshabilitaba solo a sí mismo.
1// ANTES: solo se apaga su propio botón
2btn.disabled = true;
3api.startRecording({mode: 'file'}); // streamBtn sigue pulsable
4
5// DESPUÉS: se apagan AMBOS hasta confirmar, con red de seguridad
6setControlsDisabled(true);
7armControlsWatchdog(); // re-habilita a los 20s si nada arranca
8api.startRecording({mode: 'file'});
Llevaba ahí tiempo; salió al mirar de cerca. Y de paso arreglé un caso preexistente en que el botón de streaming se quedaba bloqueado tras un error.
Cápsulas del tiempo
Lo que más me ha gustado de refactorizar una vista tan vieja es la arqueología. Encuentras código que es un mensaje del pasado:
- El
$statefantasma. Hay un parámetro,$state, queview.phpparsea… pero que ningún archivo del plugin genera. Viene de fuera: lo construye la app móvil de Moodle. Lo introdujo un commit de hace años titulado, literalmente, “ionic 5 compatibility”. Parte de lo que desempaqueta es código muerto que nunca se usa. Decidí no tocarlo: romperlo significaría romper a los usuarios de la app. Una cápsula del tiempo que sigues respetando porque no sabes del todo quién depende de ella. - Las ramas de Moodle 3.11. El plugin requiere Moodle 4.5+, pero quedaban
if ($CFG->branch <= 311)que no se ejecutan nunca. Fuera. (El toggle Bootstrap 4 vs 5 sí se queda: ese aún distingue 4.5 de 5.x.)
Y los sustos del entorno
No todo es código del plugin; el terreno también muerde:
- ESLint me rechazó el push tres veces. El hook de pre-push corre ESLint con
--max-warnings 0, más estricto que el del día a día.camelcase(un argumento de web service que essnake_casepor definición),promise/no-nesting(aasync/await),no-alert… Moraleja: reproduce el lint del CI en local antes de pushear, o acumulas ciclos de push fallido. - Casi declaro un bug que no existía. Validando en vivo, vi la tabla de presencia vacía y pensé “está roto”. No: esa tabla se autolimpia a los 150 segundos y yo, encima, estaba mirando una actividad distinta de la que probaba el usuario. No confundas un estado transitorio con una avería —y asegúrate de mirar el mismo objeto—.
Lo que me llevo de esta parte
Las partes 1 y 2 fueron sobre estructura. Esta ha sido sobre lo que la estructura escondía:
- Mide antes de tocar el rendimiento.
EXPLAIN ANALYZEconvirtió un “esto parece pesado” en un cambio concreto: una columna en elWHERE, 21× más rápido. - Un caché casi siempre tapa una consulta cara. Entiende qué oculta antes de quitarlo; a veces, al entenderlo, dejas de necesitarlo.
- Refactorizar código viejo es arqueología. Destapa bugs (los botones), cápsulas del tiempo (el
$statede ionic) y decisiones olvidadas. Léelo con respeto: no todo lo raro es un error, a veces es alguien resolviendo un problema que tú ya no ves.
Con esto, el gran refactor del plugin —external.php, lib.php, la videollamada y view.php— queda cerrado. Todo en dev, validado en un Moodle real a cada paso, listo para subir a master cuando termine de probarlo a fondo. Tres archivos-dios menos, un puñado de bugs y cuellos de botella corregidos, y un plugin por fin preparado para el Moodle que viene.
Epílogo en la parte 4: creía que había terminado… y quedaba el último CRUD que recargaba la página entera.