23 June 2013

monitoring

MongoDB это замечательная NoSQL база данных, которая дает большую гибкость при разработке приложений за счет своего документо-ориентированного способа представления данных. В этой статье я опишу логирование и профилирования ваших решений на базе MongoDB.

Профилирование

Для целей профилирования работы, в MongoDB существует специальная коллекция system.profile. В терминологии MongoDB, system.profile является ограниченной коллекцией (capped collection), потому что её размер ограничен 1Мб. По умолчанию профилирование запросов отключено, и никакой информации о работе системы не сохраняется. Из db.help() нас будут интересовать две команды:

db.getProfilingStatus() - returns if profiling is on and slow threshold
db.setProfilingLevel(level, <slowms>) 0=off 1=slow 2=all

Первая отображает текущий статус профилирования, а вторая помогает его менять. Всего существует три режима, как можно догадаться из подсказки:

  • 0, профилирование отключено полность. Это режим по умолчанию, если вы еще не успели настроить профилирование в своей БД, то вы должны увидеть следующее:

      > db.getProfilingStatus()
      { "was" : 0, "slowms" : 100 }
    
  • 1, профилирование медленных запросов. Этот режим я использую на продакшене, потому что он позволяет логировать только запросы, выполнявшиеся дольше определенного порога(threshold). Когда вы устанавливаете этот режим, второй параметр в db.setProfilingLevel становится обязательным и указывает на размер порога срабатывания в миллисекундах. Я использую порог в 100 мс, но это дело вкуса:

      > db.setProfilingLevel(1, 100)
      { "was" : 0, "slowms" : 100, "ok" : 1 }
      > db.getProfilingStatus()
      { "was" : 1, "slowms" : 100 }
    
  • 2, профилирование всех запроса. Хорошо подходит для разработки, но на продакшене использовать нецелесообразно: старые данные профайлера быстро затираются, а накладные расходы на поддержание столь подробного лога, увеличиваются.

      > db.setProfilingLevel(2)
      { "was" : 1, "slowms" : 100, "ok" : 1 }
      > db.getProfilingStatus()
      { "was" : 2, "slowms" : 100 }
    

Структура документов в system.profile

Все записи профайлера представляют собой обычные документы со следующим набором основных полей:

  • op, тип операции(insert, query, update, remove, getmore, command)
  • ns, коллекция(а точнее namespace), над которой производится операция
  • millis, время выполнения операции в миллисекундах
  • ts, время(timestamp) операции. Большого значения это не имеет, но это дата окончания выполнения операции.
  • client, IP-адрес или имя хоста, с которого была отправлена команда
  • user, авторизованный пользователь, который выполнил запрос. Если вы не используете авторизацию, то в профайлер будет записана пустая строка.

В дополнение к основным полям, есть ещё поля, специфические для каждого типа запроса. Для поиска(find) это будет сам запрос(query), информация о числе просканированных(nscanned) и возвращенных(nreturned) документов, для изменения(update) это будет число обновленных(nupdated) и перемещённых на диске(nmoved) элементом и т.д. За полным списком полей можно обратиться к документации.

Вот пример для вставки(insert) документа:

{
	"op" : "insert",
	"ns" : "test_db.test_coll",
	"ninserted" : 1,
	"keyUpdates" : 0,
	"numYield" : 0,
	"lockStats" : {
		"timeLockedMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(46)
		},
		"timeAcquiringMicros" : {
			"r" : NumberLong(0),
			"w" : NumberLong(424)
		}
	},
	"millis" : 101,
	"ts" : ISODate("2013-06-28T09:03:21.396Z"),
	"client" : "127.0.0.1",
	"allUsers" : [ ],
	"user" : ""
}

Запросы к профайлеру

К коллекции system.profile применимы все те же способы формирования запросов, что и к обычной коллекции. Вот несколько самых ходовых вариантов:

    // Вывести все данные в порядке убывания даты создания
    db.system.profile.find().sort({$natural:-1});
            
    // Найти все операции длиннее 5 мс.
    db.system.profile.find( { millis : { $gt : 5 } } );
            
    // Вывести все данные в порядке убывания времени выполнения
    // (самые тяжелые запросы в начале)
    db.system.profile.find().sort({millis:-1});

Анализ истории помогает выявить и локализовать неэффективные запросы. Для этого стоит регулярно просматривать самые тяжелы операции на предмет ошибки.

Такой подход я применяю для анализа новых коллекций и пользовательских сценариев, но в определенный момент схема данных и запросы “устаканиваются”, а анализ исторических данных начинает показывать одни и те же цифры, в которых сложно заподозрить проблемы. Другими словами, со временем этот подход перестает приносить свои плоды, потому что проект/модуль переходит из стадии разработки в стадию поддержки.

Логирование

Логи работы системы являются еще одной возможностью проанализировать работу БД на предмет потенциальных проблем. Найти лог не сложно, в /etc/mongodb.conf есть соответствующая настройка для этого:

logpath=/var/log/mongodb/mongodb.log

Лог MongoDB хранит множество информации обо всех аспектах работы системы, но нас будут интересовать только некоторые записи:

Wed Jun 26 22:02:06.197 [conn1599] insert test_db.events ninserted:1 keyUpdates:0 locks(micros) w:31 152ms
Wed Jun 26 22:02:41.183 [conn1598] insert test_db.events ninserted:1 keyUpdates:0 locks(micros) w:33 185ms

Такие записи отражают обращения в БД, которые выполнялись более 100 мс. Сюда могут входить как команды по изменению данных(save, insert, update), так и команды по извлечению или агрегации данных(find, aggregate, mapReduce), например:

Wed Jun 26 22:05:01.022 [conn1588] command test_db.$cmd command: { aggregate: "events", pipeline: [ ... ] } ntoreturn:1 keyUpdates:0 numYields: 109 locks(micros) r:1788726 reslen:762 921ms

В зависимости он того, как организован доступ к БД, в логах могут часто появляться записи об открытии/закрытии соединения с клиентом и общее число подключений:

Thu Jun 26 22:46:51 [initandlisten] connection accepted from xxx.xxx.xxx.xxx:56918 #80045 (22 connections now open)
Thu Jun 26 22:46:51 [conn80043] end connection xxx.xxx.xxx.xxx:51580 (21 connections now open)

За логами можно следить в реальном времени, если воспользоваться консольной командой tail:

$ tail -f /var/log/mongodb/mongodb.log

Таким образом можно отслеживать производительность различных пользовательских сценариев при разработке.

Логи сильно меня выручали, когда я только начинал разбираться с мониторингом и отладкой MongoDB. Если вы только планируете выводить на продакшен решение на базе MongoDB, изучение логов является обязательным пунктом. Правда, если информации слишком много или нужно проанализировать выполнение запросов за предыдущий период времени, лучше обратиться к другому инструменту.

Заключение

В этой части были рассмотрены базовые возможности логирования и профилирования в MongoDB. По своему опыту, могу сказать, что этого достаточно для диагностирования большинства проблем. В следующей части я расскажу о более продвинутых способах профилирования с использованием Aggregation Framework.



blog comments powered by Disqus

Fork me on GitHub