В этой статье мы рассмотрим легко встречающийся и в то же время легко избегаемый подводный камень, который может возникнуть при использовании clojure.core.logging, фактического фасада логирования для проектов Clojure. Я создам пример проекта, который будет имитировать реальный сценарий, доведенный до самых основ.
Суть в том, что время логирования (даже ниже активного порога логирования) будет увеличено на два порядка, в результате чего форма, для оценки которой требуется 379 мс, займет более 19,5 секунд только за счет добавления jar в classpath. Форма немного надуманная, но она имитирует произвольную «работу» и то, как логирование может сильно замедлить ваш код, если вы забудете, как был настроен ваш логгер (возможно, несколько лет назад).
tl;dr
- уточните реализацию вашего clojure.tools.logging. Со временем она может измениться по сравнению с тем, что вы думали изначально.
- следите за своими деплоями. Очень легко накопить их больше, чем вы думаете.
Настройка
Давайте создадим базовый проект, включающий логгер. Я думаю, что самый приятный способ запустить новый проект — это использовать один из инструментов, созданных Borkdude, под названием neil. Если он у вас установлен, просто выполните следующие действия в пустом каталоге:
neil add build
Это даст нам отличный шаблон для начала нашего примера. Если у вас не установлен neil (а он должен быть установлен), просто создайте следующий deps.edn:
{:deps {}
:aliases {
:build ;; added by neil
{:deps {io.github.clojure/tools.build {:git/tag "v0.8.3" :git/sha "0d20256"}}
:ns-default build}}}
Найдите учебник по log4j2 или скопируйте конфиг из вашего последнего проекта, и мы получим следующее состояние:
{:deps {org.clojure/tools.logging {:mvn/version "1.2.4"}
org.apache.logging.log4j/log4j-api {:mvn/version "2.18.0"}
org.apache.logging.log4j/log4j-core {:mvn/version "2.18.0"}}
:aliases {
:build ;; added by neil
{:deps {io.github.clojure/tools.build {:git/tag "v0.8.3" :git/sha "0d20256"}}
:ns-default build}}}
Создайте каталог src и вставьте следующее в src/log4j2.xml:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
<Appenders>
<Console name="Console">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
</Console>
</Appenders>
<Loggers>
<Root level="WARN">
<AppenderRef ref="Console"/>
</Root>
</Loggers>
</Configuration>
Создание jar
Давайте создадим jar:
$ clj -T:build uber
$ cp target/lib1-1.2.1-standalone.jar log4j2-uber.jar
Я не буду использовать инструменты и запущу все через repl в командной строке прямо из jar. Еще одна вещь, которую я хочу сделать, это включить невероятную библиотеку criterium, чтобы мы могли проводить профилирование. Я намеренно включаю Criterium отдельно, потому что вы не должны иметь такой инструмент для разработчиков, как Criterium, в убер-джаре. И знание того, как легко объединить другие банки с вашей настоящей производственной банкой, может быть очень полезным. Я взял jar из своего кэша .m2.
$ java -cp log4j2-uber.jar:criterium.jar clojure.main
user=> (require '[clojure.tools.logging :as log])
nil
user=> (time (reduce (fn [acc x] (log/info "accumulating") (+ acc x)) 0 (range 10000000)))
"Elapsed time: 447.684167 msecs"
49999995000000
user=>
А теперь мы смоделировали некоторую работу, которая занимает примерно полсекунды на этом прогоне.
Изменение
Теперь предположим, что возникли требования к работе, и нам нужно разобраться со sparksql. Это не особенно актуально, но вы можете представить себе любой особенно большой jar, или, может быть, просто накопление jars со временем. Давайте добавим org.apache.hive/hive-jdbc {:mvn/version "3.1.3"} в нашу карту :deps.
;; deps.edn with the hive-jdbc driver
{:deps {org.clojure/tools.logging {:mvn/version "1.2.4"}
org.apache.logging.log4j/log4j-api {:mvn/version "2.18.0"}
org.apache.logging.log4j/log4j-core {:mvn/version "2.18.0"}
org.apache.hive/hive-jdbc {:mvn/version "3.1.3"}}
:aliases {
:build ;; added by neil
{:deps {io.github.clojure/tools.build {:git/tag "v0.8.3" :git/sha "0d20256"}}
:ns-default build}}}
Изменения, необходимые для сборки
Это не имеет особого отношения к нашей сборке, но нам придется поработать над тем, как работает tools.build. Либ tools.build является выдающимся и весьма полезным. Она занимает немного места, но мы получаем простые программы, которые создают наши банки. Способ, которым она создает банки, заключается в копировании всех файлов классов из банок, от которых мы зависим, для создания одного uberjar. Я пишу этот пост на OSx, которая не чувствительна к регистру. Jar-файлы — это zip-файлы, которые чувствительны к регистру. И это приводит к проблеме: jar-файл может легко включать foo/bar.txt и файл FOO; но моя файловая система, не чувствительная к регистру, не может допустить сосуществования этих двух вещей. С ее точки зрения, я хочу иметь файл с именем foo, а также папку с именем foo (независимо от того, что мы знаем ее верхний регистр). Нам нужно исключить эти файлы, чтобы не попасть в это непредставимое состояние.
Мы обновим файл build.clj, который neil создал для нас, добавив несколько записей :exclude, чтобы предотвратить попадание в такую ситуацию. Дополнительную документацию смотрите в doc-строке b/uber.
(defn uber [_]
(clean nil)
(b/copy-dir {:src-dirs ["src" "resources"]
:target-dir class-dir})
(b/compile-clj {:basis basis
:src-dirs ["src"]
:class-dir class-dir})
(b/uber {:class-dir class-dir
:exclude ["META-INF/license/.*" "license/LICENSE.*" "license.*"]
:uber-file uber-file
:basis basis
:main 'clojure.main}))
Новый jar с hive
Опять же, не особенно важно, что jar — это jar hive-jdbc, но он представляет состояние, которое может накапливаться со временем в проекте, и даже от одного jar. Давайте соберем jar и запустим ту же форму, что и ранее.
$ clj -T:build uber # this can take a little bit, its a big jar
$ cp target/lib1-1.2.1-standalone.jar with-hive.jar
$ java "$(socket-repl 6001)" -cp with-hive.jar:criterium.jar clojure.main
Clojure 1.11.1
user=> (require '[clojure.tools.logging :as log])
nil
user=> (time (reduce (fn [acc x] (log/info "accumulating") (+ acc x)) 0 (range 10000000)))
"Elapsed time: 19681.165584 msecs"
49999995000000
А вот и наша ошибка: мы ничего не сделали с существующим кодом. Мы не изменили наш файл log4j2.xml. Мы ничего не изменили, кроме добавления jar в classpath, но теперь наша имитация «работы» (сложение нескольких чисел) вместо половины секунды заняла более 19 секунд.
Диагностика
Поскольку у нас есть criterium в нашем classpath, мы можем провести бенчмарк из каждой реплики.
user=> (require '[clojure.tools.logging :as log]
'[clojure.tools.logging.impl :as log.impl]
'[criterium.core :refer [bench]])
nil
user=> (bench (log/trace "no-op"))
Это выведет некоторую статистику, но цифры, которые нас интересуют, находятся во второй строке
log4j2-uber: 21.209608 ns
with-hive.jar: 1.911062 µs (1911 ns!)
Вот наши два порядка величины. И еще одну подсказку о том, что происходит, можно найти, проверив clojure.tools.logging/*logger-factory* для каждой реплики:
;; log4j2-uber.jar:
user=> (log.impl/name log/*logger-factory*)
"org.apache.logging.log4j"
;; with-hive.jar
user=> (log.impl/name log/*logger-factory*)
"org.slf4j"
Объяснение
Фактическим фасадом логирования для Clojure является clojure.tools.logging. Он пытается представить унифицированный интерфейс для взаимодействия с экосистемой протоколирования java в целом. Для этого он знает, как обеспечить соответствие (log/trace "no-op") классам trace и логгеру для вашего конкретного логгера.
Это достигается путем проверки наличия классов, указывающих на то, что конкретный логгер находится в classpath, и использует первый найденный.
(defn find-factory
"Returns the first non-nil value from slf4j-factory, cl-factory,
log4j2-factory, log4j-factory, and jul-factory."
[]
(or (slf4j-factory)
(cl-factory)
(log4j2-factory)
(log4j-factory)
(jul-factory)
(throw ; this should never happen in 1.5+
(RuntimeException.
"Valid logging implementation could not be found."))))
Раньше мы падали на (log4j2-factory), но теперь, в связи с расширением jar, в качестве фабрики логгеров регистрируется первый (slf4j-factory).
Исправление
В readme есть хороший раздел о выборе реализации логирования. Я усвоил урок, что это гораздо важнее, чем я думал вначале. В лучшем случае, это был посторонний вопрос, и обычно он полностью игнорировался. Но если оставить это без внимания, то можно оказаться во власти очень серьезных потерь производительности.
Из README:
Приведенный выше подход проблематичен, поскольку приложения часто непреднамеренно втягивают несколько реализаций протоколирования в качестве транзитивных зависимостей. Поэтому настоятельно рекомендуется установить системное свойство.
$ java -Dclojure.tools.logging.factory=clojure.tools.logging.impl/log4j2-factory -cp with-hive.jar:criterium.jar clojure.main
Clojure 1.11.1
user=> (require '[clojure.tools.logging :as log])
nil
user=> (time (reduce (fn [acc x] (log/info "accumulating") (+ acc x)) 0 (range 10000000)))
"Elapsed time: 373.54025 msecs"
49999995000000
Таким образом, с тем же with-hive.jar, если мы установим нашу реализацию логгера, мы вернемся к 373 мс вместо 19 секунд.
Уроки:
Я надеюсь, что это будет полезно для людей. Это немного надуманный пример, но я надеюсь, что в нем присутствует зародыш опыта реального мира. Жесткий цикл здесь делает совершенно очевидным, что что-то пошло не так. Но в реальной жизни эти провалы в производительности могут быть распределены во времени в вашем коде, никогда не добавляя достаточно микросекунд, чтобы вы почувствовали, но всегда снижая пропускную способность.
Я также думаю, что этот сценарий не так уж и надуман, чтобы встретиться в реальной жизни. Когда в последний раз вы проводили аудит своих деплоев, чтобы узнать, сколько логгеров у вас на самом деле? Задавали ли вы явным образом logger-factory для вашего uberjar? Для меня ответ был «давно» и «нет».
Хорошее предположение — подумать, каким, по вашему мнению, является ваш логгер, а затем оценить форму (log.impl/name log/*logger-factory*) и посмотреть, правильно ли вы поняли. Проверьте clj -Stree | grep log в этом образце репозитория. Он включает наши log4j2, slf4j, logback, commons-logging и, кажется, log4j. Их легко накопить.
Postscript
На самом деле, есть еще один момент, но он не обязателен для понимания общей сути. Но это укусило нас на работе, когда мы не добавили новый логгер в classpath, а промолчали о предупреждении.
При запуске мы видели сообщение в журнале:
WARNING: sun.reflect.Reflection.getCallerClass не поддерживается. Это повлияет на производительность.
Немного погуглив, мы выяснили, что это предупреждение появляется, когда у вас есть многорелизный jar, но у вас нет свойства Multi-Release: true в вашем файле манифеста. Поэтому мы убедились, что наш манифест добавлен правильно, и забыли об этом. Затем к нам стали поступать сообщения о том, что запросы стали намного медленнее. Прошло некоторое время, и коллеге потребовалось время, чтобы отследить регрессию до поиска логгеров при регистрации, и мы в замешательстве вернули изменение.
Вы можете убедиться в этом сами, отредактировав манифест with-hive.jar, чтобы удалить мультирелиз. Помня, что имитация работы заняла 19 секунд с логгером slf4j.
$ java -cp with-hive-not-multirelease.jar:criterium.jar clojure.main
Clojure 1.11.1
user=> (require '[clojure.tools.logging :as log])
nil
user=> (time (reduce (fn [acc x] (log/info "accumulating") (+ acc x)) 0 (range 10000000)))
WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance.
"Elapsed time: 3615.623583 msecs"
49999995000000
Это 3,6 секунды (вместо 0,3 секунды, которые, как мы знаем, возможны). Но это тот штраф за производительность, который может быть легко размазан по вашей кодовой базе.
Постскрипт
Часто лучше позволить убер-джарам идти и делать свои дела, чем запускать их с помощью clojure.main. Сокетные ответы делают невероятно приятной возможность зайти в уберджар, пока он использует свою основную точку входа для обслуживания веб-запросов или чего-либо еще. Если ваш профайлинг требует некоторой настройки, это часто является отличным способом убедиться, что он инициализируется так, как нужно, и у вас есть repl прямо в хорошее рабочее состояние.
Clojure позволяет использовать некоторые системные свойства для легкого запуска repl, но это может быть немного многословным. Ниже приведена удобная функция оболочки, которую я постоянно использую:
# huge props to p-himik on the Clojurians slack for this
# sample usage: clj -J"$(socket-repl 6000)" ... or java "$(socket-repl 6000) -jar ...
socket-repl()
{
echo -n "-Dclojure.server.repl={:port $1 :accept clojure.core.server/repl}"
}
Затем вы можете легко запускать реплеи следующим образом:
$ java "$(socket-repl 6000)" -cp log4j2-uber.jar:criterium.jar clojure.main
Clojure 1.11.1
user=>
## or with `clj` or `clojure` command line tools:
$ clj -J"$(socket-repl 6009)" -A:build
Затем просто netcat localhost <port> и у вас есть ответ на любой запущенный jar.
Очень удобно работать, если ваш редактор может подключаться к сокетным реплам. Это делает запуск repl из jar или из вашей обычной «dev» установки почти неотличимым. Я могу легко выполнять repl из prod jar как из ветки в Clojure, и мой рабочий процесс точно такой же, потому что я использую inf-clojure