なぜ DateTime.Now によるパフォーマンス計測は「罪悪」なのか
業務システム、とりわけ長年保守されてきたVB6/VBA由来のロジックを抱えるVB.NETアプリケーションにおいて、処理速度の遅延は日常茶飯事だ。しかし、そのボトルネックを特定しようとするアプローチの多くが、最初から致命的な間違いを犯している。
未だに以下のようなコードを目にすることがある。
‘ 敗北を約束された愚かな計測コード
Dim startTime As DateTime = DateTime.Now
‘ — 処理対象 —
Call ExecuteLegacyBatchProcess()
‘ —————
Dim endTime As DateTime = DateTime.Now
Dim elapsedMs As Double = (endTime – startTime).TotalMilliseconds
Console.WriteLine($”処理時間: {elapsedMs} ms”)
システムアーキテクトとして断言する。`DateTime.Now`（あるいは `DateTime.UtcNow`）をパフォーマンス計測に使ってはならない。
Windowsシステムクロックの分解能という「壁」
`DateTime.Now` は、現在の日時を取得するためのAPIであり、パフォーマンス計測のために設計されていない。その内部実装は、Windowsカーネルのタイマー割り込み（システムタイマーリフレッシュレート）に依存している。
多くの標準的なWindows環境において、このタイマーの分解能は 約 15.6 ミリ秒（1/64秒 = 15.625ms） だ。
つまり、`DateTime.Now` で計測した場合、実際には `0.001ms` で完了しているミリ秒未満の超高速処理であっても、タイマーの割り込みタイミングの跨ぎ方次第で「`0ms`」と出力されるか、あるいは「`15.625ms`」と出力される。15.6ms以下の微妙な差（アルゴリズムの改善による数ミリ秒の短縮など）は、すべて誤差の闇に呑まれて消失する。
精度が保証されない計測値に基づいてプロファイリングを行うことは、狂った定規で精密部品を設計するようなものだ。
—
高精度プロファイリングの核心：System.Diagnostics.Stopwatch の真価
.NET環境において、正確な時間を計測するための唯一解が `System.Diagnostics.Stopwatch` クラスだ。
`Stopwatch` クラスは、オペレーティングシステムおよびハードウェアが提供する高分解能パフォーマンスカウンタ（High-Resolution Performance Counter）を直接利用する。
QueryPerformanceCounter (QPC) との直結
Windows環境下において、`Stopwatch` はWin32 APIの `QueryPerformanceCounter` (QPC) および `QueryPerformanceFrequency` をラップして動作する。これにより、CPUのタイムスタンプカウンタ（TSC）やマザーボード上の高精度タイマーを利用し、1マイクロ秒（0.001ミリ秒）以下、環境によってはナノ秒単位の分解能 を実現する。
計測を行う前に、対象のハードウェアが高精度タイマーをサポートしているかを確認するプロパティが `Stopwatch.IsHighResolution` だ。現代の標準的なx86/x64アーキテクチャであれば、ほぼ確実に `True` を返す。
Imports System.Diagnostics
If Stopwatch.IsHighResolution Then
Console.WriteLine($”高精度タイマー有効: 周波数 = {Stopwatch.Frequency} Hz”)
Else
Console.WriteLine(“警告: 高精度タイマーがサポートされていません。システムクロックにフォールバックします。”)
End If
`Stopwatch.Frequency` は1秒あたりのカウント数を表す。これが `10,000,000` であれば、1カウントの精度は `100ナノ秒`（1 ticks）となる。
—
プロファイリングにおける3つの罠：JIT、GC、そしてアロケーション
`Stopwatch` を導入するだけで正確な計測ができると考えるのは浅はかだ。実戦の.NET環境では、実行ランタイムの挙動が計測結果を大きく歪める。
1. JIT（Just-In-Time）コンパイルの冷え（Cold Start）
.NETのIL（中間言語）コードは、初回実行時にJITコンパイラによってネイティブ機械語に翻訳される。そのため、関数の初回呼び出し（Cold Execution）にはJITコンパイルのオーバーヘッドが加算される。
純粋なアルゴリズムの計算コストを測りたい場合は、事前にウォーミングアップ（ウォームアップ実行）を行ってJITコンパイルを完了させてから計測（Warm Execution）を開始しなければならない。
2. ガベージコレクション（GC）の不確定性
計測の最中にGC（特にGen 2のFull GC）が発生すると、実行スレッドが停止（Stop-The-World）し、数値が数ミリ秒〜数百ミリ秒単位で跳ね上がる。
計測前後でのGCの発生回数（`GC.CollectionCount`）とヒープ割り当て量（`GC.GetTotalAllocatedBytes`）を記録し、ノイズを除外する必要がある。
3. 計測コード自体のアロケーション
計測のために `Stopwatch` オブジェクトを `New` するコストや、文字列結合でログを出すコスト自体がヒープメモリを汚染する。極限の計測では、`Stopwatch.GetTimestamp()` を用いた構造体ベース（アロケーションフリー）の計測が求められる。
—
現場でそのまま使える：高精度プロファイラ兼メモリメトリクスエンジンの実装
以下に、シニアエンジニアが現場のエンタープライズコードに組み込むべき、高精度ベンチマークフレームワークのVB.NET実装を示す。
単なる時間の計測にとどまらず、GCコレクション回数 および ヒープメモリ割り当て量（Allocated Bytes） を同時に追跡し、ボトルネックの「質」をあぶり出す設計となっている。
Imports System
Imports System.Diagnostics
Imports System.Runtime.CompilerServices
Namespace Architecture.Profiling
”’
”’
Public Module PerformanceProfiler
”’
”’
Public Structure ProfilingResult
Public ReadOnly ElapsedMilliseconds As Double
Public ReadOnly AllocatedBytes As Long
Public ReadOnly Gen0Collections As Integer
Public ReadOnly Gen1Collections As Integer
Public ReadOnly Gen2Collections As Integer
Public Sub New(elapsedMs As Double, allocatedBytes As Long, gen0 As Integer, gen1 As Integer, gen2 As Integer)
Me.ElapsedMilliseconds = elapsedMs
Me.AllocatedBytes = allocatedBytes
Me.Gen0Collections = gen0
Me.Gen1Collections = gen1
Me.Gen2Collections = gen2
End Sub
Public Overrides Function ToString() As String
Return $”[Time]: {ElapsedMilliseconds:F4} ms | ” &
$”[Allocated]: {AllocatedBytes / 1024.0:F2} KB | ” &
$”[GC Count (0/1/2)]: {Gen0Collections}/{Gen1Collections}/{Gen2Collections}”
End Function
End Structure
”’
”’
Public Function Measure(action As Action, Optional warmup As Boolean = True) As ProfilingResult
If action Is Nothing Then Throw New ArgumentNullException(NameOf(action))
‘ JITコンパイルの影響を排他するためのウォームアップ実行
If warmup Then
action.Invoke()
End If
‘ 計測前のメモリ状態とGC発生回数を記録
GC.Collect()
GC.WaitForPendingFinalizers()
GC.Collect()
Dim gen0Before As Integer = GC.CollectionCount(0)
Dim gen1Before As Integer = GC.CollectionCount(1)
Dim gen2Before As Integer = GC.CollectionCount(2)
Dim bytesBefore As Long = GC.GetTotalAllocatedBytes(exact:=True)
Dim startTimestamp As Long = Stopwatch.GetTimestamp()
‘ — ターゲット処理の実行 —
action.Invoke()
‘ —————————-
Dim endTimestamp As Long = Stopwatch.GetTimestamp()
Dim bytesAfter As Long = GC.GetTotalAllocatedBytes(exact:=True)
Dim gen0After As Integer = GC.CollectionCount(0) – gen0Before
Dim gen1After As Integer = GC.CollectionCount(1) – gen1Before
Dim gen2After As Integer = GC.CollectionCount(2) – gen2Before
‘ チック数を高精度にミリ秒へ変換
Dim elapsedTicks As Long = endTimestamp – startTimestamp
Dim elapsedMs As Double = (elapsedTicks / CType(Stopwatch.Frequency, Double)) 1000.0
Dim allocatedBytes As Long = Math.Max(0L, bytesAfter – bytesBefore)
Return New ProfilingResult(elapsedMs, allocatedBytes, gen0After, gen1After, gen2After)
End Function
End Module
End Namespace
Win32 API を直接叩く極限の代替（参考）
万が一、古い.NET Framework環境やP/Invokeを直接扱う低レイヤなシステムを保守する場合、以下のWin32 API宣言が `Stopwatch` の裏で動作している本質だ。
Imports System.Runtime.InteropServices
Public Class Win32HighResolutionTimer
Public Shared Function QueryPerformanceCounter(ByRef lpPerformanceCount As Long) As Boolean
End Function
Public Shared Function QueryPerformanceFrequency(ByRef lpFrequency As Long) As Boolean
End Function
End Class
—
ボトルネック特定の深層：レガシーVB.NETコードの暗部を炙り出す
プロファイラを手に入れたら、次に行うべきは「どこが本当に遅いのか」を切り分けるプロファイリングの実践だ。
現場で頻繁に遭遇する「レガシーVB.NET/VBA由来のパフォーマンス低下」の典形的なパターンと、計測による改善例を示す。
検証：文字列結合のオーバーヘッド（String vs StringBuilder）
VBAや初期のVB.NETから移行されたコードによく見られるのが、ループ内での `String` 加算操作（`+=` または `&`）だ。
Imports Architecture.Profiling
Module Program
Sub Main()
Const LoopCount As Integer = 30000
Console.WriteLine(“=== パフォーマンス計測開始 ===”)
‘ 1. 不適切なコード: Stringの反復結合
Dim resultBad = PerformanceProfiler.Measure(Sub()
Dim str As String = “”
For i As Integer = 0 To LoopCount
str &= “Data:” & i.ToString() ‘ 大量のアロケーションが発生
Next
End Sub, warmup:=True)
Console.WriteLine($”[悪名高きString結合] {resultBad}”)
‘ 2. 適切なコード: StringBuilderの利用と容量事前確保
Dim resultGood = PerformanceProfiler.Measure(Sub()
Dim sb As New System.Text.StringBuilder(LoopCount 15)
For i As Integer = 0 To LoopCount
sb.Append(“Data:”)
sb.Append(i)
Next
Dim str As String = sb.ToString()
End Sub, warmup:=True)
Console.WriteLine($”[最適化StringBuilder] {resultGood}”)
End Sub
End Module
実行結果例（アーキテクトの視点による出力の解釈）
=== パフォーマンス計測開始 ===
[悪名高きString結合] [Time]: 482.1523 ms | [Allocated]: 1,245,812.50 KB | [GC Count (0/1/2)]: 142/12/1
[最適化StringBuilder] [Time]: 0.8912 ms | [Allocated]: 468.80 KB | [GC Count (0/1/2)]: 0/0/0
計測値が語る事実
1. 処理時間の圧倒的差: 482ms から 0.89ms へ（約540倍の高速化）。
2. メモリ割り当て（Allocated Bytes）: `String` の不変性（Immutability）により、結合のたびにヒープ上に新しい文字列インスタンスが生成され、1GB超のゴミデータが作られている。
3. GCの発生（GC Count）: `String` 結合側では Gen 0 のGCが142回、さらにはStop-The-Worldを引き起こす Gen 2 のGCまで発生している。
これが、`Stopwatch` とメモリトラッキングを組み合わせることで可視化される「ボトルネックの真実」である。
—
COMオブジェクト・レガシーAPI呼び出しのプロファイリングと解放戦略
VB.NETが社内基幹システムで長年使われ続ける理由の一つに、Excel AutomationやレガシーCOM（ActiveX）コンポーネントとの連携がある。
COM連携において処理速度が低下する最大の要因は、Interopの境目を越えるマーシャリングコスト と RCW (Runtime Callable Wrapper) の解放遅延によるメモリ圧迫 だ。
計測と解放最適化のパターンを以下に示す。
Imports System.Runtime.InteropServices
Imports System.Diagnostics
Public Sub ExecuteComProcessProfiling()
Dim sw = Stopwatch.StartNew()
‘ COMオブジェクトの参照
Dim excelApp As Object = Nothing
Try
‘ COMインスタンスの生成コストを計測
Dim instStart As Long = Stopwatch.GetTimestamp()
Dim excelType As Type = Type.GetTypeFromProgID(“Excel.Application”)
excelApp = Activator.CreateInstance(excelType)
Dim instEnd As Long = Stopwatch.GetTimestamp()
Console.WriteLine($”COMインスタンス生成時間: {(instEnd – instStart) / CDbl(Stopwatch.Frequency) 1000:F3} ms”)
‘ — 何らかの自動化処理 —
Finally
‘ 明示的かつ確定的なCOM参照の解放
If excelApp IsNot Nothing Then
Marshal.FinalReleaseComObject(excelApp)
excelApp = Nothing
End If
End Try
sw.Stop()
Console.WriteLine($”総処理時間: {sw.Elapsed.TotalMilliseconds:F3} ms”)
End Sub
確定的なリソース解放の原則
.NETのGCは「メモリアロケーションが限界に達するまで動作しない」という非確定的な性質を持つ。アンマネージドリソース（ファイルハンドル、DB接続、COMオブジェクト、GDI+ハンドル）を抱えるレガシー処理では、`IDisposable` の `Using` ステートメント、あるいは `Marshal.FinalReleaseComObject` を用いて、計測区間の外で即座にリソースを廃棄しなければならない。
これを怠ると、プロファイリング結果において「処理自体は終わっているのに、後の無関係なロジックで突然スローダウンする」という原因不明の現象に悩まされることになる。
—
アーキテクトからの助言：感ではなく「数字」で語れ
高精度なプロファイリングツールを手にしたエンジニアが陥りがちな罠が、「推測による最適化（Premature Optimization）」 だ。
1. まず計測せよ: コードを変更する前に、`Stopwatch` とプロファイラでボトルネックの正確な場所と「ベースライン（現在の数値）」を測定せよ。
2. ボトルネック以外は触るな: 全体の処理時間の1%しか占めていない関数をどれほど高速化しても、全体に対する影響は皆無だ。90%の時間とメモリを消費している上位の処理に集中せよ。
3. 修正後に再計測せよ: 変更を加えた後、理論上速くなるはずのコードが、JITやCPUキャッシュの影響で逆に遅くなっていないか、数字をもって証明せよ。
`DateTime.Now` による曖昧な計測を捨て、`Stopwatch` によるミクロレベルの確証を得ること。それこそが、レガシーシステムを現代のハイパフォーマンスなシステムへと脱皮させる、チーフアーキテクトとしての第一歩である。
