将应用程序分层记录到数据库

大家好！

在本文中，我想谈谈应用程序日志记录的一种方法，该方法极大地帮助了我和我的同事进行调试，疑难解答和分析性能问题。许多关于日志记录需求的好文章，包括在哈布雷（Habré）上写；因此，这里没有太多重复的感觉。我从Oracle开始IT生涯，并从主要专家Tom Kite的书中研究了该数据库。我记得他在《有效的Oracle设计》一书中关于日志记录的说法：

检测不是开销。您可以在不损失太多利益的情况下除去开销。卸下（或没有）仪器会占用大量功能。如果您的系统永不中断，不需要诊断并且不会遭受性能问题，则无需执行此操作。如果是这样，那么您就不需要检测系统（并向我发送您的电子邮件地址，因为我为您提供了工作机会）。

通过Oracle项目的工作，一切都开始了。

Oracle中的分层日志记录

前一段时间，我正在从事一个在Oracle平台上开发大型数据仓库的项目。加载，检查，丰富数据的逻辑是在PL / SQL数据库内部实现的。关于日志记录，提出了以下想法。如果您全局查看任何应用程序，那么它就是对函数/过程（方法）的调用树。在这种情况下，其内部的方法可以调用多个子方法，但是其调用恰好是从一个父方法发生的。因此，我们获得了方法之间的父/子层次结构（称为/被调用），这自然是使用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为空）
• 状态 -'C'（已完成）-应用程序无错误终止，'R'（正在运行）-应用程序正在运行，'F'（失败）-应用程序因错误而终止。
• 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;

, 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