Depuración básica

01 · El oficio

Depurar es un método, no una corazonada

El error más caro al depurar es cambiar cosas al azar hasta que «anda»: se pierde tiempo, se agregan defectos nuevos y, cuando por fin deja de fallar, nadie sabe por qué, de modo que probablemente vuelva. Depurar bien es aplicar un método científico en miniatura, un ciclo que se repite hasta explicar el síntoma:

1. Reproducir. Un error que no se puede provocar a voluntad no se puede estudiar. Hay que encontrar las condiciones que lo disparan (una secuencia de entradas, una carga, una temperatura, un tiempo de funcionamiento) y, si es posible, automatizarlas. Un error esporádico se vuelve tratable cuando se logra que ocurra una de cada diez veces en lugar de una de cada diez mil.
2. Observar sin perturbar. Antes de teorizar, reunir hechos: qué pasa exactamente, cuándo, con qué datos. Una observación precisa vale más que una teoría brillante.
3. Formular una hipótesis concreta y refutable: «la interrupción del UART se pierde cuando el temporizador la retrasa más de 300 µs», no «algo anda mal con las interrupciones».
4. Diseñar un experimento que pueda refutarla, cambiando una sola cosa por vez. Si el resultado la contradice, se descarta; si la confirma, se intenta refutarla de otra manera antes de darla por cierta.
5. Corregir la causa, no el síntoma, y comprobar que el síntoma desaparece y que no apareció otro. Anotar lo que se aprendió (y agregar una prueba que habría detectado el error).

Hay una dificultad propia de los sistemas embebidos que condiciona la elección de las herramientas: observar cambia el sistema. Agregar una línea para imprimir un valor modifica el tiempo de ejecución, el uso de la pila y la distribución de la memoria. En un programa de tiempo real, eso puede hacer desaparecer el error (un error que se esfuma cuando se lo mira se llama, con humor, heisenbug, por el principio de Heisenberg) o crear uno nuevo. Por eso las técnicas de este tema se ordenan por su intrusividad, y lo habitual es empezar por las menos intrusivas:

02 · El instrumento más barato

LEDs: lo más simple que funciona

Un LED es la salida más barata de un sistema, y a veces la única disponible: no hace falta una UART configurada ni un conector. Sirve para tres cosas, con un grado creciente de información:

• Latido (heartbeat): un LED que cambia de estado cada medio segundo desde el programa principal. Si parpadea, el bucle principal sigue corriendo; si se congela, el programa se colgó. Es la señal de vida más elemental, y la primera que conviene tener en cualquier proyecto.
• Estado: con varios LED, mostrar en qué estado está el sistema (esperando, midiendo, transmitiendo, error). Útil para seguir el flujo a simple vista.
• Código de parpadeos: un número de destellos seguido de una pausa larga informa un código de error con un solo LED: tres destellos y pausa significa «error 3». Un técnico en el campo sin ninguna herramienta puede leerlo.

/* Latido: se llama en cada vuelta del bucle principal. Si el LED se congela, el bucle se colgó. */
void latido_tick(void) {
    static uint32_t t0;
    if ((int32_t)(ahora_ms() - t0) >= 500) { t0 = ahora_ms(); led_alternar(); }
}

/* Código de parpadeos sin bloquear: N destellos de 200 ms y una pausa de 1,5 s, que se repite */
static uint8_t codigo_pendiente, destello;  static uint32_t t_led;  static bool led_encendido;

void falla_codigo(uint8_t n) { codigo_pendiente = n;  destello = 0;  led_encendido = false;  t_led = ahora_ms(); }

void falla_tick(void) {                                       /* se llama desde el bucle principal, sin esperas */
    if (codigo_pendiente == 0) return;
    uint32_t espera = led_encendido ? 200 : (destello < codigo_pendiente ? 200 : 1500);
    if ((int32_t)(ahora_ms() - t_led) < (int32_t)espera) return;
    t_led = ahora_ms();
    if (led_encendido)                         { led_apagar();  led_encendido = false;  destello++; }
    else if (destello < codigo_pendiente)       { led_encender(); led_encendido = true; }
    else                                       { destello = 0; }                       /* terminó la pausa: empezar otra vez */
}

Dos advertencias sobre el latido. Primera: dónde se alterna importa. Si el LED lo cambia la interrupción de un temporizador, seguirá parpadeando aunque el programa principal esté colgado, y el latido mentirá (es el mismo error de alimentar un watchdog desde una ISR, tema 38). Se alterna en el camino que se quiere vigilar. Segunda: un LED consume (varios mA, tema 33) y en un equipo a batería no puede quedar encendido, ni parpadeando seguido, en el producto final: se deshabilita con una macro de compilación o se lo reduce a destellos cortos y espaciados.

03 · Mirar el tiempo

Pines de prueba y analizador lógico

La técnica más valiosa de la depuración sin depurador es la de los pines de prueba: se elige un pin de salida libre, se lo pone en alto al entrar a la rutina o a la sección que interesa y en bajo al salir, y se observa con un analizador lógico (o un osciloscopio). Es la técnica ideal para los problemas de tiempo porque casi no cambia lo que mide: cambiar un pin cuesta una escritura a un registro, uno o dos ciclos de reloj, tiempo despreciable frente a una ISR de decenas de microsegundos. Con un pin se mide, con precisión de microsegundos:

• La duración de una ISR o de una función: el ancho del pulso (tema 18).
• La latencia de una interrupción: la distancia entre el evento externo (otro pin) y el comienzo del pulso.
• El orden de los eventos: con varios pines (uno por tarea, por ISR, por sección crítica), el analizador muestra una línea de tiempo con todo en paralelo, y de un vistazo se ven interrupciones que se pisan, tareas que no corren o secciones críticas demasiado largas (tema 16).
• El estado de una máquina de estados: con tres o cuatro pines se codifica el número de estado en binario, y el analizador lo muestra como un bus (tema 24).

/* Pines de prueba en un puerto de salida: una sola escritura atómica (STM32: BSRR sube con los bits bajos y baja con los altos) */
#define DBG_ALTO(n)  (GPIOB->BSRR = (1u << (n)))
#define DBG_BAJO(n)  (GPIOB->BSRR = (1u << ((n) + 16u)))

#define DBG_ISR_TIM    0         /* PB0: dura lo que dura la ISR del temporizador */
#define DBG_SENSOR     1         /* PB1: dura lo que dura la lectura del sensor */
#define DBG_CRITICA    2         /* PB2: dura lo que están deshabilitadas las interrupciones */
#define DBG_ERROR      3         /* PB3: un pulso cada vez que se detecta una condición de error */

void TIM2_IRQHandler(void) {
    DBG_ALTO(DBG_ISR_TIM);
    borrar_bandera_tim2();
    atender_temporizador();
    DBG_BAJO(DBG_ISR_TIM);
}
/* Con el analizador: el ancho del pulso de PB0 es la duración de la ISR; la separación entre pulsos, su período; si falta un pulso, se perdió una interrupción. */

La Parte 1 del programa de Python analiza la captura de un analizador lógico de un pin que marca la ISR de un temporizador de 1 ms (60 interrupciones). Con solo las marcas de tiempo de los flancos se obtienen cosas que a ojo no se ven: un período mediano de 1000,5 µs, una duración mediana de la ISR de 120,1 µs (una carga del 12,0 %), y dos anomalías escondidas entre las 60 ejecuciones: la ISR número 45 duró 900 µs, siete veces más que las demás (y es un candidato a ser investigado: ¿qué hizo diferente?), y la ISR número 37 empezó con 399 µs de retraso (los períodos de 1400 y de 600 µs alrededor de ella lo delatan), algo propio de una sección crítica larga que mantuvo deshabilitadas las interrupciones. Ninguna de las dos cosas se vería con un printf, que además habría causado parte del problema.

Una regla para elegir la frecuencia de muestreo de un analizador: debe ser bastante mayor que la señal más rápida que interesa. Para medir el ancho de un pulso con un error del 1 %, el intervalo entre muestras debe ser el 1 % del ancho: para la ISR de 120 µs, 1,2 µs o menos (cerca de 1 MS/s). Para ver un pulso espurio (glitch) de 100 ns, hacen falta decenas de MS/s. Con una frecuencia de muestreo baja, un pulso corto simplemente no aparece, y uno mira una captura limpia de un sistema que tiene un problema (el mismo efecto de muestreo que vimos en el tema 36).

Y una recomendación para el diseño del hardware, que se agradece al depurar: dejar puntos de prueba en la placa (un pin libre del microcontrolador, aunque sea con un conector sin poblar, y accesos a la masa, la alimentación, el reset y las líneas de comunicación) y, siempre que se pueda, un conector para el depurador (tema 45). Una placa sin ninguno de ellos obliga a soldar cables sobre los pines de un componente de paso fino, y cada cable es una fuente de errores nuevos.

04 · Hablarle al programador

La consola por la UART

Imprimir texto por una UART conectada a una PC (con un adaptador USB-serie) es la técnica más familiar, y por eso la más usada y la más abusada. Tiene un valor real: permite ver valores, mensajes y secuencias en un formato legible. Y un costo que se ignora por costumbre: enviar los bytes lleva tiempo, y el programa suele esperar a que salgan. La Parte 2 del programa calcula cuánto tarda una línea, a 10 bits por byte (inicio, 8 de datos y parada):

Una línea de 40 caracteres a 115 200 baudios bloquea 3,5 milisegundos. Dentro de una interrupción de 1 ms, eso significa que la ISR dura más que su período y se pierden interrupciones; en un bucle de control de 5 ms, que la mitad del tiempo se va en imprimir. Imprimir cambia el sistema que se quiere observar, y la medición, además de lenta, es engañosa. Además, printf con coma flotante consume mucha pila y flash (temas 29 y 32), y puede ser la causa de un desborde de pila que no existía antes de agregarlo.

La solución es el registro diferido: el programa no espera a la UART. Escribe el mensaje en un buffer circular en RAM (unos microsegundos) y es la interrupción de transmisión de la UART, o el DMA, la que va sacando los bytes en segundo plano. El costo en el camino crítico pasa de milisegundos a microsegundos:

/* Registro diferido: el mensaje va a un buffer; la interrupción de la UART lo envía mientras el programa sigue */
#define LOG_TAM  512u                                   /* potencia de dos */
static uint8_t           log_buf[LOG_TAM];
static volatile uint16_t log_cab, log_col;              /* cabeza: donde escribe el programa; cola: de donde saca la UART */
static volatile uint16_t log_perdidos;

void log_bytes(const char *s, size_t n) {
    uint32_t pm = __get_PRIMASK();  __disable_irq();    /* varios contextos pueden registrar: sección crítica corta (tema 16) */
    for (size_t i = 0; i < n; i++) {
        if ((uint16_t)(log_cab - log_col) == LOG_TAM) { log_perdidos++; break; }   /* buffer lleno: se descarta y se CUENTA */
        log_buf[log_cab++ & (LOG_TAM - 1)] = (uint8_t)s[i];
    }
    USART1->CR1 |= USART_CR1_TXEIE;                     /* habilitar la interrupción de transmisor vacío: arranca el envío */
    __set_PRIMASK(pm);
}

void USART1_IRQHandler(void) {
    if (USART1->SR & USART_SR_TXE) {
        if (log_col != log_cab) USART1->DR = log_buf[log_col++ & (LOG_TAM - 1)];
        else                    USART1->CR1 &= ~USART_CR1_TXEIE;   /* no queda nada: se apaga la interrupción */
    }
}

/* Niveles de registro, con filtrado en compilación: lo que no se usa no cuesta ni una instrucción */
#define LOG_ERROR 1
#define LOG_INFO  2
#define LOG_DEBUG 3
#ifndef LOG_NIVEL
#define LOG_NIVEL LOG_INFO
#endif
#define LOG(nivel, ...)  do { if ((nivel) <= LOG_NIVEL) log_formato(__VA_ARGS__); } while (0)    /* log_formato usa snprintf y log_bytes */

Tres precauciones. El formateo (snprintf) no se hace en una interrupción: es lento y usa mucha pila; las ISR registran un evento (apartado siguiente), no texto. El buffer tiene un tamaño calculado, y una política de desborde: a 115 200 baudios el canal solo admite 11 520 B/s, es decir 288 mensajes de 40 caracteres por segundo, y una ráfaga de 20 mensajes de 40 caracteres generados en 1 ms (800 B) tarda 69 ms en salir y necesita un buffer de al menos 789 bytes; si no cabe, se descarta y se cuenta (log_perdidos) en vez de bloquear. Y el registro se deshabilita en el producto, con el nivel de compilación, porque mantiene la UART activa (tema 35), ocupa flash con los textos (tema 32) y puede filtrar información sensible (tema 43).

Existen alternativas que no pasan por una UART común, y que el tema 45 retoma con el depurador conectado: la salida ITM/SWO de los Cortex-M3/M4 y la RTT de Segger, que escriben en un buffer de RAM que el depurador lee sin detener el programa, con un costo de microsegundos.

05 · La caja negra de la depuración

El registro de eventos en RAM

Para los errores que ocurren de vez en cuando y que ningún instrumento está mirando en ese momento, la técnica más poderosa es un registro de eventos (trace) en RAM: un buffer circular donde el programa anota, en puntos clave, qué pasó y cuándo, con un costo de decenas de ciclos. Cuando el error ocurre (un cuelgue, un valor imposible, una aserción que falla), el contenido del buffer cuenta la historia inmediatamente anterior, como la caja negra de un avión (tema 37). No guarda texto, sino registros compactos: un instante, un identificador del evento y un argumento.

typedef struct { uint32_t t; uint16_t id; uint16_t arg; } EventoTraza;      /* 8 bytes */
#define N_TRAZA 256u                                                       /* potencia de dos: 2 KB */

static EventoTraza traza[N_TRAZA] __attribute__((section(".noinit")));     /* sobrevive a un reinicio (tema 29) */
static volatile uint32_t traza_cab;

void traza_iniciar(void) {                                                 /* contador de ciclos del núcleo (Cortex-M3/M4) */
    CoreDebug->DEMCR |= CoreDebug_DEMCR_TRCENA_Msk;
    DWT->CTRL        |= DWT_CTRL_CYCCNTENA_Msk;
}

static inline void evt(uint16_t id, uint16_t arg) {                        /* se puede llamar desde cualquier contexto, ISR incluidas */
    uint32_t pm = __get_PRIMASK();  __disable_irq();
    EventoTraza *e = &traza[traza_cab++ & (N_TRAZA - 1)];
    e->t = DWT->CYCCNT;  e->id = id;  e->arg = arg;                       /* tres escrituras: unos 30 ciclos en total */
    __set_PRIMASK(pm);
}

/* Los identificadores se definen una sola vez (una macro de tabla, tema 32) y se traducen a texto en la PC, no en el equipo */
#define EVENTOS(X)  X(EV_ISR_TIM, 1)  X(EV_SENSOR_INICIO, 2)  X(EV_SENSOR_FIN, 3)  X(EV_COLA_LLENA, 7)  X(EV_ESTADO, 8)

/* Uso */
void TIM2_IRQHandler(void)  { evt(EV_ISR_TIM, 0);  /* ... */ }
void sensor_leer(void)      { evt(EV_SENSOR_INICIO, 0);  /* ... */  evt(EV_SENSOR_FIN, valor); }
void maquina_cambiar(uint8_t nuevo) { evt(EV_ESTADO, nuevo);  /* ... */ }

/* Tras un cuelgue o una aserción (tema 39): volcar el buffer por la UART o leerlo con el depurador, de más viejo a más nuevo */

La Parte 3 del programa simula un sistema que genera 2000 eventos y se cuelga en el último, con un buffer de 256 entradas de 8 bytes (2 KB en total). Después del cuelgue se conservan los últimos 256 eventos, del número 1744 al 1999, con las marcas de tiempo crecientes, y cubren los últimos 58,1 ms de funcionamiento; los cinco últimos antes del cuelgue son los que permiten ver qué rutinas habían corrido. El costo de registrar cada uno es del orden de 0,62 µs (con un supuesto de 30 ciclos a 48 MHz), contra los 3472 µs de imprimir una línea de 40 caracteres a 115 200 baudios: unas 5556 veces menos. Es la diferencia entre poder instrumentar el interior de una ISR y no poder.

Algunas decisiones de diseño: la marca de tiempo viene de un contador libre de alta resolución (el contador de ciclos DWT->CYCCNT de los Cortex-M3 y M4, que no existe en los M0; en ese caso, un temporizador de hardware); el tamaño se elige para cubrir la ventana que interesa (a 5000 eventos por segundo, 512 entradas de 8 bytes, 4 KB, cubren 102 ms); el registro se pone en la RAM sin inicializar para que un reinicio no lo borre y se pueda leer tras un fallo; y se vuelca por la UART (en un momento tranquilo o ante una falla), con el depurador, o se lo incorpora a la telemetría (tema 37). Y los eventos no tienen que ser muchos: unos pocos puntos bien elegidos (entrada y salida de las ISR, cambios de estado, errores) valen más que mil eventos sin criterio.

06 · Antes de culpar al software

Los instrumentos y lo primero que se revisa

Una gran parte de los errores que parecen de software son de hardware: una alimentación que se hunde, una masa floja, un reloj que no arrancó, un pin mal cableado. Antes de mirar el código, conviene revisar lo básico, en este orden, porque es lo más barato de comprobar y lo más frecuente:

Un truco útil para decidir si un problema es de software o de hardware: un programa mínimo. Se escribe (o se toma de los ejemplos del fabricante) un programa de diez líneas que haga solo lo imprescindible con el periférico sospechoso: parpadear un LED, enviar un byte por la UART, leer un registro de identificación de un sensor. Si el programa mínimo funciona, el hardware está bien y el problema está en el programa grande; si no funciona, el problema es de hardware o de configuración, y se acota sin las miles de líneas que lo rodean. El esqueleto del tema 12 existe para eso.

07 · Leer el síntoma

Tipos de error y sus síntomas

Con experiencia, el patrón del síntoma sugiere el tipo de error, y por lo tanto la técnica con que investigarlo. Los más frecuentes en sistemas embebidos, y a qué apuntan:

El síntoma «desaparece cuando lo miro» merece un lugar propio, porque desorienta a quien empieza: no significa que el error se haya ido sino que la forma de mirar lo tapó. Casi siempre es un problema de tiempo: la instrumentación demora una sección lo suficiente como para que la carrera no se produzca, o cambia el uso de la pila o la ubicación de las variables. La reacción correcta no es celebrar, sino cambiar de instrumento por uno menos intrusivo (un pin, un registro de eventos) y confirmar que el error sigue existiendo y se puede ver.

08 · Acorralar al error

Estrategias para acorralar un error

Además de las herramientas, hay estrategias de búsqueda que ahorran horas:

• Bisección. Si el programa funcionaba en una versión anterior y falla en la actual, hay una versión intermedia en la que apareció el error. Se prueba la del medio: si falla, el error está entre la buena y la del medio; si no, entre la del medio y la mala. Con 64 versiones, seis pruebas bastan (log₂ 64), contra unas 32 en promedio probando una por una: la Parte 4 lo simula y encuentra la versión 41 en seis pruebas. Sirve con el control de versiones (git bisect automatiza el proceso), y también dentro del código: se desactiva la mitad de las funciones y se ve de qué lado queda el error.
• Reducir el caso. Quitar piezas del sistema hasta quedarse con el programa más chico que todavía falla. Un error en un programa de 50 líneas es casi evidente; el mismo en uno de 5000, no. La reducción obliga además a entender qué es y qué no es relevante.
• Comparar lo que anda con lo que no: la versión buena y la mala, la placa que funciona y la que no, las condiciones en que falla y en que no. La diferencia más pequeña entre las dos es el mejor candidato.
• Aserciones e invariantes (tema 39): afirmar en el código lo que debería ser verdad. Un ASSERT que salta convierte «algo raro pasó en algún momento» en «esta condición se violó, en este lugar».
• Pasar el problema a la PC. La lógica del firmware, separada del hardware (temas 10, 25 y 27), se puede ejecutar en la computadora con herramientas mucho más potentes (depuradores completos, sanitizers, pruebas automáticas con entradas al azar), y los errores de lógica se encuentran allí en minutos.
• Explicárselo a alguien (o a un objeto: es el método del «patito de goma»). Al describir en voz alta qué hace cada línea y qué se espera, muchas veces el error aparece solo, porque obliga a pasar de «creo que hace esto» a «hace esto».
• Descansar. Un error que no se encuentra después de horas casi siempre se resuelve en minutos tras una pausa o al día siguiente: lo que cansa es el supuesto equivocado que uno no revisa.

Y dos hábitos que valen oro: anotar lo que se prueba y lo que se descubre (un cuaderno de laboratorio, un archivo de texto), para no repetir experimentos ni perder la pista; y escribir una prueba que reproduzca el error antes de corregirlo, de modo que quede protegido contra su regreso. La corrección sin la prueba es una promesa; con ella, un hecho.

09 · Comprobar que funciona

Verificación y diagnóstico

La instrumentación también se verifica, por dos razones: puede cambiar el comportamiento (y entonces las conclusiones valen poco) y puede quedarse en el producto (y entonces consume recursos o expone información).

10 · Analogía con programación

Probar el modelo en Python

El programa reúne cuatro piezas del tema: el análisis de la captura de un pin de prueba (duración, período, latencia y anomalías de las 60 ejecuciones de una ISR); el costo de imprimir por la UART y el tamaño del buffer de registro necesario para una ráfaga; un registro de eventos circular en RAM que sobrevive a un cuelgue; y la bisección que encuentra, entre 64 versiones, la primera que introdujo un error.

# Depuración básica: leer una captura de un pin de prueba, el costo de imprimir por la UART, un registro de eventos en RAM y la búsqueda binaria de un error.
import random, statistics, math

# ---- Parte 1: analizar la captura de un analizador lógico (un pin que sube al entrar a la ISR y baja al salir) --------------
rnd = random.Random(5)
flancos = []                                                       # (instante en µs, nivel) como los exporta un analizador lógico
for k in range(60):
    inicio = k * 1000 + rnd.gauss(0, 2)
    dur = rnd.gauss(120, 3)
    if k == 37: inicio += 400                                      # una sección crítica retrasó la interrupción
    if k == 45: dur = 900                                          # una ISR que tardó siete veces más
    flancos += [(inicio, 1), (inicio + dur, 0)]
flancos.sort()
subidas = [t for t, n in flancos if n == 1]
bajadas = [t for t, n in flancos if n == 0]
duraciones = [b - s for s, b in zip(subidas, bajadas)]
periodos = [b - a for a, b in zip(subidas, subidas[1:])]
med_d, med_p = statistics.median(duraciones), statistics.median(periodos)
print("Parte 1: captura de un pin de prueba que marca la duración de la ISR (60 interrupciones)")
print(f"  período mediano {med_p:.1f} µs (desvío {statistics.pstdev(periodos):.1f}); duración mediana de la ISR {med_d:.1f} µs; carga {med_d / med_p * 100:.1f} %")
print(f"  duración máxima: {max(duraciones):.0f} µs; período mínimo {min(periodos):.0f} µs y máximo {max(periodos):.0f} µs")
raras_dur = [k for k, d in enumerate(duraciones) if d > 3 * med_d]
raros_per = [k for k, p in enumerate(periodos) if abs(p - med_p) > 200]
print(f"  ISR con duración anormal (más de 3 veces la mediana): número {raras_dur}")
print(f"  intervalos con período anormal (más de 200 µs de diferencia): entre las ISR {[(k, k + 1) for k in raros_per]} (el retraso de la ISR {raros_per[0] + 1} y el adelanto relativo de la siguiente)")
retraso = subidas[37] - 37 * 1000
print(f"  latencia de la ISR 37 respecto de su instante esperado: {retraso:.0f} µs")

# ---- Parte 2: el costo de imprimir por la UART --------------------------------------------------------------------------------
print()
print("Parte 2: imprimir una línea por la UART, bloqueando hasta que sale el último byte (10 bits por byte)")
print(f"  {'baudios':>8} | " + " | ".join(f"{n:>3} caracteres" for n in (20, 40, 80)))
for baud in (9600, 115_200, 921_600):
    print(f"  {baud:>8} | " + " | ".join(f"{n * 10 / baud * 1e6:>8.0f} µs  " for n in (20, 40, 80)))
cap = 115_200 / 10
print(f"  a 115 200 baudios el canal admite {cap:,.0f} B/s = {cap / 40:.0f} mensajes de 40 caracteres por segundo como máximo".replace(",", " "))
rafaga, largo = 20, 40
bytes_rafaga = rafaga * largo
print(f"  una ráfaga de {rafaga} mensajes de {largo} caracteres generada en 1 ms ({bytes_rafaga} B) tarda {bytes_rafaga / cap * 1000:.0f} ms en salir: el buffer de registro debe tener al menos {bytes_rafaga - int(cap * 0.001)} B")

# ---- Parte 3: un registro de eventos circular en RAM -----------------------------------------------------------------------------
TAM_REG, N = 8, 256                                                # 8 bytes por evento, 256 eventos = 2 KB
buffer = [None] * N
cabeza = 0
t = 0
for i in range(2000):                                              # el sistema genera 2000 eventos y se cuelga en el último
    t += rnd.randint(40, 400)                                      # instante en µs
    buffer[cabeza % N] = (t, rnd.choice((1, 2, 3, 7)), i)          # (marca de tiempo, identificador del evento, argumento)
    cabeza += 1
ultimos = [buffer[(cabeza - 1 - k) % N] for k in range(N)][::-1]   # de más viejo a más nuevo
print()
print(f"Parte 3: registro de eventos de {N} entradas de {TAM_REG} bytes = {N * TAM_REG} bytes, tras {cabeza} eventos y un cuelgue")
print(f"  se conservan los últimos {len(ultimos)} eventos: del número {ultimos[0][2]} al {ultimos[-1][2]}; marcas de tiempo crecientes: {all(a[0] < b[0] for a, b in zip(ultimos, ultimos[1:]))}")
print("  los 5 últimos antes del cuelgue (instante µs, id, argumento):", ultimos[-5:])
ventana = ultimos[-1][0] - ultimos[0][0]
print(f"  esos {N} eventos cubren los últimos {ventana / 1000:.1f} ms de funcionamiento")
CICLOS, MHZ = 30, 48
registrar_us = CICLOS / MHZ
imprimir_us = 40 * 10 / 115_200 * 1e6
print(f"  costo de registrar un evento (SUPUESTO: {CICLOS} ciclos a {MHZ} MHz): {registrar_us:.2f} µs; imprimir una línea de 40 caracteres por la UART a 115 200 baudios: {imprimir_us:.0f} µs ({imprimir_us / registrar_us:,.0f} veces más)".replace(",", " "))

# ---- Parte 4: encontrar la versión que introdujo un error por bisección -------------------------------------------------------------
versiones = 64
mala_desde = 41                                                    # la primera versión con el error (el programador no lo sabe)
pruebas = []
bajo, alto = 0, versiones - 1                                      # la 0 es buena y la última es mala
while alto - bajo > 1:
    medio = (bajo + alto) // 2
    esta_mala = medio >= mala_desde
    pruebas.append((medio, "MALA" if esta_mala else "buena"))
    if esta_mala: alto = medio
    else: bajo = medio
print()
print(f"Parte 4: buscar entre {versiones} versiones cuál introdujo el error (la primera mala es la {mala_desde}, pero eso no se sabe)")
print("  pruebas por bisección:", ", ".join(f"v{v}={r}" for v, r in pruebas))
print(f"  la versión que introdujo el error es la {alto}: {len(pruebas)} pruebas (log2({versiones}) = {math.log2(versiones):.0f}); probando una por una, en promedio {versiones / 2:.0f}")

Resultado, parte 1: de la captura de 60 interrupciones salen un período mediano de 1000,5 µs, una duración mediana de la ISR de 120,1 µs (12,0 % de carga) y dos anomalías: la ISR número 45 dura 900 µs (más de tres veces la mediana) y la 37 arranca con 399 µs de retraso (períodos de 1395 y de 598 µs a su alrededor). Parte 2: una línea de 40 caracteres bloquea 41 667 µs a 9600 baudios, 3472 µs a 115 200 y 434 µs a 921 600; a 115 200 baudios el canal admite 11 520 B/s (288 mensajes de 40 caracteres por segundo), y una ráfaga de 20 mensajes de 40 caracteres en 1 ms tarda 69 ms en salir y exige un buffer de al menos 789 B. Parte 3: tras 2000 eventos y un cuelgue, el buffer de 256 entradas de 8 bytes (2048 bytes) conserva los eventos 1744 a 1999, con marcas de tiempo crecientes, que cubren los últimos 58,1 ms; registrar un evento cuesta 0,62 µs (supuesto de 30 ciclos a 48 MHz) contra 3472 µs de imprimir: 5556 veces menos. Parte 4: la bisección encuentra la versión 41, entre 64, con seis pruebas (v31 buena, v47 mala, v39 buena, v43 mala, v41 mala, v40 buena).

Probá cambiar en la Parte 1 el valor de la duración de la ISR anómala o el instante del retraso y mirá que el análisis las sigue encontrando, o aumentá versiones a 1024 en la Parte 4 y verificá que bastan 10 pruebas. La lección del programa es que los datos de una captura bien tomada hablan: dos anomalías enterradas en 60 ejecuciones, que a ojo no se ven, aparecen con unas pocas líneas de análisis, y esas líneas se pueden reutilizar con cualquier captura de un analizador lógico exportada a un archivo.

11 · Exploración interactiva

El costo de mirar

El laboratorio simula una interrupción de 1 ms que dura 120 µs, y muestra qué le hace cada forma de instrumentarla: nada, un pin de prueba, un printf dentro de la ISR o un registro diferido a un buffer de 512 bytes. Elegís la velocidad de la UART, el largo de los mensajes y cuántos se imprimen por segundo. El laboratorio simula un segundo de funcionamiento y cuenta las interrupciones que se pierden, la carga del procesador y los mensajes que no caben en el canal; la línea de tiempo muestra las primeras ejecuciones (en naranja, las que duran más que el período).

Recorrido guiado

1. Con «Sin instrumentar»: la ISR dura 120 µs en un período de 1000 µs (12 % de carga), no se pierde nada y no se ve nada. Es la referencia: el sistema sano y a oscuras.
2. Elegí «Pin de prueba»: la ISR dura 120,2 µs (el pin cuesta 0,2 µs) y la carga sigue en 12 %. Casi no perturba, y con un analizador lógico se ve cada ejecución. Es la técnica para los problemas de tiempo.
3. Elegí «printf dentro de la ISR» a 115 200 baudios y 40 caracteres, un mensaje por ISR: la ISR dura 3592 µs, casi cuatro veces su período; se pierden 720 de las 1000 interrupciones y el procesador está al 100 %. La línea de tiempo muestra bloques naranja que cubren varios períodos. La instrumentación destruyó el comportamiento que se quería observar.
4. Con el mismo printf, bajá la tasa a 10 mensajes por segundo: la ISR que imprime sigue durando 3592 µs (y pierde dos interrupciones cada vez que lo hace: 20 de 1000 en total), pero ocurre una vez cada 100 ejecuciones. Y subí la velocidad a 921 600: la ISR baja a 554 µs y ya entra en el período sin perder ninguna. Imprimir en una ISR depende de cuánto y de qué tan rápido.
5. Elegí «Registro diferido» con 1000 mensajes por segundo de 40 caracteres a 115 200 baudios: la ISR dura 122 µs (la copia al buffer cuesta 2 µs) y no se pierde ninguna interrupción, pero el canal solo admite 288 mensajes por segundo: unos 712 por segundo se pierden cuando el buffer de 512 B se llena. Se arregló el tiempo y apareció el límite del ancho de banda.
6. Con el registro diferido, bajá los mensajes a 100 por segundo (o subí la velocidad a 921 600): ahora el canal alcanza y no se pierde nada. La conclusión es la de la Parte 2: el registro diferido protege el tiempo, pero hay que dimensionar el volumen de información que se manda y decidir qué se pierde cuando no cabe.

12 · Método de trabajo

Método: depurar con orden

1. Reproducí el error y anotá cómo. Un error que se puede provocar se puede estudiar, y si es raro, buscá qué lo hace más frecuente.
2. Revisá lo básico antes del código: alimentación, masa, reloj, reset, pines, niveles. Si hay dudas, un programa mínimo que ejercite el periférico sospechoso.
3. Elegí el instrumento por la pregunta: tiempo → pin y analizador; secuencia → registro de eventos; valores → depurador (tema 45); señal analógica → osciloscopio. Siempre el menos intrusivo que responda.
4. Prefiero lo diferido: nada de texto dentro de las ISR; un buffer en RAM y salida en segundo plano; contadores de lo perdido.
5. Dejá el latido y los puntos de prueba desde el principio del proyecto: un LED de vida en el bucle principal, pines libres accesibles, un conector de depuración y un registro de eventos básico.
6. Formulá hipótesis concretas y probalas con un experimento que cambie una sola cosa. Si el error desaparece al observarlo, cambiá de instrumento, no lo celebres.
7. Acotá con estrategia: bisección entre versiones, reducción del caso, comparación entre lo que anda y lo que no, aserciones; y trasladá la lógica a la PC cuando se pueda.
8. Corregí la causa, no el síntoma, y escribí una prueba que reproduzca el error para que no regrese.
9. Anotá lo que aprendiste (qué era, cómo se encontró, cómo se evitará).
10. Quitá o desactivá la instrumentación del producto, y verificá la configuración de producción: sin textos de depuración, sin LED parpadeando, con los pines de prueba en un estado seguro.

13 · Comprensión

Confusiones frecuentes

14 · Práctica guiada

Ejercicios

1. El costo de una línea

Un programa imprime una línea de 32 caracteres a 57 600 baudios, bloqueando, desde una interrupción que se dispara cada 1 ms. ¿Cuánto tarda en salir la línea? ¿Qué pasa con la interrupción? Si solo se imprimiera, sin otra cosa, ¿cuántas líneas por segundo caben?

2. El tamaño del buffer

Un sistema genera una ráfaga de 10 mensajes de 50 caracteres en 2 ms. La UART va a 115 200 baudios. ¿Cuántos bytes se generan, cuántos salen durante los 2 ms y qué tamaño mínimo debe tener el buffer? ¿Cuánto tarda en vaciarse?

3. La frecuencia de muestreo

Se quiere medir con un analizador lógico la duración de una ISR de 120 µs con un error del 1 %. ¿Qué intervalo entre muestras y qué frecuencia de muestreo mínimos hacen falta? ¿Y para ver un pulso espurio de 100 ns?

4. Cuánta historia guarda el registro de eventos

Un registro de eventos usa 8 bytes por evento y dispone de 4 KB de RAM. El sistema genera 5000 eventos por segundo. ¿Cuántos eventos caben y qué ventana de tiempo cubren? ¿Qué harías si el error aparece unos 500 ms después de su causa?

5. Bisección

Se sabe que un error aparece en algún lugar de una historia de 1000 versiones. Cada prueba (compilar, grabar y probar) lleva 8 minutos. ¿Cuántas pruebas hacen falta por bisección? ¿Cuánto tiempo, comparado con probar una por una en promedio?

6. El error que desaparece

Un equipo se cuelga una vez por hora. Se agrega un printf al principio de la ISR del UART para ver los datos, y desde entonces no se cuelga más. ¿Qué indica esto, y cómo seguirías?

15 · Síntesis

Ideas para recordar

¿Listo para el tema siguiente?

Antes de avanzar, revisá un proyecto tuyo y respondé: ¿tiene un LED de latido en el bucle principal?, ¿hay un pin libre accesible para medir tiempos y un conector para el depurador?, ¿hay un printf dentro de alguna interrupción?, ¿qué registraría el equipo si se colgara ahora mismo? Si la respuesta a la última es «nada», agregá un registro de eventos de 256 entradas: es una hora de trabajo que vale años de depuración.

En el próximo tema usamos la herramienta más potente de la depuración: SWD y JTAG. Puntos de interrupción, inspección de registros y memoria, observación de variables sin detener el programa y trazas, con el depurador conectado al microcontrolador.