В предыдущем блоге мы уже рассмотрели возможные нетипичные проблемы сервера MySQL и способы их выявления. Теперь соберем полученные знания в некую инструкцию (кейс) по поиску и устранению проблем с базой данных MysQL. Рассмотрим процесс диагностики редко возникающих проблем с производительностью на примере конкретной ситуации. В этом кейсе мы заберемся в неизвестную вам область, если вы не эксперт в MySQL, InnoDB и GNU/Linux. Однако основная идея этого кейса в другом. Попытайтесь найти метод в безумии: прочитайте этe раздел, ориентируясь на сделанные нами предположения и догадки. Рассмотрите подходы, основанные на рассуждениях и измерениях. Мы детально вникаем в конкретный случай лишь для иллюстрации общих положений.
Прежде чем приступить к решению проблемы, откликаясь на чью-то просьбу, стоит попробовать прояснить две вещи, желательно делая заметки, чтобы не забыть о чем- то важном.
- В чем заключается проблема? Постарайтесь выяснить это. Удивительно легко начать охоту не за той проблемой. В данном случае клиент жаловался, что один раз в день или раз в два дня сервер отклоняет соединения, выдавая ошибку
max_connections. Проблема появляется периодически и длится от нескольких секунд до нескольких минут. - Что было сделано в попытке это исправить? В данном случае клиент вообще не пытался решить проблему. Слушая о проблеме в изложении другого, очень трудно понять, какова точная последовательность событий, в чем заключаются изменения, которые эти события повлекли за собой, и каков результат их воздействия. Это особенно верно, когда человек в отчаянии после пары бессонных ночей и до краев налитых кофеином дней. На сервере, с которым происходили неизвестные изменения с неизвестным эффектом, очень сложно устранять неполадки, особенно в цейтноте.
Обсудив эти моменты, приступим. Стоит не только попытаться понять, как ведет себя сервер, но и оценить его состояние, конфигурацию, программное обеспечение и оборудование. Мы сделали это с помощью инструментов pt-summary и pt-mysql-summary. На этом сервере были 16-ядерный процессор, 12 Гбайт ОЗУ и всего 900 Мбайт данных, все в InnoDB, на твердотельном диске. На сервере запущена GNU/Linux с MySQL 5.1.37 и плагином InnoDB версии 1.0.4. Ранее мы работали с этим клиентом, решая другие неожиданные проблемы с производительностью, и знали систему. В прошлом с базой данных никогда не было проблем — проблемы всегда возникали в приложении. Мы посмотрели на сервер и с первого взгляда не обнаружили ничего очевидного. Запросы не были идеальными, но в большинстве случаев все еще выполнялись быстрее 10 миллисекунд. Таким образом мы убедились, что в нормальных условиях сервер работал хорошо. (Это необходимо сделать — многие появляющиеся время от времени проблемы оказываются симптомами хронических проблем, таких как сбой жестких дисков в RAID-массивах.)
Этот кейс может оказаться немного утомительным. Мы будем валять дурака, чтобы показать все диагностические данные, подробно объяснить все, что обнаружили, и проследить разные направления мысли. На самом деле не используем столь удручающе медленный подход к решению проблемы и не пытаемся сказать, что вам это нужно.
Мы установили диагностический пакет и в качестве триггера выбрали Threads_ connected, значение которого обычно составляет менее 15, но во время этих проблем увеличивалось до нескольких сотен. Покажем, пока без комментариев, выборку данных, которые мы получили. Посмотрите, сможете ли вы выбрать важное для дальнейшего анализа.
- Активность работы варьировалась от 1000 до 10 000 запросов в секунду, причем многие из них были мусорными командами, например пингование сервера для проверки того, работает ли он. Среди остальных преобладали команды
SELECT— от 300 до 2000 в секунду. Также было немного командUPDATE(около пяти в секунду). - В команде
SHOW PROCESSLISTбыло два основных типа запросов, различающихся только параметрами в разделеWHERE. Приведем обобщенные состояния запросов:
$ grep State: processlist.txt | sort | uniq -c | sort -rn
161 State: Copying to tmp table
156 State: Sorting result
136 State: statistics
50 State: Sending data
24 State: NULL
13 State:
7 State: freeing items
7 State: cleaning up
1 State: storing result in query cache
1 State: end- Большинство запросов сканировали индексы или диапазоны — полнотабличных и сканирований по кросс-соединениям не было.
- Во время работы происходило от 20 до 100 сортировок в секунду, при этом сортировалось от 1000 до 12 000 рядов в секунду.
- Во время работы создавалось от 12 до 90 временных таблиц в секунду, в том числе от 3 до 5 — на диске.
- Не было проблем с блокировкой таблиц или кэшем запросов.
- Выполнив команду
SHOW INNODB STATUS, мы заметили, что состоянием главного потока является сброс страниц буферного пула, но имелось всего несколько десятков «грязных» страниц для сброса (Innodb_buffer_pool_pages_dirty), практически не было изменений вInnodb_buffer_pool_pages_flushed, а разница между порядковым номером последней записи в журнале и последней контрольной точкой оказалась небольшой. Буферный пул InnoDB даже не приблизился к заполнению — он был намного больше размера данных. Большинство потоков ожидали в очереди InnoDB: «12 запросов внутри InnoDB, 495 запросов в очереди». - Мы зафиксировали вывод утилиты
iostatв течение 30 секунд, одну выборку в секунду. Он показал, что на дисках практически не было чтения, а записей — выше крыши. При этом среднее время ожидания ввода/вывода и длина очереди были чрезвычайно высокими. Приведем фрагмент вывода, немного упростив его, чтобы он поместился на странице без переносов:
r/s w/s rsec/s wsec/s avgqu-sz await svctm %util
1.00 500.00 8.00 86216.00 5.05 11.95 0.59 29.40
0.00 451.00 0.00 206248.00 123.25 238.00 1.90 85.90
0.00 565.00 0.00 269792.00 143.80 245.43 1.77 100.00
0.00 649.00 0.00 309248.00 143.01 231.30 1.54 100.10
0.00 589.00 0.00 281784.00 142.58 232.15 1.70 100.00
0.00 384.00 0.00 162008.00 71.80 238.39 1.73 66.60
0.00 14.00 0.00 400.00 0.01 0.93 0.36 0.50
0.00 13.00 0.00 248.00 0.01 0.92 0.23 0.30
0.00 13.00 0.00 408.00 0.01 0.92 0.23 0.30- Вывод утилиты
vmstatподтвердил то, что мы видели вiostat, и показал, что процессоры в основном бездействуют, за исключением некоторого ожидания ввода/ вывода во время всплеска записи (до 9 % ожидания).
Мозги еще не закипели? Это быстро происходит, когда вы глубоко погружаетесь в систему и у вас нет никаких предубеждений (или вы пытаетесь игнорировать их), поэтому в итоге смотрите на все. Большинство того, что вы увидите, либо совершенно нормально, либо показывает последствия проблемы, но ничего не говорит о ее источнике. Хотя в данном случае у нас есть некоторые догадки о причине проблемы, продолжим исследование, обратившись к отчету oprofile. Но сейчас мы не только вывалим на вас новые данные, но и добавим к ним комментарии и интерпретацию:
samples % image name app name symbol name
473653 63.5323 no-vmlinux no-vmlinux /no-vmlinux
95164 12.7646 mysqld mysqld /usr/libexec/mysqld
53107 7.1234 libc-2.10.1.so libc-2.10.1.so memcpy
13698 1.8373 ha_innodb.so ha_innodb.so build_template()
13059 1.7516 ha_innodb.so ha_innodb.so btr_search_guess_on_hash
11724 1.5726 ha_innodb.so ha_innodb.so row_sel_store_mysql_rec
8872 1.1900 ha_innodb.so ha_innodb.so rec_init_offsets_comp_ordinary
7577 1.0163 ha_innodb.so ha_innodb.so row_search_for_mysql
6030 0.8088 ha_innodb.so ha_innodb.so rec_get_offsets_func
5268 0.7066 ha_innodb.so ha_innodb.so cmp_dtuple_rec_with_matchДалеко не очевидно, что скрывается за большинством этих наборов символов, и большую часть времени они болтаются вместе в ядре и в наборе символов mysqld, который ни о чем нам не говорит. Не отвлекайтесь на все эти обозначения ha_innodb.so. Посмотрите на процент времени, которое они тратят: независимо от того, что они делают, это занимает так мало времени, что можно быть уверенными: не это источник проблемы. Перед нами пример проблемы, которую мы не решим с помощью анализа профиля. Мы смотрим на неверные данные. Когда вы видите что-то похожее на предыдущую выборку, продолжайте исследование, возьмите другие данные — возможно, там будет более очевидное указание на причину проблемы.
А сейчас, если вам интересен анализ ожиданий с помощью трассировки стека утилитой gdb, обратитесь к концу предыдущего раздела. Приведенная там выборка взята из системы, которую мы сейчас диагностируем. Если помните, основная часть трассировок стека просто ждала входа в ядро InnoDB, что соответствует 12 запросам внутри InnoDB, 495 запросам в очереди, полученным в результатах, выведенных командой SHOW INNODB STATUS.
Видите ли вы что-нибудь, явно указывающее на конкретную проблему? Мы не увидели — обнаружили лишь возможные симптомы множества проблем и по меньшей мере две их потенциальные причины. При этом мы опирались на интуицию и свой опыт. А еще заметили нечто не имеющее смысла. Если вы снова посмотрите на вывод утилиты iostat, то в столбце wsec/s увидите, что в течение примерно 6 секунд сервер записывает на диски сотни мегабайт данных в секунду. Каждый сектор состоит из 512 байт, поэтому выборка свидетельствует о том, что за секунду порой записывается до 150 Мбайт. Но вся база данных содержит всего 900 Мбайт, а рабочая нагрузка — это в основном запросы SELECT. Как такое могло произойти?
Исследуя систему, постарайтесь задать себе вопрос, есть ли что-то, что просто не сходится, и разберите это подробнее. Старайтесь доводить ход мысли до конца и не слишком часто отвлекаться на смежные темы, иначе просто можете забыть о многообещающих идеях. Делайте небольшие заметки и просматривайте их, чтобы убедиться, что вы расставили все точки над «i».
На этом этапе мы могли бы перескочить прямо к выводу, но это было бы неверно. Из состояния основного потока видно, что InnoDB пытается сбросить «грязные» страницы, которые обычно не отображаются в выводе состояния, если только сброс не откладывается. Мы знаем, что эта версия InnoDB подвержена проблеме яростного сброса, известной также как стопор контрольной точки. Это то, что происходит, когда InnoDB не выполняет сбросы равномерно в течение некоторого времени, а неожиданно решает вынудить контрольную точку сделать это (очистить много данных). Это может вызвать серьезную блокировку внутри InnoDB, заставив все процессы встать в очередь и ждать входа в ядро, и, таким образом, образовать пробку на уровнях выше InnoDB на сервере. Большинство симптомов, наблюдаемых на этом сервере, похожи на то, что происходит при принудительной установке контрольной точки, но в данном случае проблема в другом. Это можно доказать разными способами, самый, вероятно, простой из которых — посмотреть на счетчики команды SHOW STATUS и отследить изменения в счетчике Innodb_buffer_pool_pages_flushed, который, как мы сказали ранее, не увеличился. Кроме того, мы отметили, что в пуле буферов не так много черновых данных, чтобы сбрасывать их в любом случае, — далеко не сотни мегабайт. Это неудивительно, поскольку рабочая нагрузка на этом сервере почти полностью состоит из запросов SELECT. Следовательно, мы можем сделать вывод: вместо того чтобы обвинять проблему в сбросе InnoDB, мы должны обвинить в проблеме задержку сброса InnoDB. Это симптом, результат, а не причина. Лежащая в основе проблема приводит к тому, что диски заполняются настолько, что InnoDB не успевает выполнить свои задачи ввода/вывода. Поэтому мы можем отбросить это как возможную причину и зачеркнуть одну из наших интуитивных идей.
Иногда довольно сложно отличить причину от результата, и когда проблема выглядит знакомой, может возникнуть соблазн пропустить анализ и перейти к диагнозу. Срезать углы не стоит, но в то же время важно прислушиваться к своей интуиции. Если что-то кажется знакомым, разумно потратить немного времени на измерение необходимых и достаточных условий, чтобы понять, является ли это проблемой. Это может сэкономить много времени, которое вы потратили бы на получение других данных о системе и ее производительности. Просто постарайтесь не делать выводов, основанных на интуиции, наподобие: «Я видел это раньше и уверен, что это то же самое». Если можете, соберите доказательства.
Следующим шагом стала попытка выяснить, что вызывало такое странное использование ввода/вывода сервера. Мы обращаем ваше внимание на приведенные ранее рассуждения: «Сервер пишет сотни мегабайт на диск в течение многих секунд, но база данных содержит только 900 Мбайт. Как это могло произойти?» Обратили ли вы внимание на неявное предположение, что база данных выполняет запись? Какими мы располагаем доказательствами, что это именно база данных? Попытайтесь остановиться, если принимаете что-то на веру бездоказательно, и если что-то не имеет смысла, подумайте, нет ли тут предположений. Если возможно, выполните измерения и устраните все сомнения.
Мы видели два варианта. Либо база данных вызывала работу ввода/вывода, и в этом случае, если бы мы могли понять, почему так происходит, мы считали бы, что это приведет нас к причине проблемы. Либо база данных не выполняла весь этот ввод/ вывод, но инициатором этих операций было что-то еще, и нехватка ресурсов ввода/вывода могла повлиять на базу данных. Мы говорим об этом очень осторожно, чтобы избежать другого неявного предположения: занятость дисков не означает, что MySQL пострадает. Помните, что основная рабочая нагрузка этого сервера — чтение из оперативной памяти, поэтому вполне можно представить, что диски могли бы перестать отвечать на запросы в течение длительного времени, не вызывая серьезных проблем.
Если вы следите за нашими рассуждениями, то, возможно, видите, что нам нужно вернуться назад и проверить другое предположение. Мы видим, что дисковое устройство ведет себя неправильно, о чем свидетельствует большое время ожидания. Твердотельный накопитель не должен тратить в среднем четверть секунды на каждую операцию ввода/вывода. И действительно, мы видим, что, по данным iostat, сам диск реагирует быстро, но много времени затрачивается на проход через очередь блочного устройства к диску. Помните, что это только предположение iostat, — и это может быть ошибкой.
В чем причина плохой производительности
Когда ресурс неправильно работает, полезно попытаться понять, почему так происходит. Существует несколько причин.
- Ресурс перегружен работой, и ему не хватает мощностей для правильной работы.
- Ресурс не настроен должным образом.
- Ресурс сломан или неисправен.
В анализируемом кейсе вывод утилиты
iostatможет указывать либо на слишком большой объем работы, либо на неправильную конфигурацию (почему требования ввода/ вывода так долго стоят в очереди, прежде чем попасть на диск, если на самом деле он реагирует быстро?). Однако важным элементом поиска ошибки является сравнение спроса на систему с ее мощностью. Из результатов экстенсивного эталонного тестирования мы знаем, что конкретный накопитель SSD, используемый этим клиентом, не может выдерживать сотни мегабайт записей в секунду. Таким образом, хотя iostat утверждает, что диск отвечает очень хорошо, вполне вероятно, что это не совсем так. В данном случае мы никак не могли доказать, что диск был медленнее, чем утверждалаiostat, но это выглядело весьма вероятным. Тем не менее это не меняет нашего мнения: причиной могут быть неверное использование диска, неверная настройка или и то и другое.
После работы с данными диагностики, позволившими сделать такой вывод, следующая задача была очевидна: измерить то, что вызывает ввод/вывод. К сожалению, это было неосуществимо в используемой клиентом версии GNU/Linux. Постаравшись, мы могли бы получить обоснованное предположение, но сначала хотели рассмотреть другие варианты. В качестве альтернативного варианта мы могли бы определить, сколько операций ввода/вывода поступает из MySQL, но опять же в этой версии MySQL данная операция была неосуществима из-за отсутствия необходимых инструментов.
Вместо этого мы решили попробовать понаблюдать за вводом/выводом MySQL, основываясь на знании о том, как система использует диск. В основном MySQL записывает на диск только данные, журналы, файлы сортировки и временные таблицы. Мы исключили данные и журналы из рассмотрения на основе счетчиков состояния и другой информации, о которой говорили ранее. Теперь предположим, что MySQL внезапно запишет на диск кучу данных из временных таблиц или файлов сортировки. Как можно за этим понаблюдать? Существует два простых способа: оценить объем свободного места на диске или посмотреть открытые дескрипторы сервера с помощью команды lsof. Мы сделали и то и другое, и результаты нас вполне удовлетворили. Приведем то, что df -h показывало каждую секунду во время инцидента, который мы изучали:
Filesystem Size Used Avail Use% Mounted on
/dev/sda3 58G 20G 36G 36% /
/dev/sda3 58G 20G 36G 36% /
/dev/sda3 58G 19G 36G 35% /
/dev/sda3 58G 19G 36G 35% /
/dev/sda3 58G 19G 36G 35% /
/dev/sda3 58G 19G 36G 35% /
/dev/sda3 58G 18G 37G 33% /
/dev/sda3 58G 18G 37G 33% /
/dev/sda3 58G 18G 37G 33% /Далее представлены данные, полученные с помощью команды lsof, которые мы почему-то собирали только каждые 5 секунд. Мы просто суммируем размеры всех файлов, которые mysqld открывает в /tmp, и распечатываем сумму для каждой временной выборки в файле:
$ awk '
/mysqld.*tmp/ {
total += $7;
}
/^Sun Mar 28/ && total {
printf "%s %7.2f MB\n", $4, total/1024/1024;
total = 0;
}' lsof.txt
18:34:38 1655.21 MB
18:34:43 1.88 MB
18:34:48 1.88 MB
18:34:53 1.88 MB
18:34:58 1.88 MBНа основе полученной информации можно сделать вывод, что MySQL записывает около 1,5 Гбайт данных во временные таблицы на начальных этапах инцидента, а это соответствует тому, что мы обнаружили в состояниях SHOW PROCESSLIST («Копирование в таблицу tmp»). Свидетельства указывают на массу плохих запросов, которые мгновенно заполняют диск. Самая распространенная причина этого, которую мы видели (сработала наша интуиция), — паника в кэше, когда все кэшированные объекты разом утекают из memcached, а несколько приложений дружно пытаются повторно восстановить кэш. Мы показали выборку запросов разработчикам и обсудили их цель. В самом деле оказалось, что причиной было одновременное прекращение существования кэша (интуитивное предположение подтвердилось). Разработчики попытались решить эту проблему на уровне приложения, а мы помогли им изменить запросы так, чтобы они не использовали временные таблицы на диске. Даже одно из этих исправлений могло бы предотвратить возникновение проблемы, но лучше внести их оба.
Теперь мы хотели бы вернуться немного назад и ответить на вопросы, которые могли у вас возникнуть.
- Почему для начала мы просто не оптимизировали медленные запросы?
Потому что проблема была не в медленных запросах, это была ошибка типа «слишком много соединений». Конечно, логично ожидать, что длительные запросы приводят к накоплению запросов и увеличению количества подключений. Но к такому результату могут привести и десятки других событий. Если не найдена точная причина, объясняющая, почему все идет не так, возникает соблазн вернуться к поиску медленных запросов или других общих моментов, которые выглядят так, как будто могут быть улучшены. К сожалению, чаще такой подход приводит к негативным результатам. Если вы отвезли свой автомобиль к механику и пожаловались на непонятный шум, а затем были огорошены счетом за балансировку шин и смену трансмиссионной жидкости, потому что механик не смог найти настоящую проблему и начал искать другие, разве вы не будете в ярости?
- Но разве не сигнал тревоги то, что запросы выполняются медленно с плохим
EXPLAIN?Они действительно выполнялись медленно, но во время инцидентов. Были ли это причина или результат? Это не было понятно, пока мы не углубились в исследование. Не забывайте, что в обычных условиях запросы выполнялись довольно хорошо. Просто то, что запрос делает файловую сортировку с помощью временной таблицы, не означает, что это проблема. Избавление от файловой сортировки и временных таблиц — это обычная тактика хорошего разработчика.
Но не всегда обычные тактики помогают в решении специфических проблем. Например, проблемой могла быть неправильная конфигурация. Мы видели немало случаев, когда некто пытался исправить неверно сконфигурированный сервер оптимизацией запросов, что оказывалось пустой тратой времени и просто увеличивало ущерб от реальной проблемы.
- Если кэшированные элементы неоднократно восстанавливались, не возникало ли множества одинаковых запросов?
Да, и это то, что мы тогда не проверили. Множественные потоки, восстанавливающие один и тот же элемент в кэше, действительно вызывали бы возникновение множества полностью идентичных запросов. (Это не то же самое, что несколько запросов одного и того же общего типа, которые, например, могут различаться параметром в разделе
WHERE.) Если бы мы обратили на это внимание, то могли бы, прислушавшись к интуиции, быстрее прийти к решению. - Выполнялись сотни запросов
SELECTв секунду, но только пятьUPDATE. Можно ли сказать, что эти пять не были действительно тяжелыми запросами?Они действительно могли сильно нагружать сервер. Мы не показывали фактические запросы, поскольку эта информация лишь помешала бы, но мнение, что абсолютное число запросов каждого типа не обязательно важно, имеет право на жизнь.
- Разве «доказательство», говорящее об источнике урагана ввода/вывода, все еще недостаточно весомое?
Да. Может быть много объяснений, почему небольшая база данных записывает огромное количество данных на диск или почему свободное место на диске быстро сокращается. Это то, что довольно сложно измерить (хотя и не невозможно) в версиях MySQL и GNU/Linux. Хотя можно сыграть в адвоката дьявола и придумать множество сценариев. Мы решили уравновесить затраты и потенциальную выгоду, сначала выбрав наиболее перспективный путь. Чем сложнее проведение измерений и меньше уверенность в результатах, тем выше соотношение затрат и выгод и тем сильнее мы готовы принять неопределенность.
- Мы говорили: «Раньше база данных никогда не была проблемой». Разве это не предубеждение?
Да, это было необъективно. Если вы уловили это — здорово, если нет, то, надеемся, это станет хорошим примером того, что у всех нас есть предубеждения.
Мы хотели бы завершить кейс по устранению неполадок, указав, что рассмотренную проблему, скорее всего, можно было бы решить (или предотвратить) без нашего участия, используя инструмент профилирования приложений, например New Relic.
