Como medir tiempos de hooks con microtime en PHP en WordPress

Introducción

Medir el tiempo que tarda cada hook en ejecutarse en WordPress es una técnica muy útil para localizar cuellos de botella, identificar plugins o temas lentos y optimizar el rendimiento general. Este artículo explica con todo lujo de detalles cómo usar microtime(true) en PHP para cronometrar hooks de WordPress, cómo recoger y almacenar esos datos y cómo mostrar o registrar un resumen al finalizar la carga de la página.

Qué aprenderás

• Qué devuelve microtime(true) y por qué es adecuado para medir tiempos en segundos con fracciones.
• Cómo instrumentar hooks de actions y filters evitando interferir con el flujo normal.
• Formas de almacenar los tiempos: registro en fichero, error_log, transients o visualización en el Admin Bar.
• Buenas prácticas y precauciones para minimizar el impacto de la medición.

Conceptos básicos

microtime(true) — ¿qué devuelve?

microtime(true) devuelve un float con la marca temporal actual en segundos, incluyendo microsegundos como fracción decimal. Por ejemplo 1627382913.123456. Restando dos llamadas obtienes la duración transcurrida con precisión submilisegundo en muchas plataformas.

microtime(true) vs microtime()

microtime() sin parámetro devuelve una cadena microsegundos segundos. Para cálculos es más cómodo y directo usar microtime(true) que ya devuelve un float usable.

Implementación básica: plugin mínimo para medir hooks

El enfoque más sencillo es enganchar una función antes y otra después del hook objetivo. Sin embargo, para medir muchos hooks lo mejor es centralizar la captura con add_action/add_filter globales que registren tiempo de inicio y final por nombre del hook.

Ejemplo de plugin mínimo que captura tiempos por hook y escribe el resumen al final (fichero o error_log):

 microtime(true),
    hooks => array(),
)

/
  Registrar inicio de hook
 /
function wht_before_hook( hook_name ) {
    global wp_hook_timer
    if ( ! isset( wp_hook_timer[hooks][ hook_name ] ) ) {
        wp_hook_timer[hooks][ hook_name ] = array(
            calls => 0,
            times => array(),
        )
    }
    wp_hook_timer[hooks][ hook_name ][calls]  
    // Guardamos el tiempo de inicio en un stack para manejar recursividad
    if ( ! isset( wp_hook_timer[hooks][ hook_name ][stack] ) ) {
        wp_hook_timer[hooks][ hook_name ][stack] = array()
    }
    wp_hook_timer[hooks][ hook_name ][stack][] = microtime(true)
}

/
  Registrar fin de hook
 /
function wht_after_hook( hook_name ) {
    global wp_hook_timer
    if ( isset( wp_hook_timer[hooks][ hook_name ][stack] )  count( wp_hook_timer[hooks][ hook_name ][stack] ) ) {
        start = array_pop( wp_hook_timer[hooks][ hook_name ][stack] )
        dur = microtime(true) - start
        wp_hook_timer[hooks][ hook_name ][times][] = dur
    }
}

// Enganchamos a all para actions y filters (WordPress 4.7  soporta current_filter())
add_action( all, function() {
    current = current_filter()
    // before: insertar un marcador al inicio (se ejecuta en cada llamada antes del callback real)
    wht_before_hook( current )
    // registramos un shutdown para computar fin después de que el stack del hook termine
    // Observación: esto marca el mismo tiempo de inicio y fin en el mismo evento, por eso usaremos el mismo stack de start/stop
} )

// Para capturar el fin del hook usamos shutdown y calculamos totales finales
add_action( shutdown, function() {
    global wp_hook_timer
    summary = array()
    foreach ( wp_hook_timer[hooks] as hook => data ) {
        total = array_sum( data[times] )
        count = data[calls]
        avg = count ? total / count : 0
        summary[ hook ] = array(
            calls => count,
            total => total,
            avg   => avg,
        )
    }
    // Escribir a error_log (o a un fichero)
    foreach ( summary as hook => s ) {
        error_log( sprintf( Hook: %s  calls: %d  total: %.6f s  avg: %.6f s, hook, s[calls], s[total], s[avg] ) )
    }
} )
?>

Notas sobre el ejemplo:

1. El uso de add_action(all, …) permite interceptar todos los hooks, pero hay que tener cuidado porque esto se ejecuta con muchísima frecuencia. Es útil para debugging pero no para todas las instalaciones en producción.
2. El ejemplo anterior simplifica el cálculo. En entornos complejos tal vez necesites enganchar antes y después de callbacks concretos si quieres precisión exacta por callback (sobre todo en filters que pueden ser anidados).

Implementación avanzada: clase que mide por hook y callback

Una implementación más robusta mantiene datos por hook y por callback, soporta nested hooks correctamente y ofrece opciones para exportar los resultados a fichero o mostrar en pantalla sólo a administradores.

enabled = enabled
        this->start_time = microtime(true)
        if ( this->enabled ) {
            add_action( all, array( this, hook_enter ), 0 )
            add_action( shutdown, array( this, report ), 9999 )
        }
    }

    public function hook_enter() {
        hook = current_filter()
        now = microtime(true)

        if ( ! isset( this->data[ hook ] ) ) {
            this->data[ hook ] = array(
                calls => 0,
                times => array(),
                stack => array(),
            )
        }

        // Push start time (soporta recursividad)
        this->data[ hook ][stack][] = now
        this->data[ hook ][calls]  
        // Añadimos un shutdown parcial: capturaremos fin al salir del callback usando register_shutdown_function
        // Pero register_shutdown_function se ejecuta una vez al final mejor gestionamos el fin cuando se detecta que el stack se vacía
        // Aquí no tenemos un after directo, así que calculamos tiempos cuando detectamos que el top del stack fue cerrado por otro hook.
        // Una técnica práctica: si la siguiente llamada a all es para un hook distinto y el stack del anterior tiene tiempo, lo cerramos.
        // Implementación simplificada: al final (shutdown) leeremos el stack y asumiremos que los tiempos se calcularon por pares push/pop.
    }

    public function report() {
        report = array()
        foreach ( this->data as hook => info ) {
            // Si no hay times porque no cerramos stacks, intentamos limpiar stacks asumiendo final en shutdown
            if ( ! empty( info[stack] ) ) {
                foreach ( info[stack] as start ) {
                    info[times][] = microtime(true) - start
                }
            }
            total = array_sum( info[times] )
            count = info[calls]
            avg = count ? total / count : 0
            report[ hook ] = array(
                calls => count,
                total => total,
                avg   => avg,
            )
        }

        // Ordenar por mayor tiempo total
        uasort( report, function( a, b ) {
            return b[total] <=> a[total]
        } )

        // Guardar resumen a fichero sólo si WP_DEBUG es true o para administradores
        log_file = WP_CONTENT_DIR . /hook-timing.log
        lines = array()
        lines[] = --- Hook Profiler:  . date( Y-m-d H:i:s ) .   uptime:  . ( microtime(true) - this->start_time ) . s
        foreach ( report as hook => r ) {
            lines[] = sprintf( %s  calls: %d  total: %.6f  avg: %.6f, hook, r[calls], r[total], r[avg] )
        }
        file_put_contents( log_file, implode( PHP_EOL, lines ) . PHP_EOL, FILE_APPEND  LOCK_EX )
    }
}

// Instalar el profiler si estamos en entorno de desarrollo
enabled = defined( WP_DEBUG )  WP_DEBUG
new WP_Hook_Profiler( enabled )
?>

Comentarios sobre la clase:

• El ejemplo robusto introduce guardas para habilitar el profiler sólo cuando WP_DEBUG está activado, reduciendo riesgo de impacto en producción.
• Gestión de stack: para hooks profundamente anidados es necesario empujar y sacar los tiempos correctamente. Dependiendo del nivel de precisión deseado, puede instrumentarse a nivel de callback en lugar de interceptar all.
• Se recomienda añadir filtros/whitelist para medir sólo ciertos hooks relevantes (por ejemplo template_redirect, wp_ajax_, init).

Ejemplo: escribir tiempos en un fichero y agrupar por page type

Este ejemplo muestra cómo capturar tiempos, incluir memoria usada y asociar la medición a una URL o tipo de petición.

start = microtime(true)
        add_action( all, array( this, enter ), 0 )
        add_action( shutdown, array( this, flush ), 9999 )
    }

    public function enter() {
        hook = current_filter()
        t = microtime(true)
        if ( ! isset( this->records[ hook ] ) ) {
            this->records[ hook ] = array( calls => 0, times => array() )
        }
        // Empujamos tiempo de inicio
        this->records[ hook ][calls]  
        this->records[ hook ][times][] = array( start => t, end => null )
        // Programamos un pequeño callback para marcar el final del callback actual
        // Nota: no existe hook after por defecto esta aproximación simplificada pondrá end en el siguiente evento
        last_idx = count( this->records[ hook ][times] ) - 1
        register_shutdown_function( function() use ( hook, last_idx ) {
            // Si sigue vacío el end, lo cerramos al shutdown
            global wht_file_logger_instance
            if ( isset( wht_file_logger_instance->records[ hook ][times][ last_idx ] ) ) {
                wht_file_logger_instance->records[ hook ][times][ last_idx ][end] = microtime(true)
            }
        } )
    }

    public function flush() {
        log = array()
        log[] = ---  . date( Y-m-d H:i:s ) .   URL:  . ( isset( _SERVER[REQUEST_URI] ) ? _SERVER[REQUEST_URI] : cli )
        foreach ( this->records as hook => info ) {
            total = 0
            count = info[calls]
            foreach ( info[times] as t ) {
                end = t[end] ?? microtime(true)
                total  = max(0, end - t[start])
            }
            avg = count ? total / count : 0
            log[] = sprintf( %s  calls: %d  total: %.6f  avg: %.6f  mem: %s, hook, count, total, avg, size_format( memory_get_usage() ) )
        }
        file_put_contents( WP_CONTENT_DIR . /hook-timings.log, implode( PHP_EOL, log ) . PHP_EOL, FILE_APPEND  LOCK_EX )
    }
}

global wht_file_logger_instance
wht_file_logger_instance = new WHT_File_Logger()
?>

Mostrar resultados en el Admin Bar (solo administradores)

Una manera práctica de visualizar los tiempos durante desarrollo es inyectar un nodo en el Admin Bar con el tiempo total de carga y un enlace a un detalle en HTML (o un modal). Aquí un ejemplo simple que añade el tiempo total y memoria usada:

add_node( array(
        id    => wht_summary,
        title => label,
        href  => false,
    ) )
}, 100 )
?>

Interpretación de resultados

Al analizar el resumen fíjate en:

• Total: tiempo acumulado por todas las llamadas al hook. Útil para identificar hooks que consumen mucho tiempo en conjunto.
• Calls: número de invocaciones. Un hook con muchas invocaciones pequeñas puede ser más problemático que uno con pocas invocaciones largas.
• Avg: tiempo promedio por invocación ayuda a identificar callbacks concretos lentos.

Ejemplo de tabla de resultados

Buenas prácticas y precauciones

• No habilites interceptores globales en producción salvo que sea necesario. Usar WP_DEBUG o una constante específica para activar el profiler.
• Evita escribir en disco con cada petición en sitios de alto tráfico mejor agrupar o usar transients y una tarea cron para volcar resultados.
• Medir también la memoria con memory_get_usage() y memory_get_peak_usage() te da contexto adicional.
• Filtra la lista de hooks a instrumentar (whitelist) para reducir overhead: por ejemplo medir sólo init, wp_loaded, wp_ajax_, template_redirect, etc.
• Ten en cuenta que interceptar all puede cambiar el orden/tiempos si tu instrumentation ejecuta operaciones costosas. Mantén las funciones de medición lo más ligeras posible.
• Si mides callbacks específicos puedes envolver el callback original con una closure que calcule start/end para ese callback concreto —esto suele ser más preciso.

Resumen y recomendaciones finales

Usar microtime(true) para medir hooks en WordPress es simple y efectivo. Para implementaciones prácticas:

1. Empieza con una versión ligera que registre sólo los hooks clave en un entorno de desarrollo.
2. Si necesitas más detalle, instrumenta callbacks específicos en lugar de usar all.
3. Guarda resultados en un log rotativo o en una base de datos/transient para análisis posterior y evita I/O sin control en producción.
4. Combina datos de tiempo con uso de memoria y número de llamadas para priorizar optimizaciones.

Recursos útiles

• WordPress Developer Resources
• microtime — Manual PHP

	Acepto donaciones de BAT's mediante el navegador Brave 🙂