Linux с высоким iowait без активности блочных устройств
Мне трудно понять причину высокого iowait на моем сервере.
top:
%Cpu(s): : 30.0 us, 5.4 sy, 0.0 ni, 53.9 id, 10.1 wa, 0.0 hi, 0.7 si, 0.0 st
iostat:
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 1.00 0.00 0.80 0.00 7.20 18.00 0.00 0.25 0.00 0.25 0.25 0.02
iotop:
Total DISK READ : 0.00 B/s | Total DISK WRITE : 0.00 B/s
Actual DISK READ: 0.00 B/s | Actual DISK WRITE: 0.00 B/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
4807 be/4 daemon 0.00 B/s 0.00 B/s 0.00 % 21.66 % httpd -k restart
4522 be/4 daemon 0.00 B/s 0.00 B/s 0.00 % 10.76 % httpd -k restart
4547 be/4 daemon 0.00 B/s 0.00 B/s 0.00 % 7.87 % httpd -k restart
4603 be/4 daemon 0.00 B/s 0.00 B/s 0.00 % 7.66 % httpd -k restart
4652 be/4 daemon 0.00 B/s 0.00 B/s 0.00 % 5.36 % httpd -k restart
4671 be/4 daemon 0.00 B/s 0.00 B/s 0.00 % 4.83 % httpd -k restart
похоже, что все операции ввода-вывода генерируются httpd, но на sda нет никаких действий, и на сервере больше нет жестких или сетевых дисков.
я пробовал strace на httpd:
Process 4975 attached
accept4(4, {sa_family=AF_INET6, sin6_port=htons(60547), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28], SOCK_CLOEXEC) = 9
getsockname(9, {sa_family=AF_INET6, sin6_port=htons(8080), inet_pton(AF_INET6, "::ffff:127.0.0.1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
fcntl(9, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(9, "GET /category/toys/ HTTP/1.0\r"..., 8000) = 287
stat("/srv/www/website/category/toys/", 0x7ffff11072d0) = -1 ENOENT (No such file or directory)
lstat("/srv", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/srv/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/srv/www/website", {st_mode=S_IFDIR|0755, st_size=20480, ...}) = 0
lstat("/srv/www/website/category", 0x7ffff11072d0) = -1 ENOENT (No such file or directory)
stat("/srv/www/website/index.php", {st_mode=S_IFREG|0644, st_size=39274, ...}) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={6000000, 0}}, NULL) = 0
rt_sigaction(SIGPROF, {0x7f4329cbc270, [PROF], SA_RESTORER|SA_RESTART, 0x7f432a7bd650}, {0x7f4329cbc270, [PROF], SA_RESTORER|SA_RESTART, 0x7f432a7bd650}, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
getcwd("/", 4095) = 2
chdir("/srv/www/website") = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={1000000, 0}}, NULL) = 0
fcntl(7, F_SETLK, {type=F_RDLCK, whence=SEEK_SET, start=1, len=1}) = 0
getcwd("/srv/www/website", 4096) = 17
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 10
connect(10, {sa_family=AF_LOCAL, sun_path="/tmp/memcached2.sock"}, 110) = 0
sendto(10, "get memc.sess.key.ee3e1a44ced404"..., 52, MSG_NOSIGNAL, NULL, 0) = 52
recvfrom(10, "VALUE memc.sess.key.ee3e1a44ced4"..., 8196, MSG_NOSIGNAL, NULL, NULL) = 175
socket(PF_LOCAL, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 11
connect(11, {sa_family=AF_LOCAL, sun_path="/tmp/memcached.sock"}, 110) = 0
sendto(11, "get 389768020cec2648767316c7233f"..., 38, MSG_NOSIGNAL, NULL, 0) = 38
recvfrom(11, "VALUE 389768020cec2648767316c723"..., 8196, MSG_NOSIGNAL, NULL, NULL) = 8196
recvfrom(11, "\0\"\345\22\315\00230:\374\16u\205\315\360\23\375\00050\376\0009\353\0\250\342\n\213\353Si"..., 8196, MSG_NOSIGNAL, NULL, NULL) = 8196
recvfrom(11, "px#f =\7body><tr@\v\0d \4\1ul \4\1li\304\36\2"..., 8196, MSG_NOSIGNAL, NULL, NULL) = 4629
sendto(11, "quit\r\n", 6, MSG_NOSIGNAL, NULL, 0) = 6
shutdown(11, SHUT_WR) = 0
shutdown(11, SHUT_RD) = 0
close(11) = 0
writev(9, [{"HTTP/1.1 200 OK\r\nDate: Mon, 11 M"..., 246}, {"<!DOCTYPE html> <html lang=\"en\">"..., 107113}], 2) = 107359
chdir("/") = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
sendto(10, "set memc.sess.key.ee3e1a44ced404"..., 175, MSG_NOSIGNAL, NULL, 0) = 175
recvfrom(10, "STORED\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 8
sendto(10, "quit\r\n", 6, MSG_NOSIGNAL, NULL, 0) = 6
shutdown(10, SHUT_WR) = 0
shutdown(10, SHUT_RD) = 0
close(10) = 0
fcntl(7, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
writev(9, [{"<!-- static content | last modif"..., 60}], 1) = 60
times({tms_utime=40554, tms_stime=8627, tms_cutime=0, tms_cstime=0}) = 456014999
shutdown(9, SHUT_WR) = 0
poll([{fd=9, events=POLLIN}], 1, 2000) = 1 ([{fd=9, revents=POLLIN|POLLHUP}])
read(9, "", 512) = 0
close(9) = 0
read(5, 0x7ffff1107697, 1) = -1 EAGAIN (Resource temporarily unavailable)
accept4(4,
он делает совсем немного lstats для всей структуры каталогов, несмотря на правило перезаписи, чтобы направить все запросы на index.php, но возможно ли, что эти простые lstats отвечают за такой огромный iowait? Он также имеет некоторую связь с memcached серверами через сокет unix, но, насколько я понял, связь с сокетом unix не считается iowait.
Сервер делает около 200req/sec только с динамическим контентом, но весь этот контент буферизируется в ОЗУ (без необходимости подкачки и оперативной памяти 64G), и он ничего не читает с накопителя, так почему iowait так высок?
Как я могу диагностировать эту проблему? Это какой-либо способ измерения вызовов нескольких процессов httpd, которые увеличивают iowait, когда почти не используется блочное устройство?
Обновление 1: сервер находится в сети 1GE со скоростью ~10 Мбит / с без ошибок.
Обновление 2:strace -c -f -p:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
46.39 0.006063 1 10330 poll
26.66 0.003485 0 10212 71 recvfrom
7.98 0.001043 1 880 sendto
5.03 0.000658 2 294 109 connect
2.39 0.000313 1 294 socket
2.10 0.000274 1 338 close
1.45 0.000189 1 341 43 read
1.44 0.000188 4 43 accept4
1.40 0.000183 0 509 fcntl
1.26 0.000165 3 52 writev
0.83 0.000109 1 193 shutdown
0.55 0.000072 1 84 chdir
0.42 0.000055 0 168 setitimer
0.41 0.000053 1 73 stat
0.33 0.000043 1 43 getsockname
0.25 0.000033 0 116 rt_sigaction
0.24 0.000032 0 72 getcwd
0.21 0.000028 0 109 getsockopt
0.21 0.000027 0 60 lstat
0.16 0.000021 0 106 setsockopt
0.11 0.000014 0 43 times
0.08 0.000010 0 42 rt_sigprocmask
0.05 0.000007 7 1 select
0.02 0.000003 1 5 access
0.02 0.000002 0 6 brk
0.00 0.000000 0 1 open
0.00 0.000000 0 1 mmap
0.00 0.000000 0 1 munmap
------ ----------- ----------- --------- --------- ----------------
100.00 0.013070 24417 223 total
это результат работы strace -c в течение одной минуты, но я до сих пор не могу найти ничего, что могло бы генерировать такой высокий iowait...
Обновление 3:
Я изменил конфигурацию httpd и переместил RewriteRules из каталога в область VirtualHost, чтобы я мог отключить FollowSymLinks и сохранил некоторые дополнительные вызовы lstat для каждого запроса из:
stat("/srv/www/website/category/toys/", 0x7ffff11072d0) = -1 ENOENT (No such file or directory)
lstat("/srv", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/srv/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/srv/www/website", {st_mode=S_IFDIR|0755, st_size=20480, ...}) = 0
lstat("/srv/www/website/category", 0x7ffff11072d0) = -1 ENOENT (No such file or directory)
stat("/srv/www/website/index.php", {st_mode=S_IFREG|0644, st_size=39274,
чтобы просто:
stat("/srv/www/website/index.php", {st_mode=S_IFREG|0644, st_size=39274, ...}) = 0
lstat("/srv/www/website/index.php", {st_mode=S_IFREG|0644, st_size=39274, ...}) = 0
но влияние на IO отсутствует. Я также заметил, что примерно через 10 секунд после перезапуска httpd (запросы http обрабатываются все это время) iowait находится на уровне 0-1%, а затем повышается - может быть, это может быть подсказкой?
Обновление 4
Я изменил минимальные запасные серверы с 280 на 64, и iowait был уменьшен до 1%. Это может быть связано с табло, как упомянул Кэмерон Керр, или с общением между родителями и детьми, но насколько я прочитал "Apache httpd сначала пытается создать табло полностью в памяти", и мои экземпляры apache не используют табло на основе файлов.
Кто-нибудь имеет представление, почему количество резервных процессов prefork оказывает такое большое влияние на iowait (20% против 2% для 280 против 64 резервных процессов)?