Time Profiler: leer un trace y encontrar el tiempo

Un perfilador de muestreo no sabe nada de tu programa. Cada milisegundo, más o menos, detiene los hilos, camina la pila de cada uno y anota la lista de marcos que encuentra; al terminar agrega esas listas y te presenta un árbol. Todo lo que llamas el tiempo que tarda una función es en realidad una inferencia estadística: la proporción de muestras en las que esa función aparecía en la pila. Entender esa frase entera —lo que implica y, sobre todo, lo que no garantiza— separa a quien optimiza el sitio correcto de quien pasa dos días acelerando código que se ejecutaba el cero coma tres por ciento del tiempo. Time Profiler es la herramienta más usada de Instruments y también la peor leída, porque su salida parece un informe y es un histograma.

Qué es una muestra y qué no

El instrumento se apoya en un temporizador del núcleo. Cuando dispara, para cada hilo que esté ejecutándose captura el registro de pila y desenrolla los marcos hasta la raíz. Esa fotografía es una muestra. La consecuencia inmediata, y la que casi nadie interioriza, es que un hilo bloqueado no genera muestras de trabajo: si tu función espera en un mutex, en una lectura de disco o en una respuesta de red, el Time Profiler la ve como tiempo que sencillamente no existe.

De ahí nacen dos magnitudes que hay que separar mentalmente desde el primer minuto:

• Tiempo de CPU: instrucciones realmente ejecutadas. Es lo que mide este instrumento.
• Tiempo de pared: lo que percibe la persona que usa la app. Incluye esperas, contención de bloqueos y trabajo hecho por otros procesos.

Una pantalla que tarda dos segundos en aparecer y muestra ciento veinte milisegundos de CPU no tiene un problema de algoritmo: tiene un problema de espera, y ese se caza con os_signpost o con System Trace, no aquí.

Sobre cada marco del árbol Instruments calcula dos números que responden preguntas distintas. El peso total cuenta las muestras en las que el marco aparecía en cualquier posición de la pila: mide la responsabilidad de un subárbol entero. El peso propio cuenta solo las muestras en las que el marco estaba en la cima: mide el trabajo hecho por ese código y por nadie más. Un viewDidLoad con noventa por ciento de peso total y cero de peso propio no es lento; es el sitio desde el que se invoca lo lento.

flowchart TD
A[El temporizador dispara cada milisegundo] --> B[Se congela el hilo en ejecucion]
B --> C[Se desenrolla la pila completa]
C --> D[La lista de marcos se guarda como una muestra]
D --> E[Al final se agregan las muestras identicas]
E --> F[Peso total igual a muestras donde el marco aparece]
E --> G[Peso propio igual a muestras donde el marco esta en la cima]
F --> H[Arbol de llamadas descendente]
G --> I[Pila invertida]

La pila invertida y los filtros

El árbol descendente es fiel a la estructura del programa y por eso resulta inútil al principio: la raíz siempre es start, luego UIApplicationMain, luego veinte niveles de sistema, y el trabajo real está enterrado. La pila invertida —la opción Invert Call Tree— da la vuelta a la agregación y ordena por peso propio, poniendo arriba las hojas donde de verdad se consumen ciclos. Es el primer clic de toda sesión seria.

Junto a él hay cuatro ajustes que convierten un muro de datos en un diagnóstico:

• Hide System Libraries colapsa los marcos que no puedes cambiar y atribuye su coste al último marco tuyo. Con él descubres que ese CGContextDrawImage carísimo lo llama tu propia función de miniaturas.
• Separate by Thread deja de mezclar el hilo principal con las colas de fondo. Sin él, un trabajo pesado y correcto en segundo plano puede tapar un bloqueo real en el hilo de la interfaz.
• Flatten Recursion colapsa las repeticiones de una misma función recursiva, que de otro modo reparten su peso en cien niveles distintos y no aparecen en ningún ranking.
• Charge to Callers reasigna el coste de un marco concreto entre quienes lo invocan, útil cuando una utilidad genérica sale la primera y necesitas saber quién abusa de ella.

Del pico a la causa

Un trace completo de treinta segundos es ruido. El método que funciona empieza al revés: primero se reproduce el síntoma con el reloj en la mano, después se selecciona en la línea de tiempo solo el intervalo del síntoma, y el árbol se recalcula sobre esa ventana. Un scroll con tirones de trescientos milisegundos analizado en aislamiento cuenta una historia nítida que el promedio de treinta segundos diluye hasta hacerla desaparecer.

La lectura después es casi mecánica. Se mira el hilo principal, se invierte el árbol, se ocultan las bibliotecas del sistema y se examinan las tres o cuatro primeras filas por peso propio. Con doble clic sobre un marco, Instruments abre el código fuente con el coste anotado línea a línea, y es ahí donde suelen aparecer los sospechosos clásicos: una decodificación de imagen síncrona, una expresión regular compilada dentro de un bucle, un DateFormatter construido en cada celda, una colección que se copia por valor en cada iteración porque alguien retuvo una referencia y rompió la optimización de copia perezosa.

// El patron que domina los traces de listas lentas
struct FilaMal: View {
    let fecha: Date
    var body: some View {
        // Construir el formateador en cada evaluacion del cuerpo
        let f = DateFormatter()
        f.dateStyle = .medium
        return Text(f.string(from: fecha))
    }
}

// La version que desaparece del perfil
private let formateador: DateFormatter = {
    let f = DateFormatter()
    f.dateStyle = .medium
    return f
}()

Conviene además comprobar siempre el número absoluto de muestras antes de creerse un porcentaje. Un marco con el cuarenta por ciento del peso pero solo doce muestras no es un hallazgo, es ruido estadístico; la incertidumbre de un muestreador escala con la raíz del recuento, así que una sesión corta necesita repetirse o alargarse antes de sacar conclusiones.

Hay un segundo paso que casi nadie da y que multiplica el valor del trace: mirar la columna de hilos antes de mirar el árbol. Si el hilo principal aparece con poco tiempo de CPU durante el intervalo del síntoma, ninguna optimización de algoritmo va a mejorar nada, porque el problema es de espera. Si en cambio aparecen ocho colas de fondo compitiendo, la causa puede ser explosión de concurrencia: más tareas que núcleos provocan cambios de contexto y contención, y el resultado es que el trabajo total se hace más despacio precisamente por haberlo repartido.

Errores de método que invalidan la medición

Cuatro descuidos concentran la mayoría de las conclusiones falsas, y ninguno es un problema de la herramienta.

Perfilar en el simulador. El simulador ejecuta código compilado para la arquitectura del Mac, con otra jerarquía de memoria, otra GPU y sin límites térmicos. Sirve para comprobar que algo funciona; no sirve para decidir qué optimizar.

Medir el primer arranque. La primera ejecución tras instalar paga cachés frías, validación de firma, precalentamiento de fuentes y creación de bases de datos. Comparar un primer arranque con un arranque templado produce diferencias enormes que no dicen nada del código.

Confundir dispositivo caliente con código lento. Un teléfono con la batería baja o en limitación térmica reduce su frecuencia de reloj. Si la primera medición se hizo en frío y la segunda tras diez minutos de pruebas, la mejora o el empeoramiento pueden ser puramente físicos.

Optimizar sin línea base escrita. Sin un número anotado antes del cambio, cualquier resultado posterior parece una mejora. La disciplina mínima es guardar el trace previo, no solo recordar la sensación.

A esos cuatro se suma uno más sutil y muy caro: medir con datos de juguete. Una lista de veinte elementos no revela el algoritmo cuadrático que estalla con dos mil, y una respuesta de red de tres kilobytes no ejercita el decodificador como lo hace la real. El conjunto de prueba debe parecerse al peor caso que verá un usuario, o la medición describirá un programa que nadie ejecuta.

// Convertir la sospecha en una linea base reproducible
func medir(_ nombre: String, _ bloque: () -> Void) {
    let inicio = ContinuousClock.now
    bloque()
    let duracion = inicio.duration(to: .now)
    print("\(nombre): \(duracion)")
}

Conviene además fijar el procedimiento de comparación antes de tocar nada. Tres repeticiones de la misma acción en el mismo dispositivo, descartando la primera por caliente o fría según el caso, y quedándose con la mediana en lugar de la media: la mediana resiste el arranque atípico que la media arrastra durante toda la sesión.

Y un último detalle que separa una medición honesta de una anécdota: anotar qué no cambió. Si entre las dos mediciones se actualizó el sistema operativo, se instalaron otras apps o se cambió el conjunto de datos de prueba, la diferencia observada no es atribuible al código. Registrar las condiciones cuesta un minuto y evita defender en una revisión una mejora que en realidad nunca ocurrió.

Ese cronómetro no sustituye al perfilador: lo complementa. El perfilador dice dónde está el coste; un número reproducible dice si el cambio sirvió. Sin las dos piezas, la optimización se convierte en una sucesión de reescrituras justificadas por la intuición, que es exactamente el hábito que esta lección intenta desmontar.