Get best of the week

Journalisation hiérarchique de l'application dans la base de données

Bonjour à tous!


Dans cet article, je voudrais parler d'une des approches de la journalisation des applications, qui m'a beaucoup aidé, moi et mes collègues, à déboguer, dépanner et analyser les problèmes de performances. Beaucoup de bons articles ont été écrits sur la nécessité de se connecter, y compris sur Habré; par conséquent, il n'y a pas beaucoup de sens à répéter ici. J'ai commencé ma carrière informatique chez Oracle et j'ai étudié cette base de données dans les livres de l'expert principal - Tom Kite. Je me souviens de sa phrase sur la journalisation extraite du livre "Effective Oracle by Design":

L'instrumentation n'est pas une surcharge. Les frais généraux sont quelque chose que vous pouvez supprimer sans perdre beaucoup d'avantages. Supprimer (ou ne pas avoir) l'instrumentation enlève une fonctionnalité considérable. Vous n'auriez pas besoin de le faire si vos systèmes ne se cassent jamais, n'ont jamais besoin de diagnostics et ne souffrent jamais de problèmes de performances. Si cela est vrai, vous n'avez pas besoin d'instrumenter votre système (et de m'envoyer votre adresse e-mail, car j'ai une offre d'emploi pour vous).


Avec le travail sur des projets Oracle, tout a commencé.


Journalisation hiérarchique dans Oracle


Il y a quelque temps, je travaillais sur un projet de développement d'un grand entrepôt de données sur la plate-forme Oracle. La logique de chargement, de vérification, d'enrichissement des données a été implémentée à l'intérieur de la base de données en PL / SQL. En ce qui concerne l'exploitation forestière, l'idée suivante a été proposée. Si vous regardez globalement n'importe quelle application, alors c'est un arbre d'appels aux fonctions / procédures (méthodes). Dans ce cas, une méthode en elle-même peut appeler plusieurs méthodes enfants, mais son appel se produit exactement à partir d'une méthode parent. Ainsi, nous obtenons la hiérarchie parent / enfant entre les méthodes (appelées / appelées), qui est naturellement modélisée dans la base de données en utilisant les champs id , parent_id , où parent_id est la clé étrangère sur le champ id. Il s'agit exactement de la même relation que dans l'exemple classique avec les employés et leurs managers (un employé ne peut avoir qu'un seul manager, un manager peut avoir plusieurs employés). Le schéma de journalisation peut être décrit comme suit:


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
/

La première table log_instances contient des informations sur chaque démarrage d'application:


  • log_instance_name - nom, par exemple, "sample_app_20200501"
  • start_ts / end_ts - heure de début et de fin de la journalisation ( end_ts est vide si l'application est en cours d'exécution)
  • état - «C» (terminé) - l'application s'est terminée sans erreur, «R» (en cours d'exécution) - l'application est en cours d'exécution, «F» (a échoué) - l'application s'est terminée avec une erreur.
  • start_log_id est l'ID racine dans la hiérarchie des appels.

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_NAMESTATUSSTART_TSEND_TSCOMMENTS
sample_app_20200501C2020-05-01 16:37:46.7531682020-05-01 16:37:51.755380NULL
In procedure a()C2020-05-01 16:37:46.7535542020-05-01 16:37:51.754649procedure A(), line: 19
p_name_in: dummy_a
In procedure b()C2020-05-01 16:37:46.7538692020-05-01 16:37:49.753746procedure 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:


Implémentation d'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

Implémentation Java:


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

More articles:


All Articles