ストアド実行中のトレースログを残す(SQLServer)

記事概要

本記事は、ストアド実行中のログを残すための実装例を１つ挙げたものです。
ストアドのログを専用のログテーブルに書き込む処理について記載します。

まず、ストアドのログを残す方法として、例えば以下のような方法があるようです。

• (a)ストアド呼び出し自体の結果を、SQLServerのログとして残す
• (b)RAISEERROR(レベル10以下)を呼び出す
• (c)ストアドからシェル機能などを呼び出し、そこからファイルに出力する
• (d)専用のログテーブルに書き込む
• etc..??

もし、トレースログ的なものを出力したいのであれば、(a)は用途外です。
(b)、(c)、(d)は、処理速度の優劣もあるでしょうし、また、ログの残り方(ログを確認する方法)に差がでてきます。※私は(b)(c)を試していないため、詳細が分かりません。

本記事では、(d)専用のログテーブルに書き込む　の、実装例を記載します。

同一データベースに、ストアドのログ用に専用のテーブルを作ります。
ストアド実行中のトレースログは変数にためておき、Commit/Rollbackの確定後にログテーブルへ出力します。

注意
本記事の実装は、トランザクション(開始、Commit/Rollback)はストアドの内部で発生することを前提とします。
ストアドの呼び出し元がトランザクションを制御している場合、呼び出し元のRollbackの影響を受けると思われます。

実装例

　トランザクション内でログテーブルにInsertすると、ストアド処理でRollbackされたときにログテーブルもRollbackされてしまいます。そのため、Commit/Rollbackする前にログテーブルへInsertするのは避けるべきです。

　では実行途中のトレースログはどうやって残すのかというと、これにはストアド内のテーブル変数を利用します。普通のテーブルや一時テーブルと違い、ストアド内のテーブル変数はRollbackの影響をうけないからです。 トレースログを必要な(都合のよい)ときにテーブル変数へInsertしていき、ストアドのCommit/Rollbackが確定した後に、そのテーブル変数の内容をまとめてログテーブルに書き込む、という手順になります。

　トレースログを残すテーブルのほうは、参照時に時系列でソートできること、データがひたすら貯まってしまわないよう古いデータを削除できること、などを考慮します。主キーをdatetime等にするのが安直でよいのですが、一回に複数行を書き込みたいときはPK制約違反になるためいけません。ここでは、主キーを datetime + インデックス値とします。インデックス値のみでもよいかと思います。

　いざ運用でトレースログを、となると、古いデータは自動で整理されてほしい、とか、ログテーブルの主キーが複雑だとInsertがめんどくさいなどの事情がでてきます。そこで、テーブル変数からトレースログを書き込む処理はストアドとしてしまいます(ストアドから別のストアドの呼び出す)。

構築

トレースログ用のテーブル変数

テーブル変数のユーザー定義型を作成します。必要なわけではありませんがお勧めします。いくつもストアドを作るなら、型定義を作ってしまいどのストアドでもその型を使うほうが分かりやすいです。

IF TYPE_ID('TYPE_LOG_TABLE') IS NOT NULL  
    DROP TYPE TYPE_LOG_TABLE;  
GO
CREATE TYPE TYPE_LOG_TABLE AS TABLE (
    IDX int IDENTITY(1,1) -- SELECT結果がINSERT順にならないので、ソートするための情報が必要
    ,RECORD_DATETIME datetime
    ,STP_NAME nvarchar(50)
    ,TEXT nvarchar(500)
);
GO

トレースログ用のログテーブル

DROP TABLE IF EXISTS [dbo].[T_STP_LOG]
GO
CREATE TABLE [dbo].[T_STP_LOG] (
    [RECORD_DATETIME] [datetime] NOT NULL ,
    [IDX] [int] IDENTITY(1,1) NOT NULL ,
    [STP_NAME] [nvarchar] (50),
    [TEXT] [nvarchar] (500) 
) ON [PRIMARY]
GO
ALTER TABLE [dbo].[T_STP_LOG] WITH NOCHECK ADD 
    CONSTRAINT [PK_T_STP_LOG] PRIMARY KEY  CLUSTERED 
    (
        [RECORD_DATETIME] ,
        [IDX] 
    ) WITH  FILLFACTOR = 90  ON [PRIMARY] 
GO

テーブル変数の内容を実テーブルに書き込むためのストアド

トレースログを溜め続けるわけにはいかないので、参照・整理すること込みで運用方法を決めてください。運用方法に応じ、このストアドの中で小細工できます。ここでは古いデータの整理やインデックスのローリング処理を作り込んでいます。

注意
このストアドは、呼び出し側のトランザクションのCommit/Rollbackが確定した後に呼び出されることを想定しています。

IF OBJECT_ID('STP_TRACELOG', 'P') IS NOT NULL  
    DROP PROCEDURE STP_TRACELOG;  
GO  
CREATE PROCEDURE STP_TRACELOG 
     @LogTable dbo.TYPE_LOG_TABLE READONLY
AS
BEGIN
    SET NOCOUNT ON;  -- No count for SELECT statements.
    BEGIN TRANSACTION;
    BEGIN TRY
        DECLARE @OlderThan datetime = DATEADD(DAY, -7, GETDATE());
        DELETE FROM T_STP_LOG WHERE RECORD_DATETIME < @OlderThan;
        INSERT INTO T_STP_LOG SELECT RECORD_DATETIME, STP_NAME, TEXT FROM @LogTable;
        DECLARE @GivenDatetime datetime;
        SELECT @GivenDatetime = MAX(RECORD_DATETIME) FROM @LogTable;
        DECLARE @Idx bigint = ISNULL((SELECT MAX(IDX) FROM T_STP_LOG WHERE RECORD_DATETIME = @GivenDatetime), 0);
        IF @Idx > 1000000
        BEGIN
            DBCC CHECKIDENT ('T_STP_LOG', RESEED, 1);     
        END
        -- 正常終了
        COMMIT TRANSACTION;
    END TRY
    BEGIN CATCH
        ROLLBACK TRANSACTION;
        print('log output error!!');
    END CATCH
END;

必要なのは INSERT INTO T_STP_LOG SELECT RECORD_DATETIME, STP_NAME, TEXT FROM @LogTable; であり、それ以外はおまけです。

トレースログを書き込む側(呼び出し側)の使い方

例えば、下記のようなストアドがあったとします。
・品番、入庫数、在庫レコードバージョンを入力とし、
・在庫に対し入庫数を加算する。但し在庫レコードバージョンが不一致なら失敗する。
・入力と、失敗理由をトレースログに記録する
※SQLServerではレコードバージョンに timestamp型 (byte[] 8)を使うのが普通ですが、ここではintで済ませています。

繰り返しになりますが、Commit/Rollbackが確定した後に、ログテーブルへ出力します。

CREATE PROCEDURE STP_RECEIVING
     @IN_ITEM_NUMBER int
    ,@IN_COUNT int
    ,@IN_REC_VERSION int
AS
BEGIN
    SET NOCOUNT ON;  -- No count for SELECT statements.
    DECLARE @STP_NAME nvarchar(50) = 'STP_RECEIVING';
    DECLARE @LogTable dbo.TYPE_LOG_TABLE;
    DECLARE @LogMsg nvarchar(200) = '';
    DECLARE @Date datetime = getdate();

    BEGIN TRANSACTION;
    BEGIN TRY
        INSERT INTO @LogTable VALUES (@Date, @STP_NAME, 'start');
        SET @LogMsg = CONCAT('IN_ITEM_NUMBER:', @IN_ITEM_NUMBER, ', IN_COUNT:', @IN_COUNT, ', IN_REC_VERSION:', @IN_REC_VERSION);
        INSERT INTO @LogTable VALUES (@Date, @STP_NAME, @LogMsg);

        UPDATE T_STOCK SET 
             STOCK_COUNT = STOCK_COUNT + @IN_COUNT
            ,REC_VERSION = REC_VERSION + 1 
        WHERE 
            ITEM_NUMBER = @IN_ITEM_NUMBER AND REC_VERSION = @IN_REC_VERSION;

        IF @@ROWCOUNT <> 1
        BEGIN
            ROLLBACK TRANSACTION;

            -- 戻り値記載省略

            INSERT INTO @LogTable VALUES (@Date, @STP_NAME, '!! ERROR !!  Concurrency conflict: record version may be outdated');
            EXEC STP_TRACELOG @LogTable;
            RETURN;
        END

        -- 正常終了
        COMMIT TRANSACTION;
        INSERT INTO @LogTable VALUES (@Date, @STP_NAME, 'committed');
        EXEC STP_TRACELOG @LogTable;

        -- 戻り値記載省略

    END TRY
    BEGIN CATCH
        ROLLBACK TRANSACTION;

        INSERT INTO @LogTable VALUES (@Date, @STP_NAME, ERROR_MESSAGE());
        EXEC STP_TRACELOG @LogTable;

        -- 戻り値記載省略

    END CATCH
END;