Отладка медленного WordPress сайта с помощью strace

Я пытаюсь докопаться до сайта WordPress, который работает очень медленно: при запросе страницы он зависает примерно на 20 секунд, прежде чем страница начинает загружаться.

Я пробовал обычные вещи: режим отладки WP, проверка медленных запросов MySQL, отключение плагинов, проверка того, что Apache не ставит запросы в очередь и т. Д., Без радости. Сейчас я прибегаю к наблюдению за процессом Apache (я использую PHP как mod_php) с помощью strace, чтобы увидеть, что происходит. К сожалению, мое ядро-фу слабое, и мне нужна помощь в интерпретации вывода strace.

Я запускаю strace с ключом -r, если я правильно понимаю страницы справочника, это будет указывать время, затраченное на предыдущий вызов sys.

Просматривая вывод, я вижу несколько вызовов, занимающих 5 секунд, например:

 0.000114 accept4(4, {sa_family=AF_INET6, sin6_port=htons(46242), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 13
 0.000116 getsockname(13, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
 0.000109 fcntl(13, F_GETFL)        = 0x2 (flags O_RDWR)
 0.000061 fcntl(13, F_SETFL, O_RDWR|O_NONBLOCK) = 0
 0.000078 read(13, "GET /wp-content/uploads/fake-ici"..., 8000) = 593
 0.000144 stat("/var/www/wp-content/uploads/fake-icicles-500x500.jpg", {st_mode=S_IFREG|0777, st_size=34241, ...}) = 0
 0.000197 open("/var/www/wp-content/uploads/fake-icicles-500x500.jpg", O_RDONLY|O_CLOEXEC) = 14
 0.000100 close(14)                 = 0
 0.000097 read(13, 0x7f66f397b048, 8000) = -1 EAGAIN (Resource temporarily unavailable)
 0.000079 writev(13, [{"HTTP/1.1 304 Not Modified\r\nDate:"..., 182}], 1) = 182
 0.000161 write(8, "127.0.0.1 - - [26/Oct/2016:14:17"..., 235) = 235
 0.000112 times({tms_utime=3107, tms_stime=70, tms_cutime=0, tms_cstime=0}) = 1802798719
 0.000090 poll([{fd=13, events=POLLIN}], 1, 5000) = 0 (Timeout)
 5.005144 shutdown(13, SHUT_WR)     = 0
 0.000130 poll([{fd=13, events=POLLIN}], 1, 2000) = 1 ([{fd=13, revents=POLLIN|POLLHUP}])
 1.000750 read(13, "", 512)         = 0

Моя интерпретация заключалась бы в том, что опрос дескриптора файла с идентификатором 13 занял 5 секунд и истек тайм-аут (4-я строка с конца). 13 выглядит как идентификатор сокета, который был открыт для записи ответа HTTP клиенту. Это правильно? Есть ли что-то еще, чему я могу научиться из вышесказанного? Должен ли я беспокоиться о "временно недоступном ресурсе" в read() в середине моего вывода?

Источник

1 ответ

Да, ваша интерпретация верна.

На самом деле, насколько я понимаю, вы видите HTTP KeepAlive.

Что просходит:

Вы получаете соединение и принимаете его с дескриптором файла = 13:

 0.000114 accept4(4, {sa_family=AF_INET6, sin6_port=htons(46242), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 13

Вы получаете запрос HTTP GET:

 0.000078 read(13, "GET /wp-content/uploads/fake-ici"..., 8000) = 593

Вы пишете ответ, в данном случае 304 "Не изменено", а не весь файл, так как запрос является условным GET, вероятно, из-за If-Modified-Since, поскольку я не вижу чтения в открытом файле, не уверен хоть):

 0.000079 writev(13, [{"HTTP/1.1 304 Not Modified\r\nDate:"..., 182}], 1) = 182

Вы пишете запись в файл журнала:

 0.000161 write(8, "127.0.0.1 - - [26/Oct/2016:14:17"..., 235) = 235

Затем вы ожидаете еще один запрос к тому же сокету из-за KeepAlive, который по умолчанию в Apache составляет 5 секунд:

 0.000090 poll([{fd=13, events=POLLIN}], 1, 5000) = 0 (Timeout)

Никакой другой запрос не приходит в течение интервала keepalive, поэтому вы начинаете закрывать TCP-соединение:

 5.005144 shutdown(13, SHUT_WR)     = 0

Что касается чтения, возвращающего -EAGAIN (ресурс временно недоступен), это нормально, проверьте здесь более подробное описание, чем у меня: https://stackoverflow.com/questions/10318191/reading-socket-eagain-resource-temporarily-unavailable

Источник
Другие вопросы по тегам