Статьи

Осуществите ведение журнала в IDE с помощью консоли Grep.

Одним из многих ежедневных действий, которые каждый программист должен выполнять для выполнения своей работы, является контроль выходных данных журналов из своего приложения. Ведение журнала, если все сделано правильно и правильно, дает отличное представление о внутренней работе приложения и может быть отличным ресурсом для анализа и оптимизации поведения вашего кода. Будь то на этапе разработки или сопровождения / поддержки жизненного цикла продукта, эта задача часто считается неприятной для многих программистов. Но так как анализ журналов так важен и часто требуется, обычно не существует простого пути обхода. В этой статье я представлю элегантное решение для просмотра журналов на стадии разработки приложения в IDE.

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

  • Выполнение выражения SQL
  • Начало и конец транзакции
  • Запрос и ответ веб-службы

Grep пульт

Учитывая нашу практику разработки и тот факт, что Spring Framework поддерживает большинство наших продуктов, наша любимая IDE — Spring Tool Suite (сокращенно STS). А так как STS построен на основе Eclipse IDE, он поставляется с обширной торговой площадкой Eclipse . Если вы посмотрите достаточно глубоко, вы можете найти все там. Среди множества полезных инструментов и плагинов Marketplace также хранит один небольшой, но мощный плагин, который называется Grep console . Этот маленький проект разработан и поддерживается Марианом Шеденигом . Он позволяет вам определять набор стилей, которые применяются к вашей консоли ведения журнала на основе назначенных регулярных выражений.

Если вы похожи на меня, и тема Eclipse по умолчанию (шрифты, цвета, размеры шрифтов и прочее) просто не работает для вас, то вы, вероятно, используете некоторые плагины для настройки внешнего вида IDE. Я лично предпочитаю плагин Eclipse Color Themes и тему Gedit Original Oblivion . Отличительной особенностью этого проекта является то, что все настройки темы доступны онлайн в приятной форме. И здесь все становится интересным. Это позволяет программисту создавать согласованный стиль для кода и журналов, предоставляя действительно простой и интуитивно понятный способ организации ваших мыслей и улучшая общую ориентацию.

Grep консоль в действии

Следующие параграфы демонстрируют примененные стили для трех упомянутых интересных событий.

Выполнение выражения SQL

Одна из основных задач анализа журналов — определить местонахождение выполнения определенного выражения SQL. Мы используем datasource-proxy для ведения журнала SQL в нашем проекте, который предоставляет прокси-классы для JDBC API для перехвата выполнения запросов. Благодаря этому мы смогли легко сопоставить регулярные выражения консолей Grep с классом CommonsQueryLoggingListener который регистрирует любое взаимодействие с источником данных. Учитывая наши локальные настройки стиля, это то, что вы видите в консоли в Eclipse IDE.

Цвет: # 1eff67
Выражение:. .*net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener.*

1
2
3
4
5
6
7
8
9
2013-11-18 09:00:08,893 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:1, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}
2013-11-18 09:00:08,896 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:2, Num:1, Query:{[insert into S_SYS_MON (COL_A, COL_B, COL_C) values (?, ?, ?)][1, 2013-11-18 08:59:07.872, A]}
2013-11-18 09:01:10,920 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:1, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}
2013-11-18 09:01:10,924 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:3, Num:1, Query:{[insert into S_SYS_MON (COL_A, COL_B, COL_C) values (?, ?, ?)][2, 2013-11-18 09:59:07.872, B]}
2013-11-18 09:02:12,946 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:1, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}
2013-11-18 09:02:12,949 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:2, Num:1, Query:{[insert into S_SYS_MON (COL_A, COL_B, COL_C) values (?, ?, ?)][3, 2013-11-18 10:59:07.872, C]}
2013-11-18 09:03:14,971 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:1, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}
2013-11-18 09:03:14,974 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:2, Num:1, Query:{[insert into S_SYS_MON (COL_A, COL_B, COL_C) values (?, ?, ?)][4, 2013-11-18 11:59:07.872, D]}
2013-11-18 09:04:16,999 [systemMonitoringScheduler-1] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:2, Num:1, Query:{[select SQ_S_SYS_MON.nextval from dual][]}

Начало и конец транзакции

Всегда полезно помнить о транзакциях, особенно в процессе отладки. С консолью Grep действительно легко найти соответствующую часть журнала для данной транзакции. После применения правильного выражения и стиля цвета все управление транзакциями становится хорошо видимым в журналах и не будет скрыто в строках журнала. Как видите, вся ситуация становится мгновенно узнаваемой исключительно на основании назначения цвета.

Цвет: # ffff00
Выражение:. .*org.hibernate.transaction.JDBCTransaction.*

1
2
3
4
5
6
7
2013-11-18 08:36:51,211 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – begin
2013-11-18 08:36:51,211 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – current autocommit status: true
2013-11-18 08:36:51,212 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – disabling autocommit
2013-11-18 08:36:51,223 [http-bio-8080-exec-6] DEBUG net.ttddyy.dsproxy.listener.CommonsQueryLoggingListener – Name:dmDataSource, Time:8, Num:1, Query:{[select count(*) from ABC where a like ? order by b asc][AI%]}
2013-11-18 08:36:51,226 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – commit
2013-11-18 08:36:51,229 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – re-enabling autocommit
2013-11-18 08:36:51,230 [http-bio-8080-exec-6] DEBUG org.hibernate.transaction.JDBCTransaction – committed JDBC Connection

Запрос и ответ веб-службы

Последнее интересное событие для меня — это получение SOAP-запроса или ответа из-за степени интеграции, требуемой / предоставляемой нашим приложением. Указав следующие два выражения, мы теперь можем точно отслеживать точки, когда сообщение входит / выходит из области нашего приложения.

Цвет: #03abff
Выражение:. .*org.springframework.ws.client.MessageTracing.*
Выражение:. .*org.springframework.ws.server.MessageTracing.*

01
02
03
04
05
06
07
08
09
10
11
12
13
14
2013-11-18 10:31:48,288 [http-bio-8080-exec-3] TRACE org.springframework.ws.soap.saaj.support.SaajUtils – SOAPElement [com.sun.xml.internal.messaging.saaj.soap.ver1_1.Envelope1_1Impl] implements SAAJ 1.3
2013-11-18 10:31:48,315 [http-bio-8080-exec-3] TRACE org.springframework.ws.server.MessageTracing.received – Received request [<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://a.b.c.com/product/v1.0">
<soapenv:Header/>
<soapenv:Body>
<xsd:getItem>
<xsd:itemId>1</xsd:itemId>
</xsd:getItem>
</soapenv:Body>
</soapenv:Envelope>]
2013-11-18 10:31:48,319 [http-bio-8080-exec-3] TRACE org.springframework.ws.soap.saaj.support.SaajUtils – SOAPElement [com.sun.xml.internal.messaging.saaj.soap.ver1_1.Body1_1Impl] implements SAAJ 1.3
2013-11-18 10:31:48,321 [http-bio-8080-exec-3] DEBUG org.springframework.ws.server.endpoint.mapping.PayloadRootAnnotationMethodEndpointMapping – Looking up endpoint for [{http://a.b.c.com/product/v1.0}getItemRequest]
2013-11-18 10:31:48,321 [http-bio-8080-exec-3] DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher – Endpoint mapping [org.springframework.ws.server.endpoint.mapping.PayloadRootAnnotationMethodEndpointMapping@7115660] maps request to endpoint [public com.c.b.a.v10.getItem com.c.b.a.ws.ws.endpoint.ItemQuery.getItem(com.c.b.a.v10.getItemRequestDocument)]
2013-11-18 10:31:48,324 [http-bio-8080-exec-3] TRACE org.springframework.ws.soap.saaj.support.SaajUtils – SOAPElement [com.sun.xml.internal.messaging.saaj.soap.ver1_1.Header1_1Impl] implements SAAJ 1.3
2013-11-18 10:31:48,325 [http-bio-8080-exec-3] DEBUG org.springframework.ws.soap.server.SoapMessageDispatcher – Testing endpoint adapter [org.springframework.ws.server.endpoint.adapter.GenericMarshallingMethodEndpointAdapter@16a77b1c]

Вывод

Использование этого плагина действительно упрощает процесс разработки и освобождает ваш разум от беспокойства о более важных проблемах, чем просмотр счетчиков журналов. Настройка довольно проста, и единственным ограничением является ваша способность находить интересующие вас события и создавать для них соответствующие правила. Еще одним большим преимуществом является возможность настраивать журналы консоли так, как выглядит ваша IDE, обеспечивая единую среду разработки. Это также отлично подходит для группового сотрудничества, поскольку, определяя общий набор стилей, вы всегда будете получать одинаковые результаты регистрации даже на компьютере своего коллеги. Я связался с разработчиком консоли Grep и спросил о возможности открытия внешних файлов в Grep Console для применения стилей, и он сам сказал, что это интересная идея, поэтому мы могли бы получить эту функциональность в будущих версиях плагина. После всего сказанного я нахожу консоль Grep одним из важнейших инструментов для улучшения процесса разработки и могу честно рекомендовать ее использование.