Investigando un uso alto de CPU en nuestro servidor

Publicada en WordPress.

Mira nuestro vídeo

Existe una versión mejor de tu web

Comparte este artículo

Hace unos días recibimos un correo de nuestro proveedor de hosting (SiteGround) avisándonos de que nuestro plan de hosting había alcanzado «el 90% del uso mensual permitido de 800000 segundos de CPU por plan» y que, una vez superáramos el 100%, el «servicio web quedaría limitado» y, por lo tanto, que podríamos tener «problemas para acceder a nuestra web». Sin duda, una situación totalmente indeseable que teníamos que corregir cuanto antes. Pero… ¿por dónde empezar?

Estadísticas de nuestra web durante el episodio de alto uso de CPU
Estadísticas de nuestra web durante el episodio de alto uso de CPU.

En la entrada de hoy compartimos contigo nuestra experiencia afrontando un problema bastante común explicando qué hicimos para identificar al culpable y ponerle solución. De esta forma, si estás en una situación parecida, por lo menos tendrás por dónde empezar…

Motivos por los que puedes tener un uso de CPU elevado

WordPress es un gestor de contenidos escrito en PHP. Esto quiere decir que, de entrada, cada vez que llega un visitante a tu web, WordPress se pone en marcha y procesa la petición (por ejemplo, «dame la página principal») para generar una respuesta (o sea, la propia página principal). Así, pues, dar respuesta a una petición implica un cierto uso de recursos del servidor: hay que ver qué se pide, ir a buscarlo a la base de datos, montar el HTML resultante, etc.

Uno de los motivos por los que un sistema de cache acelera el tiempo de carga de tu web es, precisamente, que consigue ahorrar este tiempo de procesamiento. Cuando llega una petición concreta por primera vez («dame la página principal»), WordPress se ejecuta tal y como estábamos comentando y la cache guarda una copia de la respuesta que está a punto de darse. De esta forma, futuras peticiones a ese mismo recurso (en nuestro ejemplo, la página principal) ya no necesitan de la ejecución de WordPress; la cache puede devolver la copia que se generó anteriormente, ahorrando tiempo y recursos.

Teniendo este funcionamiento en mente, no es difícil imaginar cuáles son los motivos por los que podemos ver un uso de CPU elevado en nuestro servidor:

  • Estamos recibiendo muchísimas peticiones. Si vienen muchos usuarios a nuestra web, o recibimos muchas peticiones ilegítimas (vamos, que están atacando a nuestro servidor), WordPress tendrá que procesar todas esas peticiones y, por lo tanto, aumentará el uso de recursos del servidor.
  • Las peticiones son lentas de resolver. Si tienes muchos plugins instalados, o tienes algún plugin que, por lo que sea, es poco eficiente, cada vez que recibas una petición, esta será costosa de resolver porque WordPress deberá cargar todos tus plugins y dejar que hagan «su trabajo».

En ambos casos puedes pensar… «bueno, parece que el problema está siempre en la ejecución de WordPress, así que si uso una cache, según lo que me has contado, debería solucionar el problema, ¿no?» Y, efectivamente, así es: un sistema de cache «soluciona» el problema (a veces simplemente lo enmascara; el problema sigue ahí, pero simplemente no nos afecta), pero la realidad es un poco más compleja.

Hay funcionalidades de WordPress que no siempre se pueden meter detrás de una cache y que, por lo tanto, requieren de la ejecución de WordPress cuando las usas:

  • Tareas programadas con WP-Cron. Se trata de un mecanismo de WordPress para programar tareas que se ejecutarán en algún momento del futuro. Por ejemplo, WP-Cron se usa para programar la publicación de una entrada: cuando llega la fecha de publicación, WordPress debe cambiar el estado de la entrada de Programada a Publicada.
  • La API REST de WordPress. Se trata de una interfaz que podemos usar desde aplicaciones externas para interaccionar con un sitio WordPress enviando y recibiendo objetos JSON. Aunque las peticiones de lectura a la API REST pueden ser cacheadas, esta API también permite crear y actualizar contenidos, los cuales no permiten (por definición) ser cacheados.
  • Peticiones AJAX en WordPress. Antes de que apareciera la API REST, si querías interaccionar de una forma más dinámica con WordPress debías usar su API de AJAX. Es muy parecido a la API REST, ya que podemos enviar y recibir información del servidor y, precisamente por ello, no podemos usar una cache para este tipo de peticiones.

Analizando el problema

Lo primero que tenemos que identificar es el motivo por el que el uso de CPU ha aumentado en nuestra web. ¿Ha aumentado el número de peticiones a nuestra web o resulta que resolver una petición es, de repente, más lento? Para responder esta pregunta disponemos de una herramienta muy útil en nuestro servidor: el registro de acceso.

El registro de acceso es un fichero de texto en el que el servidor apunta todas y cada una de las peticiones que le llegan junto con información útil sobre las mismas. En concreto, el registro de acceso nos dice cuándo se recibe una petición (fecha y hora), quién la hace (una IP), qué recurso pide (una URL), el resultado de esa petición y alguna cosa más. Aquí tienes un ejemplo de nuestro servidor:

66.249.83.82 - - [22/Apr/2020:14:04:59 +0200] "GET /es/blog/imagenes-gratuitas-para-tu-blog/ HTTP/1.0" 200 22325 "-" "Mozilla/5.0 (Linux; Android 4.2.1; en-us; Nexus 5 Build/JOP40D) AppleWebKit/535.19 (KHTML, like Gecko; googleweblight) Chrome/38.0.1025.166 Mobile Safari/535.19"
66.249.83.84 - - [22/Apr/2020:14:05:02 +0200] "GET /es/wp-content/uploads/sites/3/2018/07/aziz-acharki-549137-unsplash-540x350.jpg HTTP/1.0" 200 10566 "https://neliosoftware.com/es/blog/imagenes-gratuitas-para-tu-blog/" "Mozilla/5.0 (Linux; Android 4.2.1; en-us; Nexus 5 Build/JOP40D) AppleWebKit/535.19 (KHTML, like Gecko; googleweblight) Chrome/38.0.1025.166 Mobile Safari/535.19"
66.249.83.82 - - [22/Apr/2020:14:05:02 +0200] "GET /es/wp-content/uploads/sites/3/2018/07/Screenshot-of-Unsplah-website-768x520.png HTTP/1.0" 200 399577 "https://neliosoftware.com/es/blog/imagenes-gratuitas-para-tu-blog/" "Mozilla/5.0 (Linux; Android 4.2.1; en-us; Nexus 5 Build/JOP40D) AppleWebKit/535.19 (KHTML, like Gecko; googleweblight) Chrome/38.0.1025.166 Mobile Safari/535.19"
...
188.79.17.218 - - [22/Apr/2020:14:06:14 +0200] "GET /es/blog/problemas-mas-comunes-de-wordpress/ HTTP/1.0" 200 110741 "https://www.google.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15"
188.79.17.218 - - [22/Apr/2020:14:06:16 +0200] "GET /es/wp-content/plugins/nelio-ab-testing/assets/dist/js/alternative-loader.js?version=52b0ff65c68ab39896d47d6ff673fd59 HTTP/1.0" 200 2763 "https://neliosoftware.com/es/blog/problemas-mas-comunes-de-wordpress/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15"
188.79.17.218 - - [22/Apr/2020:14:06:16 +0200] "GET /es/wp-includes/css/dist/block-library/style.min.css?ver=5.4 HTTP/1.0" 200 7627 "https://neliosoftware.com/es/blog/problemas-mas-comunes-de-wordpress/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/12.1.2 Safari/605.1.15"
...

Veamos con detalle la primera línea:

  • 66.249.83.82. Esto es la IP del dispositivo que hizo la petición.
  • 22/Apr/2020:14:04:59 +0200. A continuación vemos la fecha en la que se hizo dicha petición.
  • GET /es/blog/imagenes-gratuitas-para-tu-blog/ HTTP/1.0. Luego vemos que se trata de una petición de lectura (GET) pidiendo una entrada de nuestro blog.
  • Mozilla/5.0 (Linux; Android ... Esto es el User-Agent del dispositivo que hizo la petición y básicamente nos permite obtener información sobre la aplicación y el sistema operativo que hace la petición.

Si te fijas, lo interesante de este registro es que después de que la IP 66.249.83.82 acceda al blog, esa misma IP sigue haciendo peticiones a nuestro servidor, pero pidiendo recursos diferentes. Y es lógico: la entrada del blog que nos ha pedido incluye estilos, scripts e imágenes que necesita recuperar del servidor, así que las va pidiendo según las necesita.

Pues bien, en nuestro caso pudimos comprobar que, efectivamente, teníamos un número de peticiones inusualmente alto. Altísimo, de hecho. Una posible explicación sería que hubo un pico de visitas por algún motivo que desconocíamos… pero según Google Analytics dicho pico no existía. Así que estaba pasando algo diferente.

Un análisis más detallado del registro de acceso nos permitió identificar el siguiente hecho: más de un 15% de todas las peticiones que estábamos recibiendo venían de una misma IP. Y (redoble de tambores) esa IP era la del propio servidor: 35.214.244.124.

Identificando al culpable

Llegados a este punto por fin sabíamos que era el propio servidor el que lanzaba peticiones hacia nuestra web, forzando la ejecución de WordPress múltiples veces y elevando el consumo de recursos de forma anómala. Pero, ¿por qué? ¿Qué estaba pasando? ¿Quién estaba generando esas peticiones?

Lo primero que hicimos fue fijarnos únicamente en las peticiones que venían del servidor (filtrando por IP) para intentar identificar algún tipo de patrón:

35.214.244.124 - - [22/Apr/2020:14:06:08 +0200] "GET /es HTTP/1.0" 301 - "https://neliosoftware.com/es" "php-requests/1.7-3470169"
35.214.244.124 - - [22/Apr/2020:14:06:08 +0200] "GET /es?..." "php-requests/1.7-3470169"
35.214.244.124 - - [22/Apr/2020:14:06:18 +0200] "GET /es?..." "php-requests/1.7-3470169"
35.214.244.124 - - [22/Apr/2020:14:07:21 +0200] "GET /es?..." "php-requests/1.7-3470169"
35.214.244.124 - - [22/Apr/2020:14:07:24 +0200] "GET /es?..." "php-requests/1.7-3470169"
...

y lo encontramos: el User-Agent de todas las peticiones era php-requests/1.7-3470169.

Como imagino que ya sabes, WordPress dispone de varias funciones con las que hacer peticiones hacia fuera: wp_remote_request y compañía. Si echas un vistazo al código fuente de dichas funciones, verás que internamente usan los métodos de una clase llamada WP_Http y que, precisamente, dicha clase establece que, por defecto, todas las peticiones salientes de WordPress que usen las funciones antes mencionadas tendrán como User-Agent algo tipo «WordPress/versión». No está mal, pero no es el php-requests que queríamos…

Si seguimos tirando del hilo verás que WP_Http usa otra clase de WordPress internamente para hacer las peticiones hacia fuera: Requests. Y vaya si es interesante esta clase: vemos que define una constante VERSION cuyo valor es 1.7-3470169 y que se usa para construir el User-Agent por defecto que nos está dando guerra: php-requests/1.7-3470169.

¡Genial! Ya hemos confirmado que la petición sale efectivamente de WordPress. Así que estamos bastante seguros de que el culpable debe ser un plugin. ¿Pero cuál?

La idea que tuvimos para conocer qué plugin (o plugins) estaba generando tantas peticiones era bastante sencilla: hay que modificar el User-Agent para que incluya el nombre del plugin que está usando la clase Requests y, así, cuando recibamos peticiones al servidor y estas queden registradas en el registro de acceso, la sección de User-Agent incluirá ese nombre.

Conseguir esto es bastante más sencillo de lo que parece. Lo único que hicimos fue editar la función get_default_options de Requests con el siguiente fragmento de código:

$trace = debug_backtrace();
$files = [];
foreach ( $trace as $log ) {
  if ( false !== strpos( $log['file'], '/wp-content/plugins/' ) ) {
    $files[] = $log['file'];
  }
}

if ( empty( $files ) ) {
  $debug = 'no-plugin';
} else {
  $plugins = array_map( function( $x ) {
    return preg_replace(
      '/.*\/wp-content\/plugins\/([^\/]+)\/.*/',
      '$1',
      $x
    );
  }, $files );
  $plugins = array_unique( $plugins );
  $debug   = implode( ' ', $plugins );
}

$defaults['useragent'] .= " (NelioDebug {$debug})";

Veamos qué hace paso a paso:

  • Lo primero que hacemos es obtener la pila de ejecución con debug_backtrace. Esto es una función de PHP que nos da acceso a todas las funciones que se han ido llamando hasta llegar a la actual.
  • Para cada elemento de la pila de ejecución tenemos información como la función que se ha invocado, el fichero en la que está definida y su línea, los argumentos con los que se invocó, etc. Lo que nos interesa en este caso es el fichero en el que está definida, porque si es un fichero que está dentro de wp-content/plugins quiere decir que se trata de una función de un plugin.
  • Una vez hemos procesado todos los elementos de la pila, podemos repasar cuántos de ellos eran funciones de wp-content/plugins y podemos quedarnos con el nombre exacto del plugin aprovechando el hecho de que cada plugin tiene su propia carpeta.
  • Finalmente, extendemos el useragent con un pequeño texto que incluye los nombres de todos los plugins.

Y, efectivamente, si actualizamos el fichero en nuestro servidor y esperamos a que se actualice el registro de acceso, veremos que ahora aparece el nombre del culpable:

35.214.244.124 - - [23/Apr/2020:10:59:08 +0200] "GET /es HTTP/1.0" 301 - "https://neliosoftware.com/es" "php-requests/1.7-3470169 (NelioDebug culpable)"
35.214.244.124 - - [23/Apr/2020:10:59:20 +0200] "GET /?..." "php-requests/1.7-3470169 (NelioDebug culpable)"
35.214.244.124 - - [23/Apr/2020:10:59:36 +0200] "GET /?..." "php-requests/1.7-3470169 (NelioDebug culpable)"
35.214.244.124 - - [23/Apr/2020:11:00:01 +0200] "GET /es?..." "php-requests/1.7-3470169 (NelioDebug culpable)"
35.214.244.124 - - [23/Apr/2020:11:05:21 +0200] "GET /es?..." "php-requests/1.7-3470169 (NelioDebug culpable)"
...

Solucionando el problema

En este caso, una vez pudimos identificar al culpable, nos bastó con ponernos en contacto con su desarrollador para que nos ofreciera una solución. Y, efectivamente, después de aplicarla, las estadísticas mejoraron rápidamente:

Estadísticas de nuestra web después de corregir un problema con el uso de CPU
Estadísticas de nuestra web después de detectar el plugin que elevaba el uso de CPU.

Como puedes ver, una de las grandezas del software libre es que podemos explorar el código fuente de las aplicaciones que usamos y adaptarlo para nuestras necesidades. En este caso, pudimos modificar WordPress y convertirlo en un «chivato» que nos dijera qué estaba fallando.

Espero que te haya gustado el truco de usar debug_backtrace para descubrir quién es el que está forzando la ejecución de una cierta función. Soy consciente de que es un método poco ortodoxo, pero rápido de implementar y que en muchos casos nos da un acceso rápido a la respuesta que buscamos.

Imagen destacada de Michał Mancewicz en Unsplash.

Deja una respuesta

No publicaremos tu correo electrónico. Los campos obligatorios están marcados con: •

He leído y acepto la Política de privacidad de Nelio Software

Al marcar la casilla de aceptación estás dando tu legítimo consentimiento para que tu información personal se almacene en SiteGround y sea usada por Nelio Software con el propósito único de publicar aquí este comentario. Contáctanos para corregir, limitar, eliminar o acceder a tu información.