06.05.2020 08:59
mospan-n 6 1300 Источник

Всем, привет!


В статье я хотел бы рассказать об одном из подходов к логированию приложения, который сильно помогал мне и коллегам при отладке, поиске ошибок и анализе проблем производительности. Про необходимость логирования было написано множество хороших статей в том числе и на Хабре, поэтому здесь нет большого смысла повторяться. Я начинал карьеру в IT с Oracle и изучал эту БД по книгам главного эксперта — Тома Кайта. Мне запомнилась его фраза по поводу логирования из книги "Effective Oracle by Design":

Instrumentation is not overhead. Overhead is something you can remove without losing much benefit. Removing (or not having) instrumentation takes away considerable functionality. You wouldn’t need to do this if your systems never break, never need diagnostics, and never suffer from performance issues. If that is true, you don’t need to instrument your system (and send me your email address, because I have a job offer for you).


С работой над Oracle проектами всё и началось.


Иерархическое логирование в Oracle


Какое-то время назад я работал на проекте разработки крупного Хранилища Данных на платформе Oracle. Логика загрузки, проверки, обогащения данных была реализована внутри БД на языке PL/SQL. В отношение логирования была предложена следующая идея. Если глобально посмотреть на любое приложение, то оно представляет из себя дерево вызовов функций/процедур(методов). При этом метод внутри себя может вызвать несколько дочерних методов, но его вызов происходит ровно из одного родительского метода. Таким образом мы получаем parent/child иерархию между методами (вызывающий/вызываемый), которая естественным образом моделируется в базе данных с помощью полей id, parent_id, где parent_id есть внешний ключ на поле id. Это ровно такая же связь, как и в классическом примере с сотрудниками и их менеджерами (у сотрудника может быть только один менеджер, у менеджера может быть несколько сотрудников). Схему логирования можно описать следующим образом:


create table log_instances (
  start_log_id number(16) not null
  , log_instance_name varchar2(100) not null
  , start_ts timestamp(6) not null
  , end_ts timestamp(6)
  , status varchar2(1) not null
  , log_date date not null,
  , constraint log_instances_pk primary key(start_log_id))
/

create index log_instances_name_idx on log_instances(log_instance_name)
/

create table log_table (
  action_name varchar2(64) not null,
  log_id  NUMBER(16) not null,
  parent_log_id NUMBER(16),
  start_ts timestamp(6) not null,
  end_ts timestamp(6),
  status varchar2(1) not null,
  comments varchar2(4000),
  exception_message varchar2(4000),
  large_text CLOB,
  log_date date not null,
  constraint log_table_status_chck check (status in ('C'/*completed*/, 'R'/*running*/, 'F'/*failed*/))
)
partition by range (log_date)
interval(NUMTODSINTERVAL(7,'day'))
(partition p_fst_day_of_week values less than (date '...'))
/

create index log_table_log_id_idx on log_table(log_id) local
/

create index log_table_parent_id_idx on log_table(parent_log_id) local
/

create index log_table_action_name_idx on log_table(action_name) local
/

В первую таблицу log_instances пишется информация о каждом старте приложения:


  • log_instance_name — название, например "sample_app_20200501"
  • start_ts/end_ts — время начала и окончания логирования (end_ts пустое, если приложение в данный момент выполняется)
  • status — 'C' (completed) — приложение завершилось без ошибок, 'R'(running) — приложение выполняется, 'F'(failed) — приложение завершилось с ошибкой.
  • start_log_id — корневой id в иерархии вызовов.

Таблица log_table содержит информацию о каждой активности внутри приложения и её связь с родительской активностью.


  • action_name — название логируемой активности
  • start_ts/end_ts — дата начала/окончания логируемой активности
  • status — 'C' (completed) — активность завершилась без ошибок, 'R'(running) — активность выполняется, 'F'(failed) — активность завершилась с ошибкой.
  • exception_message — если активность завершилась с ошибкой, то будет записан error stack trace с номером строки, где произошло исключение

На основе этих таблиц создаётся API (в Oracle API обычно реализуются с помощью пакетов и набора процедур/функций в них). Методы:


  • PROCEDURE start_logging(instance_name) — начать логирование, создать контекст логирования, создать строку в таблице log_instances
  • PROCEDURE open_next_level(action_name, comments, clob_text) — начать логирование активности в текущем контексте. Создать строку в таблице log_table
  • PROCEDURE close_level_success — завершить логирование активности со статусом 'C'
  • PROCEDURE close_level_fail — завершить логирование активности со статусом 'F'
  • PROCEDURE stop_log_success — завершить логирование приложения со статусом 'C'
  • PROCEDURE stop_log_fail — завершить логирование приложения со статусом 'F'

Контекст логирования


Под контекстом логирования понимается набор следующих сессионных переменных (в Oracle их ещё называют пакетными):


  • id корня дерева вызовов
  • текущий id, по которому будет происходить INSERT/UPDATE в log_table
  • родительский id в log_table для определения записи, после того как произошло завершение логирования текущей активности

Методы из pk_util_log управляют состоянием контекста. При необходимости можно дополнить API удобными методами:
-info — после open_level сразу вызываем close_level. Таким образом мы просто логируем какой-то факт по аналогии с logger.info в Java.
-resume_logging (parent_log_id) — позволяет начать логирование в текущей контекст из другой сессии. Для этого нужно передать id родительской записи в log_table.


Пример


DECLARE
    PROCEDURE b(p_name_in IN VARCHAR2) IS
        v_dummy_cnt PLS_INTEGER;
    BEGIN
        pk_util_log.open_next_level(p_action_name_in => 'In procedure b()',
                        p_comments_in => 'procedure B(), line: ' || $$PLSQL_LINE || chr(13) || chr(10) ||
                                                     'p_name_in: ' || p_name_in);
        dbms_lock.sleep(3);
        pk_util_log.close_level_success;
    EXCEPTION
        WHEN OTHERS THEN
            pk_util_log.close_level_fail;
            RAISE;
    END;

    PROCEDURE a(p_name_in IN VARCHAR2) IS
    BEGIN
        pk_util_log.open_next_level(p_action_name_in => 'In procedure a()',
                            p_comments_in => 'procedure A(), line: ' || $$PLSQL_LINE || chr(13) || chr(10) ||
                                    'p_name_in: ' || p_name_in);
        b('dummy_b');
        dbms_lock.sleep(2);
        pk_util_log.close_level_success;
    EXCEPTION
        WHEN OTHERS THEN
            pk_util_log.close_level_fail;
            RAISE;
    END;

BEGIN
    pk_util_log.start_logging('sample_app_20200501');
    dbms_output.put_line(pk_util_log.get_start_log_id);
    a('dummy_a');
    pk_util_log.stop_log_success;
exception
    when others then
        pk_util_log.stop_log_fail;
        raise;
END;
/

Сначала мы получаем start_log_id:


select start_log_id from log_instances where log_instance_name = 'sample_app_20200501';

Теперь по start_log_id мы можем получить весь лог приложения с помощью иерархического запроса:


SELECT
    LPAD (' ', 2* (LEVEL- 1)) || l.action_name as action_name,
    l.status,
    l.start_ts,
    l.end_ts,
    l.comments
FROM
    tech_log_table l
START WITH l.log_id = 204 /*start_log_id*/
CONNECT BY
    l.parent_log_id = PRIOR l.log_id
ORDER SIBLINGS BY
    l.log_id ASC;

ACTION_NAME STATUS START_TS END_TS COMMENTS
sample_app_20200501 C 2020-05-01 16:37:46.753168 2020-05-01 16:37:51.755380 NULL
In procedure a() C 2020-05-01 16:37:46.753554 2020-05-01 16:37:51.754649 procedure A(), line: 19
p_name_in: dummy_a
In procedure b() C 2020-05-01 16:37:46.753869 2020-05-01 16:37:49.753746 procedure B(), line: 6
p_name_in: dummy_b

Видно, что время выполнения процедуры a(p_name_in) складывается из собственных активностей плюс время выполнения дочерней процедуры b(p_name_in).


Зачем это нужно


  1. Можно получать ответы на вопросы, касающиеся времени выполнения активностей, например, какой вклад по времени дочерняя активность внесла во время выполнения родительской.
  2. Проследить логику работы приложения, последовательность вызова методов, их вложенность. Это помогает присоединившимся коллегам быстрее разобраться в специфике приложения: они могут запустить его на тестовых данных, выполнить запрос получения иерархического лога и посмотреть логику вызовов.
  3. Появляется единый язык общения между разработчиками, тестировщиками, инженерами поддержки. Все используют один и тот же SQL анализа лога. При анализе проблемы вместо обмена лог файлов по email коллеги ссылаются на id записей в лог таблице.

Несколько замечаний по реализации:


  1. DML операции с log_table используют первичный ключ (log_id). log_id генерируется через sequence объект в Oracle, обеспечивает уникальность и неблокирующий доступ. При создании sequence можно также указывать количество элементов для кэширования в каждой сессии для дальнейшего уменьшения проблем одновременного доступа.
  2. Для log_table нужно предусмотреть механизм архивации, потому что эта таблица будет очень активно расти. В случае с Oracle удобным механизмом будет интервальное партиционирование, где партиции добавляются автоматически по мере необходимости. Неактуальные партиции можно эффективно удалять, переносить в архив.

После Oracle проектов я немного поменял специализацию и перешёл на проекты, где бизнес логика реализовывалась в Java. И со временем мне пришла идея перенести иерархическое логирование на Java API.


Иерархическое логирование в Java


Итак, первое с чем надо было определиться, стала База Данных для логов. Мой выбор пал на PostgreSql как наиболее близкий к Oracle вариант в мире Open Source.


Для того, чтобы не создавать каждый раз новый Connection объект при записи в БД логирования, используется Connection Pool к ней (например HikariCP).


Контекст логирования в случае реализации бизнес логики в БД привязан к сессии. В Java он привязан к текущему thread'у. Для этого используется класс ThreadLocal, а точнее InheritableThreadLocal, чтобы дочерний thread наследовал контекст логирования от родителя.


API


Методы логирования:


  • public static void startLog(final String logInstanceName)
  • public static void openNextLevel(final String actionName, final String comments)
  • public static void stopLogSuccess()
  • public static void stopLogFail(final Exception exception)
  • public static void closeLevelSuccess()
  • public static void closeLevelFail(final Exception exception)

Пример:


public class A {
    public static void main(String[] args) {
        try {
            LogUtils.startLog("sample_app_20200501");
            A a = new A();
            a.method1("some string");
            LogUtils.stopLogSuccess();
        } catch (Exception e) {
            LogUtils.stopLogFail(e);
            throw new RuntimeException(e);
        }
    }

    private String method1(String s) {
        try {
            LogUtils.openNextLevel("method1", "Arguments: " + s);
            method2(1, 2);
            LogUtils.closeLevelSuccess();
            return s;
        } catch (Exception e) {
            LogUtils.closeLevelFail(e);
            throw new RuntimeException(e);
        }
    }

    private long method2(int i1, int i2) {
        try {
            LogUtils.openNextLevel("method2", "Arguments: " + i1 + ", " + i2);
            LogUtils.closeLevelSuccess();
            return i1 + i2;
        } catch (Exception e) {
            LogUtils.closeLevelFail(e);
            throw new RuntimeException(e);
        }
    }

}

Для того чтобы получить лог, мы как и в предыдущем примере получаем из log_instances id корня дерева (start_log_id) и выполняем иерархический запрос. В случае с PostgreSql запрос пишется через RECURSIVE WITH:


WITH RECURSIVE log AS (
    SELECT 1                as level,
           ARRAY [l.log_id] AS path,
           l.log_id,
           l.action_name,
           l.parent_log_id,
           l.start_ts,
           l.end_ts,
           l.status,
           l.comments,
           l.exception_message
    FROM log_table l
    WHERE l.log_id = ...
    UNION ALL
    SELECT l.level + 1 as level,
           path || l1.log_id,
           l1.log_id,
           l1.action_name,
           l1.parent_log_id,
           l1.start_ts,
           l1.end_ts,
           l1.status,
           l1.comments,
           l1.exception_message
    FROM log_table l1
             INNER JOIN log l ON l.log_id = l1.parent_log_id
)
SELECT
       lpad(' ', (l.level - 1) * 2) || l.log_id as log_id,
       l.action_name,
       l.start_ts,
       l.end_ts,
       l.end_ts - l.start_ts as duration,
       l.status,
       l.comments,
       l.exception_message
FROM log l
order by l.path, l.start_ts;

Boilerplate код и Aspect Oriented Programming


В предыдущем примере мы видим, что для того, чтобы корректно логировать время выполнения метода, а также выбрасываемый им exception мы должны в каждом методе писать:


try {
    LogUtils.openNextLevel(...);
    ...
    LogUtils.closeLevelSuccess();
} catch (Exception e) {
    LogUtils.closeLevelFail(e);
    throw new RuntimeException(e);
}

Это "загрязняет" код, требует определённой внимательности и дисциплины при добавлении новых методов. Частично эту проблему можно решить с помощью code templates, которые предоставляет любая современная IDE и со временем вызовы логирования не будут отвлекать при чтении логики метода. Есть и другое более элегантное решение: использовать функционал Aspect Oriented Programming (AOP). Эта тема заслуживает отдельных статей и даже книг, но если говорить совсем кратко, то AOP — это техника решения задач, присущих всему приложению (cross-cutting concerns). К таким задачам относятся поддержка транзакций, безопасность, логирование. В AOP мы отдельно определяем дополнительную функциональность (advice) и места, куда необходимо эту функциональность добавить (pointcut). Сочетание pointcut и advice называется аспектом. Далее мы можем декларативно с помощью аннотаций помечать методы, к которым хотим дополнительную функциональность добавить. Эта дополнительная функциональность может добавляться (weave) на разных этапах: compile-time, post-compile, load-time. Я приведу пример compile-time weaving, используя популярную AOP библиотеку AspectJ.


Итак, мы хотим создать аннотацию @LogToDb, чтобы при добавлении её к методу, происходило логирование аргументов. возвращаемого значения и времени выполнения:


@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface LogToDb {
    boolean suppressLogArgs() default false;
    boolean suppressLogResult() default false;
}

Тогда аспект будет выглядеть так:


@Aspect
public class LogToDbAspect {
    @Pointcut("@annotation(logToDb) && execution(* *.*(..))")
    public void logToDbPointcut(LogToDb logToDb) {
    }

    @Around(value = "logToDbPointcut(logToDb)")
    public Object around(ProceedingJoinPoint pjp, LogToDb logToDb) throws Throwable {
        try {
            LogUtils.openNextLevel(pjp.getSignature().toShortString(),
                    logToDb.suppressLogArgs() ? null : AspectUtils.getArgsString(pjp.getArgs()));
            Object result = pjp.proceed();
            if (!logToDb.suppressLogResult()) {
                LogUtils.addComments("\nResult: " + result.toString());
            }
            LogUtils.closeLevelSuccess();
            return result;
        } catch (Exception e) {
            LogUtils.closeLevelFail(e);
            throw new RuntimeException(e);
        }
    }
}

И теперь вместо boilerplate кода:


private String method1(String s) {
    try {
        LogUtils.openNextLevel("method1", "Arguments: " + s);
        LogUtils.addComments("\nResult: " + s);
        LogUtils.closeLevelSuccess();
        return s;
    } catch (Exception e) {
        LogUtils.closeLevelFail(e);
        throw new RuntimeException(e);
    }
}

Можно писать просто:


@LogToDb
private String method1(String s) {
    return s;
}

К сожалению такое удобство влечёт определённые последствия:


  1. При compile-time weaving используется сторонний компилятор aspectjc.
  2. aspectjc компилятор может конфликтовать с другим библиотеками аннотаций, которые добавляют код на этапе компиляции. В частности aspectjc не совместим с Lombok. При сборке будет происходить такая ошибка:

[WARNING] You aren't using a compiler supported by lombok, so lombok will not work and has been disabled.
Your processor is: org.aspectj.org.eclipse.jdt.internal.compiler.apt.dispatch.BatchProcessingEnvImpl
Lombok supports: sun/apple javac 1.6, ECJ

Необходимо будет использовать lombok-maven-plugin, чтобы на вход aspectjc уже подавался код с учётом генерации от lombok.


Итоги


В заключение я хотел бы выделить ключевые моменты:


  1. Иерархическое логирование в БД логирует:
    • время начала и окончания активности
    • exception
    • parent/child связь (вызывающий/вызываемый)
  2. Плюсы такого логирования:
    • единый SQL для удобного анализа времён выполнения, логики
    • информация о запусках приложения хранится в одной таблице, их удобно сравнивать
  3. Недостатки:
    • логирование предполагает наличие boilerplate кода
    • нужно помнить о периодическом архивировании лог таблицы
  4. При реализации в Java необходимо учитывать следующие факторы:
    • появляется дополнительная зависимость от БД. При современном уровне развития DevOps процессов на мой взгляд это небольшая проблема.
    • boilerplate код можно убрать с помощью техник AOP, но надо анализировать последствия (сторонний компилятор, влияние на runtime).
    • ожидается, что время на запись в БД логирования пренебрежимо мало по сравнению с работой приложения. Connection pool, изменение таблицы логирования через первичный ключ, расположение БД на том же хосте, что и приложение — всё это способствует данному утверждению. Однако необходимо убедиться в этом на своём окружении. При необходимости DML операции с таблицей логирования можно делать асинхронно.

Ссылки


Примеры реализации иерархического логирования можно посмотреть на моём GitHub:


Реализация в Oracle:


  1. https://github.com/nikita-mospan/plsql-liquibase-utplsql/blob/master/src/main/resources/oracle/tech_user/packages/pk_util_log.pks
  2. https://github.com/nikita-mospan/plsql-liquibase-utplsql/blob/master/src/main/resources/oracle/tech_user/packages/pk_util_log.pkb

Реализация в Java:


  1. https://github.com/nikita-mospan/log-to-db