Проблема: Недавно я модернизировал один из своих серверов, он был протестирован перед использованием и работает хорошо, однако несколько дней назад я заметил, что количество операций записи в корневой том примерно в 4 раза больше обычного. Это не проблема производительности - сервер работает нормально.
Моя модернизация была довольно обширной (полная перестройка), поэтому мне нечего делать с точки зрения причины. Вкратце, мои изменения включали:
Базовая настройка:
free и iostat показать минимальное использование свопа).mount --bind). Базовый том EBS смонтирован в /mnt/dataНовая установка работает более плавно (быстрее, меньше памяти и т. Д.), Чем старая система, и была стабильной в течение 20 дней (середина октября) - насколько я могу судить, повышенные записи существовали все это время. .
Вопреки тому, что я ожидал, у меня низкий объем чтения (мои чтения составляют около 1,5% моих записей, как в единицах, так и в байтах на моем корневом томе). Я ничего не менял в корневом томе (например, новые установки и т. Д.) За последние несколько дней, но объем записи по-прежнему намного выше, чем ожидалось.
Задача: чтобы определить причину увеличения количества операций записи в корневой том (по сути, выяснить, является ли это процессом (и каким процессом), другой файловой системой (ext4) или другой проблемой (например, памятью)).
Системная информация:
Моментальные снимки корневого тома и тома данных делаются один раз в день, однако это должна быть операция «чтения», а не запись. (Кроме того, такая же практика использовалась на предыдущем сервере - и предыдущий сервер также был t1.micro.)
Данные, которые заставили меня изучить ввод-вывод, были в деталях моего последнего счета за AWS (который имел выше нормального ввода-вывода - не неожиданно, поскольку я настраивал этот сервер и устанавливал много вещей с самого начала. месяца), а затем в метриках CloudWatch для прикрепленных томов EBS. Я прихожу к «4-кратному нормальному» значению, экстраполируя активность ввода-вывода с ноября (когда я не менял сервер), чтобы оценить ежемесячное значение и сравнивая это с вводом-выводом за прошлые месяцы, когда я не работал на моем предыдущем сервере. (У меня нет точных данных iostat с моего предыдущего сервера). Такое же количество операций записи сохранялось до ноября, 170–330 МБ / час.
Диагностическая информация (время безотказной работы следующих выходов составляет 20,6 дня):
Метрики Cloudwatch:
Выход: df -h (только для корневого тома)
Filesystem Size Used Avail Use% Mounted on
/dev/xvda1 4.0G 1.2G 2.8G 31% /
Используемое пространство не увеличилось заметно с момента запуска этой системы (что, на мой взгляд, предполагает, что файлы обновляются, а не создаются / добавляются).
Выход: iostat -x (с участием Blk_read, Blk_wrtn добавлено):
Linux 2.6.35.14-95.38.amzn1.i686 11/05/2011 _i686_
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s Blk_read Blk_wrtn avgrq-sz avgqu-sz await svctm %util
xvdap1 0.00 3.42 0.03 2.85 0.72 50.19 2534636 177222312 17.68 0.18 60.93 0.77 0.22
xvdf 0.00 0.03 0.04 0.35 1.09 8.48 3853710 29942167 24.55 0.01 24.28 2.95 0.12
xvdg 0.00 0.00 0.00 0.00 0.02 0.04 70808 138160 31.09 0.00 48.98 4.45 0.00
Выход: iotop -d 600 -a -o -b
Total DISK READ: 6.55 K/s | Total DISK WRITE: 117.07 K/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
852 be/4 root 0.00 B 26.04 M 0.00 % 0.42 % [flush-202:1]
539 be/3 root 0.00 B 528.00 K 0.00 % 0.08 % [jbd2/xvda1-8]
24881 be/4 nginx 56.00 K 120.00 K 0.00 % 0.01 % nginx: worker process
19754 be/4 mysql 180.00 K 24.00 K 0.00 % 0.01 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
3106 be/4 mysql 0.00 B 176.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
19751 be/4 mysql 4.00 K 0.00 B 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
3194 be/4 mysql 8.00 K 40.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
3156 be/4 mysql 4.00 K 12.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
3099 be/4 mysql 0.00 B 4.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
24216 be/4 web14 8.00 K 10.43 M 0.00 % 0.00 % php-fpm: pool web14
24465 be/4 web19 0.00 B 7.08 M 0.00 % 0.00 % php-fpm: pool web19
3110 be/4 mysql 0.00 B 100.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
579 be/4 varnish 0.00 B 76.00 K 0.00 % 0.00 % varnishd -P /var/run/varnish.pid -a :80 -f /etc/varnish/default.vcl -T 127.0.0.1:6082 -t 3600 -w 1,1000,120 -u varnish -g varnish
582 be/4 varnish 0.00 B 144.00 K 0.00 % 0.00 % varnishd -P /var/run/varnish.pid -a :80 -f /etc/varnish/default.vcl -T 127.0.0.1:6082 -t 3600 -w 1,1000,120 -u varnish -g varnish
586 be/4 varnish 0.00 B 4.00 K 0.00 % 0.00 % varnishd -P /var/run/varnish.pid -a :80 -f /etc/varnish/default.vcl -T 127.0.0.1:6082 -t 3600 -w 1,1000,120 -u varnish -g varnish
587 be/4 varnish 0.00 B 40.00 K 0.00 % 0.00 % varnishd -P /var/run/varnish.pid -a :80 -f /etc/varnish/default.vcl -T 127.0.0.1:6082 -t 3600 -w 1,1000,120 -u varnish -g varnish
1648 be/4 nobody 0.00 B 8.00 K 0.00 % 0.00 % in.imapproxyd
18072 be/4 varnish 128.00 K 128.00 K 0.00 % 0.00 % varnishd -P /var/run/varnish.pid -a :80 -f /etc/varnish/default.vcl -T 127.0.0.1:6082 -t 3600 -w 1,1000,120 -u varnish -g varnish
3101 be/4 mysql 0.00 B 176.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
19749 be/4 mysql 0.00 B 32.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
19750 be/4 mysql 0.00 B 0.00 B 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
19752 be/4 mysql 0.00 B 108.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
19788 be/4 mysql 0.00 B 12.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock
853 be/4 root 4.00 K 0.00 B 0.00 % 0.00 % [flush-202:80]
22011 be/4 varnish 0.00 B 188.00 K 0.00 % 0.00 % varnishd -P /var/run/varnish.pid -a :80 -f /etc/varnish/default.vcl -T 127.0.0.1:6082 -t 3600 -w 1,1000,120 -u varnish -g varnish
Подводя итог вышеизложенному (и экстраполировав на дневные значения), это выглядит так, за 10-минутный период:
Интересно, что между [flush-202] и php-fpm можно учесть ежедневный объем операций записи.
С помощью ftop, Я не могу отследить flush или php-fpm пишет (например, ftop -p php-fpm.
По крайней мере, часть моей проблемы связана с определением того, какие процессы производят запись в корневой том. Я ожидаю, что все из перечисленных выше будут писать в том данных (поскольку соответствующие каталоги имеют там символические ссылки) (например, nginx, mysql, php-fpm, varnish все каталоги указывают на другой том EBS)
Я считаю JBD2 - блочное устройство журналирования для ext4, и flush-202 это фоновый сброс грязных страниц. В dirty_ratio 20 лет, а dirty_background_ratio равно 10. Грязная память (от /proc/meminfo) обычно составлял 50–150 КБ). Размер страницы (getconf PAGESIZE) - системное значение по умолчанию (4096).
Выход: vmstat -s | grep paged
3248858 страниц выгружено из 104625313 страниц
Выход: sar -B | grep Average
pgpgin/s pgpgout/s fault/s majflt/s pgfree/s pgscank/s pgscand/s pgsteal/s %vmeff
Average: 1.38 39.57 113.79 0.03 36.03 0.38 0.02 0.29 73.66
Вышеизложенное указывает на большое количество выгружаемых страниц, однако я ожидал, что страницы будут записаны в мой раздел подкачки, если это необходимо, а не в мой корневой том. Из общей памяти в системе обычно используется 35%, 10% - буферы, 40% - кэшировано, 15% - не используется (т.е. 65% свободно).
Выход: vmstat -d
disk- ------------reads------------ ------------writes----------- -----IO------
total merged sectors ms total merged sectors ms cur sec
xvda1 105376 14592 2548092 824418 10193989 12264020 179666824 626582671 0 7872
xvdf 126457 579 3882950 871785 1260822 91395 30081792 32634413 0 4101
xvdg 4827 4048 71000 21358 1897 15373 138160 307865 0 29
vmstat последовательно отображает si и so значения 0
Выход: swapon -s
Filename Type Size Used Priority
/dev/xvdg partition 1048572 9252 -1
На предположение, что операции ввода-вывода могут быть связаны с памятью, я отключил лак и перезапустил сервер. Это изменило мой профиль памяти на 10% в использовании, 2% в буферах и 20% в кеш-памяти, 68% неиспользуемых (т.е. 90% свободных). Однако после 10-минутного запуска iotop дал те же результаты, что и раньше:
За час, прошедший с момента перезапуска, в корневой том уже было записано 330 МБ, из которых выгружено 370 тыс. Страниц.
Выход inotifywatch -v -e modify -t 600 -r /[^mnt]*
Establishing watches...
Setting up watch(es) on /bin /boot /cgroup /dev /etc/ home /lib /local /lost+found /opt /proc /root /sbin /selinux /src /sys /usr /var
OK, /bin /boot /cgroup /dev /etc/ home /lib /local /lost+found /opt /proc /root /sbin /selinux /src /sys /usr /var is now being watched.
Total of 6753 watches.
Finished establishing watches, now collecting statistics.
Will listen for events for 600 seconds.
total modify filename
23 23 /var/log/
20 20 /usr/local/ispconfig/server/temp/
18 18 /dev/
15 15 /var/log/sa/
11 11 /var/spool/postfix/public/
5 5 /var/log/nginx/
2 2 /var/run/pure-ftpd/
1 1 /dev/pts/
Если посмотреть немного дальше на вышеизложенное, почти все операции записи могут быть отнесены к (неизвестному) процессу, который выполняется каждые 5 минут и проверяет состояние различных служб (например, chkservd на cPanel, но я не использую cPanel и не устанавливал это). Он составляет 4 файла журнала (cron, maillog, ftp, imapproxy), обновляемых в течение 10 минут, и несколько связанных элементов (сокеты postfix, соединения pure-ftpd). Остальные элементы - это в основном измененные сеансы ispconfig, обновления системного учета и недопустимые (несуществующее имя_сервера) попытки веб-доступа (зарегистрированные в / var / log / nginx).
Выводы и вопросы:
Позвольте мне начать с того, что я немного озадачен - я обычно довольно внимателен, но я чувствую, что упускаю что-то очевидное в этом вопросе. Ясно, flush и php-fpm приходится большая часть записей, однако я не знаю, почему это может быть так. Во-первых, возьмем php-fpm - он даже не должен писать в корневой том. Его каталоги (как файлы, так и журналы) связаны с другим томом EBS. Во-вторых, основными вещами, которые должен писать php-fpm, являются сеансы и кеши страниц, которых мало и мало - конечно, не порядка 1 МБ / мин (скорее, 1 КБ / мин, если это так). Большинство сайтов доступны только для чтения, с редкими обновлениями. Общий размер всех веб-файлов, измененных за последний день, составляет 2,6 МБ.
Во-вторых, учитывая сброс - значительные записи из него предполагают, что грязные страницы часто сбрасываются на диск - но, учитывая, что у меня обычно 65% свободной памяти и отдельный том EBS для пространства подкачки, я не могу объяснить, почему это влияют на записи в моем корневом томе, особенно в той степени, в которой это происходит. Я понимаю, что некоторые процессы будут записывать грязные страницы в свое собственное пространство подкачки (вместо использования системного пространства подкачки), но, конечно же, сразу после перезапуска, когда большая часть моей памяти свободна, я не должен сталкиваться с каким-либо значительным объемом грязные страницы. Если вы действительно считаете, что это причина, дайте мне знать, как я могу определить, какие процессы пишут в свое собственное пространство подкачки.
Вполне возможно, что вся идея грязных страниц - это просто отвлекающий маневр и совершенно не имеет отношения к моей проблеме (я надеюсь, что это действительно так). Если это так, то моя единственная другая идея, что есть что-то, связанное с журналированием ext4, чего не было в ext3. Кроме того, у меня сейчас нет идей.
Обновление (я):
6 ноября 2011 г .:
Устанавливать dirty_ratio = 10 и dirty_background_ratio = 5; обновлен с sysctl -p (подтверждено через / proc); повторить 10-минутный тест iotop с аналогичными результатами (flush записал 17MB, php-fpm написал 16MB, MySQL написал 1MB, а JBD2 написал 0.7MB).
Я изменил все символические ссылки, которые я настроил для использования mount --bind вместо. Повторно включил лак, перезапустил сервер; повторить 10-минутный тест iotop с аналогичными результатами (flush записал 12,5 МБ, php-fpm записал 11,5 МБ, Varnish написал 0,5 МБ, JBD2 написал 0,5 МБ, а MySQL написал 0,3 МБ).
Как и в предыдущем прогоне, мой профиль памяти был использован на 20%, в буферах 2% и на 58% в кэше, 20% не использовалось (т.е. на 80% свободно). На всякий случай моя интерпретация свободной памяти в этом контексте ошибочна, вот результат free -m (это t1.micro). общее количество используемых свободных общих буферов кэшировано Mem: 602478124 0 14 347 - / + буферов / кеш: 116 486 Swap: 1023 0 1023
Дополнительная информация: Вывод: dmesg | grep EXT4
[ 0.517070] EXT4-fs (xvda1): mounted filesystem with ordered data mode. Opts: (null)
[ 0.531043] EXT4-fs (xvda1): mounted filesystem with ordered data mode. Opts: (null)
[ 2.469810] EXT4-fs (xvda1): re-mounted. Opts: (null)
Я также запускал ftop и iotop одновременно и с удивлением заметил, что записи, появляющиеся в iotop, не появляются в ftop. Список ftop был отфильтрован до php-fpm, так как я мог довольно надежно запускать запись этого процесса. Я отметил около 2 МБ записей на просмотр страницы для php-fpm - и мне еще предстоит выяснить, что он, возможно, пишет - любые идеи по выяснению того, что пишется, будут оценены.
Я постараюсь отключить ведение дневника в следующие несколько дней и посмотрю, улучшит ли это положение вещей. Однако на данный момент я задаюсь вопросом, есть ли у меня проблема с вводом-выводом или проблема с памятью (или и то и другое), но мне сложно увидеть проблему с памятью, если она есть.
13 ноября 2011 г .:
Поскольку файловая система использует экстенты, было невозможно смонтировать ее как ext3, кроме того, попытки смонтировать ее как доступную только для чтения просто привели к ее перемонтированию как для чтения-записи.
В файловой системе действительно включено ведение журнала (журнал 128 МБ), как видно из следующего:
Выход: tune2fs -l /dev/sda1 | grep features
has_journal ext_attr resize_inode dir_index filetype needs_recovery extent flex_bg sparse_super large_file huge_file uninit_bg dir_nlink extra_isize
Согласно следующему, около 140 ГБ было записано на этот том чуть меньше месяца - всего около 5 ГБ в день.
Выход: dumpe2fs -h /dev/sda1
Filesystem volume name: /
Last mounted on: /
Filesystem UUID: af5a3469-6c36-4491-87b1-xxxxxxxxxxxx
Filesystem magic number: 0xEF53
Filesystem revision #: 1 (dynamic)
Filesystem features: has_journal ext_attr resize_inode dir_index filetype needs_recovery extent flex_bg sparse_super large_file huge_file uninit_bg dir_nlink extra_isize
Filesystem flags: signed_directory_hash
Default mount options: (none)
Filesystem state: clean
Errors behavior: Continue
Filesystem OS type: Linux
Inode count: 262144
Block count: 1048576
Reserved block count: 10478
Free blocks: 734563
Free inodes: 210677
First block: 0
Block size: 4096
Fragment size: 4096
Reserved GDT blocks: 511
Blocks per group: 32768
Fragments per group: 32768
Inodes per group: 8192
Inode blocks per group: 512
RAID stride: 32582
Flex block group size: 16
Filesystem created: Wed Sep 21 21:28:43 2011
Last mount time: Sun Nov 13 16:10:11 2011
Last write time: Sun Oct 16 16:12:35 2011
Mount count: 13
Maximum mount count: 28
Last checked: Mon Oct 10 03:04:13 2011
Check interval: 0 (<none>)
Lifetime writes: 139 GB
Reserved blocks uid: 0 (user root)
Reserved blocks gid: 0 (group root)
First inode: 11
Inode size: 256
Required extra isize: 28
Desired extra isize: 28
Journal inode: 8
First orphan inode: 18610
Default directory hash: half_md4
Directory Hash Seed: 6c36b2cc-b230-45e2-847e-xxxxxxxxxxx
Journal backup: inode blocks
Journal features: journal_incompat_revoke
Journal size: 128M
Journal length: 32768
Journal sequence: 0x0002d91c
Journal start: 1
Продолжая искать открытые файлы, я попробовал использовать fuser на корневом томе:
Выход: fuser -vm / 2>&1 | awk '$3 ~ /f|F/'
root 1111 Frce. dhclient
root 1322 frce. mysqld_safe
mysql 1486 Fr.e. mysqld
root 1508 Frce. dovecot
root 1589 Frce. master
postfix 1600 Frce. qmgr
root 1616 Frce. crond
root 1626 Frce. atd
nobody 1648 Frce. in.imapproxyd
postfix 1935 Frce. tlsmgr
root 2808 Frce. varnishncsa
root 25818 frce. sudo
root 26346 Fr.e. varnishd
postfix 26925 Frce. pickup
postfix 28057 Frce. smtpd
postfix 28070 Frce. showq
К сожалению, ничего неожиданного. На случай, если это произошло из-за базового оборудования, я восстановил вчерашний снимок корневого тома (за последний день ничего не изменилось) и заменил корневой том экземпляра новым. Как и ожидалось, это не повлияло на проблему.
Моим следующим шагом было бы удалить ведение журнала, однако я наткнулся на решение, прежде чем добраться до него.
Проблема заключалась в APC, использующем mmap с файловой поддержкой. Исправление этого сброшенного дискового ввода-вывода примерно в 35 раз - до (ориентировочно) 150 МБ / день (вместо 5 ГБ). Я все еще мог бы рассмотреть возможность удаления журналирования, поскольку это, по-видимому, основной оставшийся вклад в это значение, однако это число на данный момент вполне приемлемо. Шаги, предпринятые для получения заключения APC, опубликованы в ответе ниже.
Поскольку главной причиной, казалось, было ведение дневника, это был бы мой следующий шаг. Однако для того, чтобы убрать ведение журнала, мне нужно будет присоединить том EBS к другому экземпляру. Я решил протестировать процедуру, используя снимок (дневной давности), однако, прежде чем убрать ведение журнала, я повторно провел 10-минутный тест iotop (на тестовом экземпляре). К своему удивлению, я увидел нормальные (т. Е. Не завышенные) значения, и это был первый раз, когда flush-202 даже не значился в списке. Это был полностью функциональный экземпляр (я также восстановил снимки своих данных) - в корневом томе не было никаких изменений за 12 часов или около того с момента его создания. Все тесты показали, что на обоих серверах выполнялись одни и те же процессы. Это заставило меня поверить в то, что причина должна заключаться в некоторых запросах, которые обрабатывает «живой» сервер.
Глядя на различия между выходными данными iotop сервера, отображающего проблему, и, казалось бы, идентичного сервера, у которого не было проблем, единственными отличиями были flush-202 и php-fpm. Это заставило меня подумать, что, хотя это и далеко не все, возможно, это была проблема, связанная с конфигурацией PHP.
Эта часть была не идеальной, но поскольку ни одна из служб, работающих на реальном сервере, не пострадала от нескольких минут простоя, это не имело особого значения. Чтобы сузить проблему, все основные службы (postfix, dovecot, imapproxy, nginx, php-fpm, varnish, mysqld, varnishncsa) на живом сервере были остановлены, а тест iotop был перезапущен - не было повышенного ввода-вывода на диск. . Сервисы перезапускались 3 пакетами, оставив php-fpm до конца. После каждой партии перезапусков тест iotop подтверждал отсутствие проблем. После запуска php-fpm проблема вернулась. (Было бы достаточно легко смоделировать несколько запросов PHP на тестовом сервере, но на данный момент я не был уверен, что это действительно PHP).
К сожалению, без PHP сервер был бы бессмысленным, так что это не идеальный вывод. Однако, поскольку flush-202 вроде бы предлагал что-то, относящееся к памяти (несмотря на то, что у меня достаточно свободной памяти), я решил отключить APC. Повторный запуск теста iotop показал, что уровни дискового ввода-вывода в норме. Более внимательное изучение вопроса показало, что mmap был включен, и что apc.mmap_file_mask был установлен на /tmp/apc.XXXXXX (по умолчанию для этой установки). Этот путь устанавливает APC для использования mmap с файловой поддержкой. Просто закомментировав эту строку (с использованием по умолчанию - анонимной памяти) и повторно запустив тест iotop, проблема была решена.
Я до сих пор не знаю, почему ни один из запусков диагностики не идентифицировал записи как исходящие от php и идущие в файлы apc в каталоге / tmp. Единственный тест, в котором упоминался каталог / tmp, был lsofоднако перечисленные в нем файлы не существовали.