1) Используйте соответствующие инструменты для работы
Многие программисты, кажется, забывают, как важно регистрировать поведение приложения и его текущую активность. Когда кто-то ставит:
|
1
|
log.info("Happy and carefree logging"); |
К счастью, где-то в коде, он, вероятно, не осознает важность журналов приложений во время обслуживания, настройки и идентификации сбоев. Недооценка ценности хороших бревен — ужасная ошибка.
На мой взгляд, SLF4J — лучший доступный API журналирования, в основном из-за большой поддержки замены шаблонов:
|
1
|
log.debug("Found {} records matching filter: '{}'", records, filter); |
В Log4j вы должны использовать:
|
1
|
log.debug("Found " + records + " records matching filter: '" + filter + "'"); |
Это не только длиннее и менее читабельно, но и неэффективно из-за широкого использования конкатенации строк. SLF4J добавляет хорошую функцию замены {}. Кроме того, поскольку избегается конкатенация строк и функция toString () не вызывается, если оператор записи в журнал фильтруется, isDebugEnabled () больше не требуется. Кстати, вы заметили одинарные кавычки вокруг параметра строки фильтра?
SLF4J — это просто фасад. В качестве реализации я бы порекомендовал уже объявленный каркас Logback вместо устоявшегося Log4J . Он имеет много интересных функций и, в отличие от Log4J, активно развивается.
Последний инструмент, который можно порекомендовать, это Perf4J . Процитирую их девиз:
Perf4J для System.currentTimeMillis (), а log4j для System.out.println ()
Я добавил Perf4J к одному существующему приложению под большой нагрузкой и видел его в действии в нескольких других. И администраторы, и бизнес-пользователи были впечатлены красивыми графиками, созданными этой простой утилитой. Также мы смогли обнаружить недостатки производительности в кратчайшие сроки. Perf4J сам по себе заслуживает отдельной статьи, но сейчас просто посмотрите их Руководство разработчика .
Кроме того, обратите внимание, что Ceki Gülcü (основатель проектов Log4J , SLF4J и Logback ) предложил простой подход, чтобы избавиться от зависимости регистрации общего ресурса (см. Его комментарий ).
2) Не забывайте, что логирование уровней для вас
Каждый раз, когда вы делаете заявление о регистрации, вы задумываетесь, какой уровень регистрации подходит для этого типа событий, не так ли? Так или иначе, 90% программистов никогда не обращают внимания на уровни ведения журнала, просто регистрируя все на одном уровне, обычно INFO или DEBUG. Почему? Каркасы журналирования имеют два основных преимущества перед System.out., То есть категории и уровни. Оба позволяют вам выборочно фильтровать записи журнала постоянно или только для времени диагностики. Если вы действительно не видите разницы, распечатайте эту таблицу и просматривайте ее каждый раз, когда начинаете вводить «log». в вашей IDE:
ОШИБКА — произошло что-то ужасное, что должно быть немедленно расследовано. Ни одна система не может терпеть элементы, зарегистрированные на этом уровне. Пример: NPE, база данных недоступна, сценарий критического использования не может быть продолжен.
ВНИМАНИЕ — процесс может быть продолжен, но будьте особенно осторожны. На самом деле я всегда хотел иметь два уровня: один для очевидных проблем, где существует обходной путь (например: «Текущие данные недоступны, используя кэшированные значения») и второй (назовите его: ВНИМАНИЕ) для потенциальных проблем и предложений. Пример: «Приложение работает в режиме разработки» или «Консоль администрирования не защищена паролем». Приложение может терпеть предупреждающие сообщения, но они всегда должны быть обоснованы и изучены.
ИНФОРМАЦИЯ — Важный бизнес-процесс завершен. В идеале администратор или опытный пользователь должен понимать сообщения INFO и быстро узнавать, что делает приложение. Например, если заявка касается бронирования авиабилетов, в каждом билете должна быть только одна ИНФО-заявка, в которой указано «[Кто] забронировал билет из [Где] в [Где]». Другое определение сообщения INFO: каждое действие, которое существенно изменяет состояние приложения (обновление базы данных, запрос внешней системы).
DEBUG — Разработчики вещей. Позже я расскажу, какая информация заслуживает регистрации.
TRACE — очень подробная информация, предназначенная только для разработки. Вы можете хранить сообщения трассировки в течение короткого периода времени после развертывания в производственной среде, но обрабатывать эти операторы журнала как временные, которые в конечном итоге должны быть отключены или могут быть отключены. Различие между DEBUG и TRACE является наиболее сложным, но если вы поместите оператор ведения журнала и удалите его после того, как функция будет разработана и протестирована, она, вероятно, должна быть на уровне TRACE.
Приведенный выше список является лишь предложением, вы можете создать свой собственный набор инструкций, которым нужно следовать, но важно иметь некоторые. Мой опыт показывает, что всегда все регистрируется без фильтрации (по крайней мере, из кода приложения), но возможность быстрой фильтрации журналов и извлечения информации с надлежащим уровнем детализации может спасти жизнь.
Последнее, что стоит упомянуть, это печально известное условие * Enabled (). Некоторые помещают это перед каждым оператором регистрации:
|
1
2
|
if(log.isDebugEnabled()) log.debug("Place for your commercial"); |
Лично я считаю эту идиому просто беспорядком, которого следует избегать. Улучшение производительности (особенно при использовании замещения шаблона SLF4J, обсуждавшегося ранее) кажется несущественным и пахнет преждевременной оптимизацией . Кроме того, вы можете обнаружить дублирование? Есть очень редкие случаи, когда наличие явного условия оправдано — когда мы можем доказать, что создание сообщения регистрации является дорогостоящим. В других ситуациях просто делайте свою работу по ведению журнала и позвольте каркасу ведения журнала делать свою работу (фильтрация).
3) Знаете ли вы, что вы входите?
Каждый раз, когда вы выполняете инструкцию по протоколированию, найдите время и посмотрите, что именно попадет в ваш файл журнала. Прочитайте ваши журналы впоследствии и найдите неправильные предложения. Прежде всего, избегайте таких NPE:
|
1
|
log.debug("Processing request with id: {}", request.getId()); |
Вы абсолютно уверены, что запрос здесь не нулевой?
Другая ловушка — регистрация коллекций. Если вы выбрали коллекцию доменных объектов из базы данных, используя Hibernate, и небрежно зарегистрируйте их, как здесь:
|
1
|
log.debug("Returning users: {}", users); |
SLF4J будет вызывать toString () только тогда, когда инструкция действительно напечатана, что довольно хорошо. Но если это произойдет … Ошибка нехватки памяти, проблема выбора N + 1 , нехватка потоков (ведение журнала синхронно!), Исключение отложенной инициализации, заполнение хранилища журналов — каждое из них может произойти.
Это гораздо лучшая идея, например, регистрировать только идентификаторы объектов домена (или даже только размер коллекции). Но создание набора идентификаторов при наличии набора объектов с методом getId () невероятно сложно и громоздко в Java. В Groovy есть отличный оператор распространения (users * .id), в Java мы можем эмулировать его с помощью библиотеки Commons Beanutils :
|
1
|
log.debug("Returning user ids: {}", collect(users, "id")); |
Где метод collect () может быть реализован следующим образом:
|
1
2
3
|
public static Collection collect(Collection collection, String propertyName) { return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));} |
Последнее, что следует упомянуть, это неправильная реализация или использование toString (). Во-первых, создайте toString () для каждого класса, который появляется в любом месте операторов логирования, предпочтительно используя ToStringBuilder (но не его отражающий аналог). Во-вторых, следите за массивами и нестандартными коллекциями. Массивы и некоторые странные коллекции могут не иметь функции toString (), вызывающей toString () каждого элемента. Используйте Arrays #deepToString JDK. И часто читайте журналы, чтобы обнаружить неправильно отформатированные сообщения.
4) Избегайте побочных эффектов
Логирование операторов не должно иметь или мало влиять на поведение приложения. Недавно мой друг привел пример системы, которая выдает исключение LazyInitializationException от Hibernates только при работе в какой-то конкретной среде. Как вы, вероятно, догадались из контекста, некоторые операторы журналирования вызывали загрузку отложенной инициализированной коллекции при присоединении сеанса. В этой среде уровни ведения журнала были увеличены, и сбор больше не был инициализирован. Подумайте, сколько времени вам потребуется, чтобы найти ошибку, не зная этого контекста?
Еще один побочный эффект — замедление работы приложения. Быстрый ответ: если вы ведете слишком много журналов или неправильно используете toString () и / или конкатенацию строк, запись в журнал имеет побочный эффект производительности. Насколько велик? Я видел перезапуск сервера каждые 15 минут из-за нехватки потоков, вызванной чрезмерным ведением журнала. Теперь это побочный эффект! По моему опыту, несколько сотен мегабайт — это, вероятно, верхний предел того, сколько вы можете войти на диск в час.
Конечно, если сама инструкция ведения журнала завершается неудачно и приводит к прекращению бизнес-процесса из-за исключительной ситуации, это также является огромным побочным эффектом. Я видел такую конструкцию, чтобы избежать этого:
|
1
2
3
|
try { log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())} catch(NullPointerException e) {} |
Это настоящий кодекс, но, пожалуйста, сделайте мир немного лучше и не делайте этого никогда.
5) быть кратким и описательным
Каждый оператор записи должен содержать как данные, так и описание. Рассмотрим следующие примеры:
|
1
2
3
4
|
log.debug("Message processed");log.debug(message.getJMSMessageID());log.debug("Message with id '{}' processed", message.getJMSMessageID()); |
Какой журнал вы хотели бы видеть при диагностике сбоя в неизвестном приложении? Поверьте, все приведенные выше примеры почти одинаково распространены. Еще один анти-шаблон:
|
1
2
3
4
|
if(message instanceof TextMessage) //...else log.warn("Unknown message type"); |
Было ли так сложно включить в строку предупреждения фактический тип сообщения, идентификатор сообщения и т. Д.? Я знаю, что что-то пошло не так, но что? Каков был контекст?
Третий анти-паттерн — «волшебный журнал». Пример из реальной жизни: большинство программистов в команде знали, что 3 амперсанда, за которыми следуют восклицательный знак, за которым следует хэш, а затем псевдослучайный алфавитно-цифровой журнал строк, означающий «Получено сообщение с идентификатором XYZ». Никто не удосужился изменить журнал, просто кто-то нажал на клавиатуру и выбрал какую-то уникальную строку «&&&! #», Чтобы ее можно было легко найти самому.
Как следствие, весь файл журнала выглядит как случайная последовательность символов. Кто-то может даже считать этот файл допустимой программой на Perl . Вместо этого файл журнала должен быть читаемым, чистым и описательным. Не используйте магические числа, значения лога, числа, идентификаторы и включайте их контекст. Показать данные, которые обрабатываются и показать их значение. Покажите, что на самом деле делает программа. Хорошие журналы могут служить отличной документацией самого кода приложения.
Я упоминал, чтобы не регистрировать пароли и какую-либо личную информацию? Не надо!
6) Настройте свой шаблон
Шаблон ведения журнала — замечательный инструмент, который прозрачно добавляет содержательный контекст к каждому выполненному вами заявлению. Но вы должны очень тщательно продумать, какую информацию включить в свой шаблон. Например, дата регистрации, когда ваши журналы катятся каждый час, не имеет смысла, так как эта дата уже включена в имя файла журнала. Напротив, без регистрации имени потока вы не сможете отслеживать какой-либо процесс, используя журналы, когда два потока работают одновременно — журналы будут перекрываться. Это может быть хорошо в однопоточных приложениях, которые в настоящее время практически не работают.
По моему опыту, идеальный шаблон ведения журнала должен включать (конечно, кроме самого записываемого сообщения): текущее время (без даты, точность в миллисекундах), уровень ведения журнала, имя потока, простое имя средства ведения журнала (не полностью) и сообщение. В Logback это что-то вроде:
|
1
2
3
4
5
|
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern> </encoder></appender> |
Вы никогда не должны включать имя файла, имя класса и номер строки, хотя это очень заманчиво. Я даже видел пустые записи журнала, выданные из кода:
|
1
|
log.info(""); |
поскольку программист предполагал, что номер строки будет частью шаблона ведения журнала, и он знал, что «если в 67-й строке файла появляется пустое сообщение (в методе authenticate ()), это означает, что пользователь прошел проверку подлинности». Кроме того, регистрация имени класса, имени метода и / или номера строки оказывает серьезное влияние на производительность.
Несколько более продвинутая функция каркасов ведения журналов — это концепция Mapped Diagnostic Context. MDC — это просто карта, управляемая локально для потока. Вы можете поместить любую пару ключ-значение в эту карту, и с тех пор каждый оператор логирования, созданный из этого потока, будет иметь это значение как часть шаблона.
7) Записывать аргументы метода и возвращаемые значения
Когда вы находите ошибку во время разработки, вы обычно запускаете отладчик, пытаясь отследить потенциальную причину. А теперь представьте, что вы не можете использовать отладчик. Например, потому что ошибка проявилась в клиентской среде несколько дней назад, и все, что у вас есть, это логи. Сможете ли вы найти в них что-нибудь?
Если вы следуете простому правилу регистрации каждого входа и выхода метода (аргументы и возвращаемые значения), вам даже не понадобится отладчик. Конечно, вы должны быть разумными, но каждый метод, который: обращается к внешней системе (включая базу данных), блокирует, ждет и т. Д., Должен быть рассмотрен. Просто следуйте этой схеме:
|
1
2
3
4
5
6
|
public String printDocument(Document doc, Mode mode) { log.debug("Entering printDocument(doc={}, mode={})", doc, mode); String id = //Lengthy printing operation log.debug("Leaving printDocument(): {}", id); return id;} |
Поскольку вы регистрируете как начало, так и конец вызова метода, вы можете вручную обнаружить неэффективный код и даже обнаружить возможные причины тупиковых ситуаций и голодания — просто наблюдая за «входом» без соответствующего «ухода». Если у ваших методов есть значимые имена, читать журналы было бы приятно. Кроме того, анализ того, что пошло не так, намного проще, поскольку на каждом шаге вы точно знаете, что было обработано. Вы даже можете использовать простой аспект АОП для регистрации широкого спектра методов в вашем коде. Это уменьшает дублирование кода, но будьте осторожны, так как это может привести к огромному количеству огромных журналов.
Вы должны рассмотреть уровни DEBUG или TRACE как наиболее подходящие для этих типов журналов. И если вы обнаружите, что какой-то метод вызывается слишком часто, и ведение журнала может снизить производительность, просто уменьшите уровень ведения журнала для этого класса или полностью удалите журнал (может быть, оставьте только один для всего вызова метода?) Но всегда лучше иметь слишком много чем слишком мало операторов регистрации. Относитесь к операторам журналирования с тем же уважением, что и к модульным тестам — ваш код должен быть покрыт процедурами журналирования, как и модульными тестами Ни одна часть системы не должна оставаться без журналов вообще. Помните, что иногда наблюдение за пролистывающимися журналами — единственный способ определить, работает ли ваше приложение правильно или зависает навсегда.
8) Остерегайтесь внешних систем
Это особый случай предыдущего совета: если вы общаетесь с внешней системой, рассмотрите возможность регистрации каждого фрагмента данных, которые поступают из вашего приложения и входят в него. Период. Интеграция — сложная задача, и диагностировать проблемы между двумя приложениями (например, двумя разными поставщиками, средами, технологическими стеками и группами) особенно сложно. Например, недавно мы обнаружили, что регистрация полного содержимого сообщений, включая заголовки SOAP и HTTP, в веб-сервисах Apache CXF чрезвычайно полезна при интеграции и тестировании системы.
Это большие издержки, и если производительность является проблемой, вы всегда можете отключить ведение журнала. Но какой смысл иметь быстрое, но неработающее приложение, которое никто не может исправить? Будьте особенно осторожны при интеграции с внешними системами и подготовьтесь оплатить эту стоимость. Если вам повезло, и вся ваша интеграция обрабатывается ESB, то шина, вероятно, является лучшим местом для записи каждого входящего запроса и ответа. Смотрите, например, Mule s ‘ log-component .
Иногда объем информации, которой обмениваются внешние системы, делает недопустимым запись всего. С другой стороны, во время тестирования и в течение короткого периода времени на производстве (например, когда происходит что-то не так), мы хотели бы сохранить все в журналах и готовы заплатить за производительность. Это может быть достигнуто путем тщательного использования уровней регистрации. Просто взгляните на следующую идиому:
|
1
2
3
4
5
|
Collection<Integer> requestIds = //...if(log.isDebugEnabled()) log.debug("Processing ids: {}", requestIds);else log.info("Processing ids size: {}", requestIds.size()); |
Если этот конкретный регистратор настроен на запись сообщений отладки, он напечатает все содержимое коллекции requestIds. Но если он настроен на печать сообщений INFO, выводится только размер коллекции. Если вам интересно, почему я забыл про условие isInfoEnabled (), вернитесь к совету №2. Стоит отметить, что в этом случае коллекция requestIds не должна быть нулевой. Хотя он будет записан правильно, как ноль, если DEBUG включен, но большое толстое исключение NullPointerException будет выдано, если регистратор настроен на INFO. Помните мой урок о побочных эффектах в совете № 4?
9) Правильно регистрируйте исключения
Прежде всего, избегайте регистрации исключений, пусть ваш фреймворк или контейнер (что бы это ни было) сделает это за вас. Есть одно, ekhem, исключение из этого правила: если вы генерируете исключения из некоторой удаленной службы (RMI, EJB-компонента удаленного сеанса и т. Д.), Которая способна сериализовать исключения, убедитесь, что все они доступны для клиента ( часть API). В противном случае клиент получит NoClassDefFoundError: SomeFancyException вместо «истинной» ошибки.
Регистрация исключений является одной из наиболее важных ролей, но многие программисты склонны рассматривать ведение журнала как способ обработки исключения. Иногда они возвращают значение по умолчанию (обычно ноль, 0 или пустую строку) и делают вид, что ничего не произошло. В других случаях они сначала регистрируют исключение, а затем оборачивают его и отправляют обратно:
|
1
2
|
log.error("IO exception", e);throw new MyCustomException(e); |
Эта конструкция почти всегда печатает одну и ту же трассировку стека два раза, потому что что-то в конечном итоге перехватит MyCustomException и зарегистрирует его причину. Записывайте или оборачивайте и отбрасывайте назад (что предпочтительнее), но не то и другое одновременно, иначе ваши журналы будут путать
Но если мы действительно хотим записать исключение? По какой-то причине (потому что мы не читаем API и документацию?), Около половины операторов логирования, которые я вижу, неверны. Быстрый тест, какой из следующих операторов журнала будет правильно регистрировать NPE?
|
01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
|
try { Integer x = null; ++x;} catch (Exception e) { log.error(e); //A log.error(e, e); //B log.error("" + e); //C log.error(e.toString()); //D log.error(e.getMessage()); //E log.error(null, e); //F log.error("", e); //G log.error("{}", e); //H log.error("{}", e.getMessage()); //I log.error("Error reading configuration file: " + e); //J log.error("Error reading configuration file: " + e.getMessage()); //K log.error("Error reading configuration file", e); //L} |
Удивительно, но только G и предпочтительно L верны! A и B даже не компилируются в SLF4J, другие сбрасывают следы стека и / или печатают неправильные сообщения. Например, E не будет ничего печатать, так как NPE обычно не предоставляет никаких сообщений об исключениях, и трассировка стека также не будет напечатана. Помните, что первым аргументом всегда является текстовое сообщение, напишите что-нибудь о природе проблемы. Не включайте сообщение об исключении, так как оно будет напечатано автоматически после оператора log, предшествующего трассировке стека. Но для этого вы должны передать само исключение в качестве второго аргумента.
10) Журналы легко читаются, легко разбираются
Журналы ваших приложений особенно интересуют две группы получателей: люди (вы можете не согласиться, но программисты также принадлежат к этой группе) и компьютеры (обычно сценарии оболочки, написанные системными администраторами). Логи должны подходить для обеих этих групп. Если кто-то смотрит из-за вашей спины в журналы вашего приложения, видит (источник Википедия):
тогда вы, вероятно, не следовали моим советам. Журналы должны быть читаемыми и легкими для понимания, как и код.
С другой стороны, если ваше приложение генерирует половину ГБ журналов каждый час, ни один человек и никакой графический текстовый редактор никогда не смогут прочитать их полностью. Это то место, где grep , sed и awk старой школы пригодятся. Если это возможно, попытайтесь писать сообщения регистрации таким образом, чтобы они могли быть понятны как людям, так и компьютерам, например, избегать форматирования чисел, использовать шаблоны, которые можно легко распознать с помощью регулярных выражений, и т. Д. Если это невозможно распечатать данные в двух форматах:
|
1
2
3
4
5
6
|
log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);log.info("Importing took: {}ms ({})", durationMillis, duration);//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds) |
Компьютеры по достоинству оценят формат времени «мс после 1970 года», а люди будут рады увидеть текст «1 день 10 часов 17 минут 36 секунд». Кстати, взгляните на DurationFormatUtils , хороший инструмент.
Вот и все, парни, «феерия советов по ведению журнала» от нашего партнера по JCP Томаша Нуркевича . Не забудьте поделиться!
- Вход Антипаттерны
- Вещи, которые должен знать каждый программист
- Законы разработки программного обеспечения
- Лучшие практики Java — Вектор против ArrayList против HashSet
- Лучшие практики Java — DateFormat в многопоточной среде
- Java Best Practices — высокопроизводительная сериализация
- Java Best Practices — строковая производительность и точное совпадение строк