Я пытаюсь добраться до конца сайта WordPress, который работает очень медленно: при запросе страницы он зависает примерно на 20 секунд, прежде чем страница начнет загружаться.
Я пробовал обычные вещи: режим отладки WP, проверку медленных запросов MySQL, отключение плагинов, проверку того, что Apache не ставит запросы в очередь и т.д., без всякой радости. Теперь я прибег к наблюдению за процессом Apache (я запускаю PHP как mod_php) с помощью strace, пытаясь увидеть, что происходит. К сожалению, мое ядро-fu слабое, и мне нужна помощь в интерпретации вывода strace.
Я запускаю strace с -r, если я правильно понимаю страницы руководства, это будет указывать время, которое потребовалось для предыдущего системного вызова.
Просматривая вывод, я вижу несколько вызовов, которые занимают 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 () в середине вывода?
Да, ваша интерпретация верна.
На самом деле, насколько я понимаю, вы видите 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)
Никаких других запросов не поступает в течение интервала поддержки активности, поэтому вы начинаете закрывать TCP-соединение:
5.005144 shutdown(13, SHUT_WR) = 0
Что касается возврата чтения -EAGAIN (ресурс временно недоступен), это нормально, проверьте здесь лучшее описание, чем у меня: https://stackoverflow.com/questions/10318191/reading-socket-eagain-resource-tempoporary-unavailable#10318268