【Python】ログファイルからモジュール名・関数名ごとの処理時間を計算する

■概要

ログファイルに記載されている、処理時間、モジュール名、関数名をインプットに、そのモジュールまたは関数ごとの処理時間を算出して、Json形式で出力する。

▼ログファイルのフォーマットと内容

ログファイルのフォーマットは以下の通り。

日付(yyyy-mm-dd hh:mi:ss,ffff)|ログレベル(INFO)|モジュール名|関数名|ログメッセージ

今回使用するログファイルは、以下の通り。

・test_sample.log

2025-05-04 12:39:20,670|INFO|test|test_main|start: test_main
2025-05-04 12:39:20,671|INFO|test|test_sub|ENV: WIN
2025-05-04 12:39:50,763|INFO|test|test_sub|ENV: Linux
2025-05-04 12:40:30,763|INFO|test|test_sub|ENV: MAC
2025-05-04 12:43:27,737|INFO|test|test_main|end: test_main
2025-05-04 12:46:48,222|INFO|test2|test_main2-1|start: test_main2
2025-05-04 12:49:34,740|INFO|test2|test_main2-1|end: test_main2
2025-05-04 12:47:07,638|INFO|test2|test_main2-2|ENV: WIN
2025-05-04 12:48:11,763|INFO|test2|test_main2-2|ENV: Linux
2025-05-04 12:59:32,111|INFO|test2|test_main2-2|ENV: MAC
2025-05-04 12:59:56,293|INFO|test3|test_main3|Only start

▼Jsonの出力フォーマット

Jsonの出力フォーマットは以下の通り。

{
  "モジュール名/関数名": {
    "start": "開始日時",
    "end": "終了日時",
    "duration_seconds": "処理時間"
  },
  "モジュール名/関数名": {
    "start": "開始日時",
    "end": "終了日時",
    "duration_seconds": "処理時間"
  },
  :
  :
}

■フローチャート

本処理のフローチャートを以下に示す。

開始
開始
開始・終了時間Dict作成
開始・終了時間Dict作成
ログファイル操作
ログファイル操作
ログファイル内の1行ずつ繰り返し
ログファイル内の1行ずつ繰り返し
改行を削除
改行を削除
区切り文字(|)ごとに配列化
区切り文字(|)ごとに配列化
ログ内の時間を取得
ログ内の時間を取得
ログ内のモジュール名を取得
ログ内のモジュール名を取得
ログ内の関数名を取得
ログ内の関数名を取得
ログファイル
ログファイル
開始・終了時間Dictの
モジュール名開始時間
開始・終了時間Dictの…
なし
なし
あり
あり
開始時間をセット
開始時間をセット
終了時間をセット
終了時間をセット
なし
なし
あり
あり
開始時間をセット
開始時間をセット
終了時間をセット
終了時間をセット
開始・終了時間Dictの
関数名開始時間
開始・終了時間Dictの…
出力用Dict作成
出力用Dict作成
開始・終了時間Dictの要素数分繰り返し
開始・終了時間Dictの要素数分繰り返し
開始時間取得
開始時間取得
終了時間取得
終了時間取得
開始と終了時間
開始と終了時間
あり
あり
終了時間 – 開始時間
終了時間 – 開始時間
結果を出力用Dictに格納
結果を出力用Dictに格納
なし
なし
出力用DictをJson形式に変換
出力用DictをJson形式に変換
結果を出力
結果を出力
終了
終了
コンソール
コンソール
行を読み込み
行を読み込み
Text is not SVG – cannot display

■サンプルコード

本処理のサンプルコードを以下に示す。

import json
from collections import defaultdict
from datetime import datetime

LOG_FILE_NAME = './logs/test_sample.log'


def cal_processing_time_main():
    """
    ログファイルから処理名および関数名
    :return: None
    """

    # 開始・終了時間Dict 初期値:{"start": None, "end": None}
    result_dict = defaultdict(lambda: {"start": None, "end": None})

    # ログファイルを読み込み
    with open(LOG_FILE_NAME, "r") as f:

        # 行を読み込み
        lines = f.readlines()

        # 1行ずつ繰り返し
        for line in lines:
            # 改行削除
            remove_lf_line = line.rstrip("\n")

            # 区切りで配列化
            line_list = remove_lf_line.split("|")

            # 時刻を取得
            timestamp = datetime.strptime(line_list[0], "%Y-%m-%d %H:%M:%S,%f")

            # 処理名取得
            process_name = line_list[2]

            # 関数名取得
            function_name = line_list[3]

            # 処理名の開始あり
            if result_dict[process_name]["start"] is None:
                result_dict[process_name]["start"] = timestamp
            else:
                result_dict[process_name]["end"] = timestamp

            # 関数名の開始あり
            if result_dict[function_name]["start"] is None:
                result_dict[function_name]["start"] = timestamp
            else:
                result_dict[function_name]["end"] = timestamp

    # 出力用Dict
    output = {}

    # 開始・終了時間Dictの要素数分繰り返し
    for key, value in result_dict.items():

        # 開始・終了時間取得
        start = value["start"]
        end = value["end"]

        # 差分時間の初期値
        duration = None

        # 開始・終了時間あり
        if start and end:
            duration = (end - start).total_seconds()

        # 出力用Dict作成
        output[key] = {
            "start": start.isoformat() if start is not None else None,
            "end": end.isoformat() if end is not None else None,
            "duration_seconds": duration if duration is not None else None
        }

    # json形式に変換
    json_output = json.dumps(output, indent=2)

    # 結果出力
    print(json_output)


# メイン処理
if __name__ == '__main__':
    cal_processing_time_main()

■実行結果

本処理の実行結果を以下に示す。

{
  "test": {
    "start": "2025-05-04T12:39:20.670000",
    "end": "2025-05-04T12:43:27.737000",
    "duration_seconds": 247.067
  },
  "test_main": {
    "start": "2025-05-04T12:39:20.670000",
    "end": "2025-05-04T12:43:27.737000",
    "duration_seconds": 247.067
  },
  "test_sub": {
    "start": "2025-05-04T12:39:20.671000",
    "end": "2025-05-04T12:40:30.763000",
    "duration_seconds": 70.092
  },
  "test2": {
    "start": "2025-05-04T12:46:48.222000",
    "end": "2025-05-04T12:59:32.111000",
    "duration_seconds": 763.889
  },
  "test_main2-1": {
    "start": "2025-05-04T12:46:48.222000",
    "end": "2025-05-04T12:49:34.740000",
    "duration_seconds": 166.518
  },
  "test_main2-2": {
    "start": "2025-05-04T12:47:07.638000",
    "end": "2025-05-04T12:59:32.111000",
    "duration_seconds": 744.473
  },
  "test3": {
    "start": "2025-05-04T12:59:56.293000",
    "end": null,
    "duration_seconds": null
  },
  "test_main3": {
    "start": "2025-05-04T12:59:56.293000",
    "end": null,
    "duration_seconds": null
  }
}

コメント

タイトルとURLをコピーしました