Поиск виновника высокой загрузки ЦП на нашем сервере WordPress

Несколько дней назад мы получили электронное письмо от нашего хостинг-провайдера (SiteGround), в котором сообщалось, что наш сайт уже имеет «90% разрешенного ежемесячного использования ЦП» и что, как только мы превысим 100%, «веб-сервис будет ограничен». и у нас могут быть «проблемы с доступом к нему». Довольно пугающе, правда? Это определенно была совершенно нежелательная ситуация, которую мы должны были исправить как можно скорее. Но… с чего начать?

Сегодня мы хотели поделиться с вами нашим опытом решения довольно распространенной проблемы на веб-сайтах, объяснив, что мы сделали, чтобы определить виновника и как мы решили проблему. Таким образом, если вы столкнетесь с похожей проблемой, у вас будет несколько идей о том, как начать…

Причины, по которым у вас может быть высокая загрузка ЦП

WordPress — это система управления контентом, написанная на PHP. Это означает, что контент, который он обслуживает, генерируется динамически с помощью набора PHP-скриптов: каждый раз, когда посетитель заходит на ваш сайт, WordPress обрабатывает запрос (что-то вроде «пожалуйста, пришлите мне вашу домашнюю страницу») и генерирует ответ (в в этом случае он отправляет домашнюю страницу). Понятно, что ответ на запрос предполагает определенное использование ресурсов сервера: нужно просмотреть сам запрос, определить, к чему хочет получить доступ посетитель, получить это из базы данных, сгенерировать HTML-ответ и так далее.

Одна из причин, по которой система кэширования ускоряет время загрузки вашего веб-сайта, теперь должна быть совершенно очевидной: она в основном экономит время обработки. Когда в первый раз поступает конкретный запрос («отправьте мне свою домашнюю страницу»), WordPress запускается и генерирует ответ. Если есть кеш, он сохраняет указанный ответ до того, как он будет отправлен посетителю. Таким образом, будущие запросы к тому же ресурсу (в нашем примере, домашней странице) больше не требуют обработки WordPress; кеш может вернуть ранее сохраненную копию, тем самым экономя время и ресурсы.

Имея в виду эту производительность, нетрудно представить, по каким причинам мы можем наблюдать высокую загрузку ЦП на нашем сервере:

• Вы получаете слишком много запросов. Если на ваш сайт одновременно заходит много пользователей или вы получаете много нелегитимных запросов (вероятно, кто-то атакует ваш сервер), WordPress придется обрабатывать все эти запросы и, следовательно, использование ресурсов сервера возрастет.
• Запросы выполняются медленно. Если у вас установлено много плагинов или некоторые из ваших плагинов по какой-то причине неэффективны, все запросы, которые вы получаете, будут занимать больше времени, чем нужно, потому что WordPress будет запускать много неэффективного кода.

Так что похоже, что кеш — хорошая защита от этих проблем, верно? И это действительно так. Однако имейте в виду, что кеш не «исправляет» проблему; он просто «скрывает» это. И это важно помнить, потому что есть функциональные возможности WordPress, которые не могут быть кэшированы и, следовательно, всегда требуют запуска WordPress:

• Задачи, запланированные с помощью WP-Cron. WP-Cron — это механизм WordPress для планирования задач, которые будут выполняться в будущем. Например, WordPress использует его для публикации запланированных сообщений.
• REST API WordPress. REST API — это интерфейс, который можно использовать в сторонних приложениях для взаимодействия с сайтом WordPress путем отправки и получения объектов JSON. Некоторые запросы REST API могут кэшироваться (а именно запросы GET), а другие нет (POST и PUT). Следовательно, это то, что вы обычно не можете кэшировать…
• AJAX-запросы в WordPress. До того, как у нас появился REST API в WordPress, нам приходилось использовать его AJAX API для создания динамических веб-сайтов. Этот API очень похож на REST API, потому что мы также можем использовать его для отправки и получения информации с сервера. Это другая система, но на нее распространяются те же ограничения, что и на REST API.

Анализ проблемы

Сначала мы должны определить, почему на нашем веб-сайте увеличилась загрузка ЦП. Увеличилось ли количество запросов на наш сайт? Стало ли медленнее обслуживать отдельные запросы? Чтобы ответить на эти вопросы, на нашем сервере есть очень полезный инструмент: журнал доступа .

Журнал доступа представляет собой текстовый файл, в котором сервер регистрирует каждый запрос, который он получает, вместе с полезной информацией о них. В частности, журнал доступа сообщает нам, когда был получен запрос (дата и время), кто его сделал (IP-адрес), какой ресурс он запросил (URL-адрес), был ли запрос успешным и т. д. Вот пример с нашего сервера. :

 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" ...

Давайте рассмотрим его поближе:

• 66.249.83.82 . Это IP-адрес устройства, отправившего запрос.
• 22/Apr/2020:14:04:59 +0200 . Это точная дата и время запроса.
• GET /es/blog/imagenes-gratuitas-para-tu-blog/ HTTP/1.0 . Затем мы видим, что посетитель запросил ( GET ) сообщение из нашего блога (на испанском языке).
• Mozilla/5.0 (Linux; Android ... Это пользовательский агент браузера, который дает нам некоторую информацию об устройстве и операционной системе, выполнившей запрос.

Обратите внимание, как наш сервер получил несколько запросов с одного и того же IP-адреса ( 66.249.83.82 ) после первого. Это может выглядеть как атака, но на самом деле это не так: веб-страницы обычно содержат несколько ресурсов (изображения, скрипты, стили), и совершенно нормально, что посетитель, обращающийся к определенной веб-странице на вашем сайте, будет выполнять несколько запросов, чтобы получить их все. .

Что ж, в нашем случае мы смогли убедиться, что у нас действительно было необычно большое количество запросов. Чрезвычайно высокий, на самом деле. И мы знали это, потому что файл журнала был намного больше, чем обычно.

Возможным объяснением может быть то, что по какой-то причине был пик посещений… но, согласно Google Analytics, это не так. Значит, происходило что-то другое.

Более подробный анализ лога доступа позволил выявить следующий факт: более 15% всех запросов, которые мы получали, пришли с одного и того же IP. И (барабанная дробь) этот IP был нашим собственным веб-сервером!

Выявление виновника

В этот момент мы, наконец, поняли, что это был наш собственный сервер, который делал так много запросов, что это привело к пиковой нагрузке на ЦП. Но почему? Почему это происходило? Кто генерировал эти запросы? На эти вопросы сложнее ответить.

Сначала мы снова просмотрели наши журналы, отфильтровав их по IP и попытавшись определить закономерность, которая могла бы пролить свет на рассматриваемую проблему:

 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" ...

и мы нашли один: User-Agent всех этих аномальных запросов был php-requests/1.7-3470169 . Интересно!

В WordPress есть несколько функций для запуска запросов: wp_remote_request . Если вы посмотрите на исходный код этих функций, вы увидите, что они в основном оборачивают несколько методов из класса с именем WP_Http . Этот класс интересен тем, что по умолчанию все запросы, которые он делает, устанавливают для User-Agent значение «WordPress/версия», так что вполне возможно, что это как-то связано с нашей проблемой. Но этого не произошло… пока.

Если мы продолжим изучать исходный код WordPress, мы увидим, что WP_Http использует другой класс WordPress внутри для выполнения запросов: Requests . И мальчик, этот класс интересен: в самом начале его определения мы видим, что он определяет константу с именем VERSION , значение которой равно 1.7-3470169 . И чуть позже он использует эту константу для создания User-Agent , который мы нашли в наших логах: php-requests/1.7-3470169 .

Великолепно! Теперь мы подтвердили, что все эти странные запросы, которые мы получаем, исходят от нашего сайта WordPress. Вероятно, это означает, что виновником является плагин… но какой именно?

Идея, которую мы должны были понять, была довольно проста: если мы изменим User-Agent так, чтобы он включал имя плагина, который использует класс Requests , мы увидим имя плагина в журнале доступа нашего сервера. А добиться этого на самом деле довольно легко. Все, что мы сделали, это отредактировали функцию get_default_options Requests следующим фрагментом:

 $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})";

Давайте посмотрим, что он делает шаг за шагом:

• Сначала мы получаем стек выполнения с помощью debug_backtrace . Это функция PHP, которая генерирует обратную трассировку, показывая все функции, которые были вызваны для достижения текущей.
• Для каждого элемента в стеке выполнения у нас есть такая информация, как вызываемая функция, файл и строка, в которых она определена, аргументы, с которыми она была вызвана, и т. д. Однако мы хотим сосредоточиться на том, файл, в котором была определена функция: если он находится в wp-content/plugins , мы точно знаем, что это функция, определенная в плагине.
• Как только мы обработали все элементы в стеке, нам просто нужно получить имена (если они есть) всех плагинов, которые мы нашли, и включить их в переменную useragent .

После расширения WordPress, как описано, мы быстро начали понимать, кто виноват :

 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 culprit)" 35.214.244.124 - - [23/Apr/2020:10:59:20 +0200] "GET /?..." "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:10:59:36 +0200] "GET /?..." "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:11:00:01 +0200] "GET /es?..." "php-requests/1.7-3470169 (NelioDebug culprit)" 35.214.244.124 - - [23/Apr/2020:11:05:21 +0200] "GET /es?..." "php-requests/1.7-3470169 (NelioDebug culprit)" ...

Решение проблемы

Как только мы узнали название плагина-нарушителя, мы просто связались с его разработчиком и попросили о помощи. Они ответили и рассказали нам, как решить проблему, пока работали над правильным решением. К счастью для нас, все быстро пошло на поправку:

Как видите, одна из замечательных особенностей свободного программного обеспечения заключается в том, что мы можем исследовать исходный код приложений, которые мы используем, и адаптировать его к нашим потребностям. В этом случае мы смогли изменить сам WordPress, чтобы он мог раскрыть некоторую необходимую нам информацию.

Надеюсь, вам понравился трюк с использованием debug_backtrace , чтобы узнать, кто запускает определенную функцию. Конечно, это не ортодоксальный метод, но его легко реализовать, и до сих пор он всегда оказывался чрезвычайно полезным.

Избранное изображение Михала Манцевича на Unsplash.