👨‍👨‍👦‍👦 🧒🏽 👐🏼 Hierarchische Protokollierung der Anwendung in der Datenbank 💫 ⬇️ 🤷🏼

Hallo alle zusammen!

In diesem Artikel möchte ich auf einen der Ansätze für die Anwendungsprotokollierung eingehen, der mir und meinen Kollegen beim Debuggen, bei der Fehlerbehebung und bei der Analyse von Leistungsproblemen sehr geholfen hat. Es wurden viele gute Artikel über die Notwendigkeit der Protokollierung geschrieben, auch über Habré. Daher ist es nicht sinnvoll, dies hier zu wiederholen. Ich begann meine IT-Karriere bei Oracle und studierte diese Datenbank aus den Büchern des Hauptexperten - Tom Kite. Ich erinnere mich an seinen Satz über die Protokollierung aus dem Buch "Effective Oracle by Design":

Die Instrumentierung ist kein Overhead. Overhead können Sie entfernen, ohne viel Nutzen zu verlieren. Das Entfernen (oder Nichtvorhandensein) von Instrumenten nimmt erhebliche Funktionen weg. Sie müssten dies nicht tun, wenn Ihre Systeme niemals kaputt gehen, niemals eine Diagnose benötigen und niemals unter Leistungsproblemen leiden. In diesem Fall müssen Sie Ihr System nicht instrumentieren (und mir Ihre E-Mail-Adresse senden, da ich ein Stellenangebot für Sie habe).

Mit der Arbeit an Oracle-Projekten begann alles.

Hierarchische Protokollierung in Oracle

Vor einiger Zeit arbeitete ich an einem Projekt zur Entwicklung eines großen Data Warehouse auf der Oracle-Plattform. Die Logik zum Laden, Überprüfen und Anreichern von Daten wurde in der Datenbank in PL / SQL implementiert. In Bezug auf die Protokollierung wurde die folgende Idee vorgeschlagen. Wenn Sie eine Anwendung global betrachten, handelt es sich um einen Baum von Aufrufen von Funktionen / Prozeduren (Methoden). In diesem Fall kann eine Methode in sich mehrere untergeordnete Methoden aufrufen, ihr Aufruf erfolgt jedoch genau von einer übergeordneten Methode. Auf diese Weise erhalten wir die Eltern / Kind-Hierarchie zwischen den Methoden (aufgerufen / aufgerufen), die natürlich in der Datenbank unter Verwendung der Felder id , parent_id modelliert wird , wobei parent_id der Fremdschlüssel im Feld id ist. Dies ist genau die gleiche Verbindung wie im klassischen Beispiel mit Mitarbeitern und ihren Managern (ein Mitarbeiter kann nur einen Manager haben, ein Manager kann mehrere Mitarbeiter haben). Das Protokollierungsschema kann wie folgt beschrieben werden:

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
/

Die erste Tabelle log_instances enthält Informationen zu jedem Anwendungsstart:

log_instance_name - name, zum Beispiel "sample_app_20200501"
start_ts / end_ts - Start- und Endzeit der Protokollierung ( end_ts ist leer, wenn die Anwendung gerade ausgeführt wird)
Status - 'C' (abgeschlossen) - Die Anwendung wurde fehlerfrei beendet. 'R' (wird ausgeführt.) - Die Anwendung wird ausgeführt. 'F' (fehlgeschlagen). - Die Anwendung wurde mit einem Fehler beendet.
start_log_id ist die Root-ID in der Aufrufhierarchie .

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).

, , , .
, , . : , .
, , . SQL . email id .

DML log_table (log_id). log_id sequence Oracle, . sequence .
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;
}

compile-time weaving aspectjc.
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.

:
- exception
- parent/child (/)
:
- SQL ,
- ,
:
- boilerplate
Java :
- . DevOps .
- boilerplate AOP, ( , runtime).
- , . Connection pool, , , — . . DML .

GitHub:

Oracle-Implementierung:

Java-Implementierung:

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

Hierarchische Protokollierung der Anwendung in der Datenbank

Hierarchische Protokollierung in Oracle

Java

API

Boilerplate Aspect Oriented Programming

More articles: