ボケ防止にGO言語の勉強／関数単位の実行時間を計測しログに残す「実行時間トレース」を実装する

今回は、関数単位で実行時間を計測してログに残す処理の実装という話題です。

７０歳目前になり「ボケ防止」でGo言語プログラミングの学びなおしをしていて「プロファイラみたいに関数単位の実行時間を取得したいな」と思ったからです。

まあ、

start := time.Now()　でスタート時間を記録

elapsed := time.Since(start)　でかかった時間を取得

みたいにガシガシソースに書き込めばできるんですけど、そういう力業は好みではなく、独立した時間計測関数を定義（例えば「Trace()」という名前）して、その関数宣言を、計測したい関数の頭に計測処理（Trace()等）を１行埋め込むだけで計測するようにはしたいですね。

計測対象の関数名も文字列で都度書くとかはスマートではないので、「自動的に呼び出し元関数名を取得して、実行時間を計測しログに残す」ようにしたいと思います。それができるかできないか「学びなおし」してみます。

まず時間を計測するやり方としては、こんな感じのようです。

start := time.Now()で計測開始時刻を取得する。
pc, _, _, ok := runtime.Caller(1)で「ひとつ前の呼び出し元の関数の情報」を取得し、runtime.FuncForPC(pc).Name()で「関数名」を取得します。
elapsed := time.Since(start)で経過時間を計算・取得します。ここで取得した数字（elapsed）では人間にはわかりづらいので、 formatDuration関数を定義して、人の見やすい時間に変換しています。

上記を実装し、動作確認に僕が使ったコードです。

package trace

import (
	"fmt"
	"log"
	"runtime"
	"time"
)

// Traceは、呼び出し元関数名を自動セットし、その関数の実行時間をlogファイルに書き出します。
// プロファイラ的に使います。本番時にはOFFにできるようにすべきですが、今のところ常に時間計測するようにしています。
func Trace() func() {
	start := time.Now()

	// 呼び出し元の関数名を取得する
	pc, _, _, ok := runtime.Caller(1)
	funcName := "unknown"
	if ok {
		funcName = runtime.FuncForPC(pc).Name()
	}

	return func() {
		elapsed := time.Since(start)
		log.Printf("[関数] %s() [実行時間] %s（%s）\n", funcName, formatDuration(elapsed), elapsed)
	}
}

// formatDurationは、計測時間（Duration）を「時間・分・秒・ミリ時間・マイクロ時間・ナノ時間」に分解してログに出力します
func formatDuration(d time.Duration) string {
	// 各単位の値を計算
	hours := d / time.Hour
	d %= time.Hour

	minutes := d / time.Minute
	d %= time.Minute

	seconds := d / time.Second
	d %= time.Second

	milliseconds := d / time.Millisecond
	d %= time.Millisecond

	microseconds := d / time.Microsecond
	d %= time.Microsecond

	nanoseconds := d

	// 文字列の組み立て（0の単位は詰めたい場合）
	var result string
	if hours > 0 {
		result += fmt.Sprintf("%d時間", hours)
	}
	if minutes > 0 || hours > 0 { // 時間がある場合は分が0でも表示
		result += fmt.Sprintf("%d分", minutes)
	}
	if seconds > 0 || minutes > 0 || hours > 0 {
		result += fmt.Sprintf("%d秒", seconds)
	}

	// ミリ秒とナノ秒（マイクロ秒も含む）は常に、または残りに応じて表示
	result += fmt.Sprintf("%dミリ秒%dマイクロ秒%dナノ秒", milliseconds, microseconds, nanoseconds)

	return result
}

使い方は、時間計測したい関数の頭に以下の１行を追加すればいけます。

defer trace.Trace()()

ここでのポイントは、Trace()関数の中からreturnするとき「return func() {}」みたいに定義して、関数をreturnしているところです。戻り値が関数なので、上記の宣言でも「Trace()()」と()が２つつける必要があります。

宣言で「defer trace.Trace()()」みたいに「defer」をつけてるので「Trace()のfunc()で囲まれていない部分「計測開始と呼び出し元関数名取得」はすぐに実行されます。でもfunc()で囲まれている部分「終了時の時間計測」はすぐに実行されず、宣言した関数の終了直前に実行されるように「defer」によって制御されることになります。

なので、開始時刻を取得して、経過時刻も計算できるというわけ。よくできた仕組みだなと感心します。

時間計測したい関数に「Trace()()を埋め込む」ひと手間が面倒にも見えますが、指定した関数のみ時間計測する方が、個人的にはログが見やすくて気に入ってます。これで出力した実行時間ログのサンプルです。

・

[TIMER] 2026/06/26 18:38:00.553305 [関数] my_go02/controllers.ExtractLinks() [実行時間] 24ミリ秒778マイクロ秒900ナノ秒（24.7789ms）
[TIMER] 2026/06/26 18:38:00.598122 [関数] my_go02/controllers.ExtractLinks() [実行時間] 44ミリ秒494マイクロ秒100ナノ秒（44.4941ms）
[TIMER] 2026/06/26 18:38:00.655406 [関数] my_go02/controllers.ExtractLinks() [実行時間] 57ミリ秒284マイクロ秒300ナノ秒（57.2843ms）
[TIMER] 2026/06/26 18:38:00.655406 [関数] my_go02/controllers.GetResults() [実行時間] 1分36秒726ミリ秒920マイクロ秒200ナノ秒（1m36.7269202s）
[TIMER] 2026/06/26 18:38:00.656031 [関数] main.main() [実行時間] 1分36秒728ミリ秒183マイクロ秒500ナノ秒（1m36.7281835s）

最後に、Geminiにサンプルコードを出力してもらうときに僕が使ったプロンプトです。

golang。関数単位で処理時間を計測し、ログに記録する関数を別パッケージに切り出します。関数名は「Trace」にします。ログは「log」を使います。時間計測対象の呼び出し元の関数名は自動で取得します。計測結果時間は「１時間１分１秒１ミリ秒１マイクロ秒１ナノ秒」と日本語にフォーマットに編集して書き出します。ただし、0の場合は非表示にする考慮も必要です。計測結果時間を編集する処理は別関数にきりだします。この仕様のサンプルコードをお願いします。

ではでは。

BOKUのブログ

ジャンルにこだわらず、ノートの感じで書いてます

ボケ防止にGO言語の勉強／関数単位の実行時間を計測しログに残す「実行時間トレース」を実装する