Кейс по диагностике MySQL: ищем "дыры" в производительности

Светлана Комарова

Светлана Комарова

Автор статьи. Системный администратор, Oracle DBA. Информационные технологии, интернет, телеком. Подробнее.

Кейс по поиску проблем MySQL сервераВ предыдущем блоге мы уже рассмотрели возможные нетипичные проблемы сервера MySQL и способы их выявления. Теперь соберем полученные знания в некую инструкцию (кейс) по поиску и устранению проблем с базой данных MysQL. Рассмотрим процесс диагностики редко возникающих проблем с производительностью на примере конкретной ситуации. В этом кейсе мы заберемся в неизвестную вам об­ласть, если вы не эксперт в MySQL, InnoDB и GNU/Linux. Однако основная идея этого кейса в другом. Попытайтесь найти метод в безумии: прочитайте этe раздел, ориентируясь на сделанные нами предположения и догадки. Рассмотрите подходы, основанные на рассуждениях и измерениях. Мы детально вникаем в конкретный случай лишь для иллюстрации общих положений.


Оглавление статьи[Показать]


Прежде чем приступить к решению проблемы, откликаясь на чью-то просьбу, стоит попробовать прояснить две вещи, желательно делая заметки, чтобы не забыть о чем- то важном.

  1. В чем заключается проблема? Постарайтесь выяснить это. Удивительно легко начать охоту не за той проблемой. В данном случае клиент жаловался, что один раз в день или раз в два дня сервер отклоняет соединения, выдавая ошибку max_connections. Проблема появляется периодически и длится от нескольких секунд до нескольких минут.
  2. Что было сделано в попытке это исправить? В данном случае клиент вообще не пытался решить проблему. Слушая о проблеме в изложении другого, очень трудно понять, какова точная последовательность событий, в чем заключаются изменения, которые эти события повлекли за собой, и каков результат их воздействия. Это особенно верно, когда человек в отчаянии после пары бессонных ночей и до краев налитых кофеином дней. На сервере, с которым происходили неизвестные изменения с неизвестным эффектом, очень сложно устранять непо­ладки, особенно в цейтноте.

Обсудив эти моменты, приступим. Стоит не только попытаться понять, как ведет себя сервер, но и оценить его состояние, конфигурацию, программное обеспечение и обо­рудование. Мы сделали это с помощью инструментов 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, — и это может быть ошибкой.


В чем причина плохой производительности

Когда ресурс неправильно работает, полезно попытаться понять, почему так проис­ходит. Существует несколько причин.

  1. Ресурс перегружен работой, и ему не хватает мощностей для правильной работы.
  2. Ресурс не настроен должным образом.
  3. Ресурс сломан или неисправен.

В анализируемом кейсе вывод утилиты 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.

Вас заинтересует / Intresting for you:

Модель развития базы данных My...
Модель развития базы данных My... 781 просмотров Ирина Светлова Thu, 10 Jan 2019, 12:29:03
Транзакции в базе данных MySQL
Транзакции в базе данных MySQL 8314 просмотров Ирина Светлова Mon, 07 Jan 2019, 05:18:23
Выбор оптимальных типов данных...
Выбор оптимальных типов данных... 3549 просмотров Валерий Павлюков Sun, 27 Oct 2019, 15:24:19
Обзор архитектуры MySQL
Обзор архитектуры MySQL 2083 просмотров Ирина Светлова Wed, 09 Jan 2019, 04:25:21
Войдите чтобы комментировать

apv аватар
apv ответил в теме #9490 07 окт 2019 15:00
Статья - просто Бомба!! Огромнейший респект!)))