【PL/SQL】インストゥルメンテーション設計｜DBMS_APPLICATION_INFO・ログトレース

CREATE TABLE plsql_log (
  log_id            NUMBER GENERATED BY DEFAULT AS IDENTITY PRIMARY KEY,
  log_level         VARCHAR2(10) NOT NULL,
  correlation_id    VARCHAR2(100),
  module_name       VARCHAR2(100),
  action_name       VARCHAR2(100),
  process_key       VARCHAR2(200),
  message           VARCHAR2(4000),
  detail_json        CLOB,
  sql_code          NUMBER,
  sql_error_message VARCHAR2(4000),
  error_backtrace   VARCHAR2(4000),
  elapsed_ms        NUMBER,
  session_user      VARCHAR2(128),
  current_user      VARCHAR2(128),
  client_identifier VARCHAR2(128),
  created_at        TIMESTAMP DEFAULT SYSTIMESTAMP NOT NULL
);

CREATE INDEX ix_plsql_log_01
  ON plsql_log(correlation_id, created_at);

CREATE INDEX ix_plsql_log_02
  ON plsql_log(module_name, action_name, created_at);

BEGIN
  DBMS_SESSION.SET_IDENTIFIER(
    client_id => :correlation_id
  );
END;
/

SELECT sid,
       serial#,
       username,
       client_identifier,
       module,
       action
  FROM v$session
 WHERE client_identifier = :correlation_id;

CREATE OR REPLACE PACKAGE instr_pkg AS
  PROCEDURE set_action(
    p_module IN VARCHAR2,
    p_action IN VARCHAR2
  );

  PROCEDURE clear_action;
END;
/

CREATE OR REPLACE PACKAGE BODY instr_pkg AS
  PROCEDURE set_action(
    p_module IN VARCHAR2,
    p_action IN VARCHAR2
  ) IS
  BEGIN
    DBMS_APPLICATION_INFO.SET_MODULE(
      module_name => p_module,
      action_name => p_action
    );
  END;

  PROCEDURE clear_action IS
  BEGIN
    DBMS_APPLICATION_INFO.SET_MODULE(NULL, NULL);
  END;
END;
/

BEGIN
  instr_pkg.set_action('ORDER_IMPORT', 'VALIDATE');
  validate_orders(:load_id);

  instr_pkg.set_action('ORDER_IMPORT', 'MERGE');
  merge_orders(:load_id);

  instr_pkg.set_action('ORDER_IMPORT', 'NOTIFY');
  notify_result(:load_id);

  instr_pkg.clear_action;
EXCEPTION
  WHEN OTHERS THEN
    instr_pkg.clear_action;
    RAISE;
END;

CREATE OR REPLACE PACKAGE logger_pkg AS
  PROCEDURE write_log(
    p_level          IN VARCHAR2,
    p_message        IN VARCHAR2,
    p_process_key    IN VARCHAR2 DEFAULT NULL,
    p_detail_json    IN CLOB DEFAULT NULL,
    p_sql_code       IN NUMBER DEFAULT NULL,
    p_error_message  IN VARCHAR2 DEFAULT NULL,
    p_backtrace      IN VARCHAR2 DEFAULT NULL,
    p_elapsed_ms     IN NUMBER DEFAULT NULL
  );
END;
/

CREATE OR REPLACE PACKAGE BODY logger_pkg AS
  PROCEDURE write_log(
    p_level          IN VARCHAR2,
    p_message        IN VARCHAR2,
    p_process_key    IN VARCHAR2 DEFAULT NULL,
    p_detail_json    IN CLOB DEFAULT NULL,
    p_sql_code       IN NUMBER DEFAULT NULL,
    p_error_message  IN VARCHAR2 DEFAULT NULL,
    p_backtrace      IN VARCHAR2 DEFAULT NULL,
    p_elapsed_ms     IN NUMBER DEFAULT NULL
  ) IS
    PRAGMA AUTONOMOUS_TRANSACTION;
  BEGIN
    INSERT INTO plsql_log (
      log_level,
      correlation_id,
      module_name,
      action_name,
      process_key,
      message,
      detail_json,
      sql_code,
      sql_error_message,
      error_backtrace,
      elapsed_ms,
      session_user,
      current_user,
      client_identifier
    ) VALUES (
      p_level,
      SYS_CONTEXT('USERENV', 'CLIENT_IDENTIFIER'),
      SYS_CONTEXT('USERENV', 'MODULE'),
      SYS_CONTEXT('USERENV', 'ACTION'),
      p_process_key,
      p_message,
      p_detail_json,
      p_sql_code,
      p_error_message,
      p_backtrace,
      p_elapsed_ms,
      SYS_CONTEXT('USERENV', 'SESSION_USER'),
      SYS_CONTEXT('USERENV', 'CURRENT_USER'),
      SYS_CONTEXT('USERENV', 'CLIENT_IDENTIFIER')
    );

    COMMIT;
  EXCEPTION
    WHEN OTHERS THEN
      ROLLBACK;
      NULL;
  END;
END;
/

DECLARE
  v_started_at TIMESTAMP := SYSTIMESTAMP;
BEGIN
  instr_pkg.set_action('PAYMENT_JOB', 'APPLY_PAYMENT');

  apply_payment(:payment_id);

EXCEPTION
  WHEN OTHERS THEN
    logger_pkg.write_log(
      p_level         => 'ERROR',
      p_message       => 'apply_payment failed',
      p_process_key   => 'payment_id=' || :payment_id,
      p_sql_code      => SQLCODE,
      p_error_message => SQLERRM,
      p_backtrace     => DBMS_UTILITY.FORMAT_ERROR_BACKTRACE,
      p_elapsed_ms    => EXTRACT(SECOND FROM (SYSTIMESTAMP - v_started_at)) * 1000
    );
    RAISE;
END;

BEGIN
  DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE(
    service_name => SYS_CONTEXT('USERENV', 'SERVICE_NAME'),
    module_name  => 'ORDER_IMPORT',
    action_name  => 'MERGE',
    waits        => TRUE,
    binds        => TRUE
  );
END;
/

-- 調査後は必ず無効化する
BEGIN
  DBMS_MONITOR.SERV_MOD_ACT_TRACE_DISABLE(
    service_name => SYS_CONTEXT('USERENV', 'SERVICE_NAME'),
    module_name  => 'ORDER_IMPORT',
    action_name  => 'MERGE'
  );
END;
/

-- どのサブプログラムを通って例外に到達したか調べたい
-- 複雑なパッケージ間呼び出しの経路を可視化したい
-- 本番常時ではなく、調査対象を絞って短時間だけ使う

CREATE TABLE batch_metric (
  batch_id      VARCHAR2(100),
  module_name   VARCHAR2(100),
  action_name   VARCHAR2(100),
  chunk_no      NUMBER,
  processed_cnt NUMBER,
  success_cnt   NUMBER,
  error_cnt     NUMBER,
  elapsed_ms    NUMBER,
  recorded_at   TIMESTAMP DEFAULT SYSTIMESTAMP
);

INSERT INTO batch_metric(
  batch_id,
  module_name,
  action_name,
  chunk_no,
  processed_cnt,
  success_cnt,
  error_cnt,
  elapsed_ms
) VALUES (
  :batch_id,
  'ORDER_IMPORT',
  'MERGE',
  :chunk_no,
  :processed_cnt,
  :success_cnt,
  :error_cnt,
  :elapsed_ms
);

UTL_HTTP.SET_HEADER(
  r     => req,
  name  => 'X-Correlation-ID',
  value => SYS_CONTEXT('USERENV', 'CLIENT_IDENTIFIER')
);

logger_pkg.write_log(
  p_level       => 'INFO',
  p_message     => 'external api called',
  p_process_key => 'order_id=' || p_order_id,
  p_detail_json => '{"endpoint":"payment","status":200}'
);