DateTime.Nowは今すぐ捨てろ。VB.NETにおけるミリ秒単位のプロファイリングとボトルネック打破の鉄則
社内業務の自動化ツールや基幹連携プログラムで、「最近どうも動きが重い」「どの処理に時間がかかっているのか分からない」といった声を聞くことはないだろうか。
そこで未熟な実装者がやりがちな最大の間違いが、`DateTime.Now`の差分をとって処理時間を測定することだ。
‘ 【アンチパターン】絶対にやってはいけない計測方法
Dim startTime As DateTime = DateTime.Now
‘ ～ 重い処理 ～
Dim duration As TimeSpan = DateTime.Now – startTime
Console.WriteLine($”処理時間: {duration.TotalMilliseconds} ms”)
現場のリーダーとして言おう。このコードはプロフェッショナルとして失格だ。
なぜ`DateTime.Now`を使った計測がゴミ同然なのか。そして、プロのエンジニアは`System.Diagnostics.Stopwatch`をどう使いこなし、ボトルネックを正確に炙り出してシステムを劇的に高速化させるのか。その極意を解説する。
—
1. なぜ DateTime.Now で時間を測ってはいけないのか？
`DateTime.Now`（あるいはVBの`Date.Now`）は、「現在の日時を取得する」ためのプロパティであり、「時間を高精度に計測する」ためのものではない。ここを混同しているエンジニアがあまりにも多すぎる。
原因1：システムクロックの分解能（Resolution）の低さ
Windows OSのシステムクロックの更新周期は、デフォルトで約15.6ミリ秒（1/64秒）に設定されている。つまり、`DateTime.Now`の値は15.6ミリ秒ごとにしか更新されない。
どれだけ内部処理が高速化されていても、`DateTime.Now`で測ると「0ミリ秒」か「15.6ミリ秒」か「31.2ミリ秒」といった大雑把な飛躍値しか取得できない。数ミリ秒～数百マイクロ秒のボトルネックなど、逆立ちしても特定不可能なのだ。
原因2：OSの時刻同期（NTP）による時間の不連続性
`DateTime.Now`はシステム時刻に依存する。処理の実行中にWindowsがNTPサーバと時刻を同期して「時計を2秒戻す」調整を行った場合、経過時間がマイナスになる、あるいは異常な跳ね上がりを見せるバグが発生する。
—
2. 唯一の正解：System.Diagnostics.Stopwatch クラス
.NET Framework / .NET Coreにおいて、高精度の時間計測を行う唯一の正しい選択肢は `System.Diagnostics.Stopwatch` クラスである。
`Stopwatch`クラスは、OSやCPUNのハードウェアタイマー（Windowsにおいては `QueryPerformanceCounter` API）を直接叩くことで、ナノ秒レベル（100ナノ秒単位）の高分解能計測を実現する。
基本的な正しい使い方
Imports System.Diagnostics
‘ Stopwatchのインスタンス生成と同時に計測開始
Dim sw As Stopwatch = Stopwatch.StartNew()
‘ — 計測対象の処理 —
DoHeavyWork()
‘ ———————-
sw.Stop()
‘ ミリ秒単位での取得（ミリ秒未満の精度が必要なら ElapsedTicks や Elapsed.TotalMilliseconds を使用）
Console.WriteLine($”実行時間: {sw.ElapsedMilliseconds} ms”)
Console.WriteLine($”高精度実行時間: {sw.Elapsed.TotalMilliseconds:F3} ms”)
これだけで、`DateTime.Now`の呪縛から解放され、ミリ秒未満の精緻なデータを得ることができる。
—
3. 実務で勝つアーキテクチャ：IDisposable を使った「プロファイリングスコープ」
単に`Stopwatch`をペタペタ貼り付けるだけでは、計測用コードとビジネスロジックが混ざり合い、コードの可読性が著しく低下する。計測が終わった後にプロファイリングコードを消すのも一苦労だ。
プロのアーキテクトは、`IDisposable`パターンと`Using`ブロックを活用し、「囲むだけで自動的にログにミリ秒を出力する構造」を設計する。
コピペで使える「パフォーマンスプロファイラー」クラス
以下のクラスをプロジェクトに組み込んでほしい。プロダクション環境でもそのまま耐えうる設計にしてある。
Imports System.Diagnostics
”’
”’ IDisposable を実装しており、Using ブロックを抜けた瞬間に自動計測・ログ出力を行う。
”’
Public NotInheritable Class PerformanceScope
Implements IDisposable
Private ReadOnly _blockName As String
Private ReadOnly _sw As Stopwatch
Private ReadOnly _thresholdMs As Long
Private _disposedValue As Boolean
”’
”’
”’ 計測対象の処理名
”’ このミリ秒を超えた場合のみ警告ログを出す場合の閾値（デフォルト0は全出力）
Public Sub New(blockName As String, Optional thresholdMs As Long = 0)
Me._blockName = blockName
Me._thresholdMs = thresholdMs
Me._sw = Stopwatch.StartNew()
End Sub
”’
”’
Private Sub Dispose(disposing As Boolean)
If Not _disposedValue Then
If disposing Then
_sw.Stop()
Dim elapsedMs As Double = _sw.Elapsed.TotalMilliseconds
‘ 閾値判定（特定以上の遅延が発生した場合にアラートを上げる運用が可能）
If elapsedMs >= _thresholdMs Then
‘ 実際の実務では Trace、ILogger、NLog 等に差し替えること
Debug.WriteLine($”[PERF] [{_blockName}] 実行時間: {elapsedMs:F2} ms”)
End If
End If
_disposedValue = True
End If
End Sub
Public Sub Dispose() Implements IDisposable.Dispose
Dispose(disposing:=True)
GC.SuppressFinalize(Me)
End Sub
End Class
使用例：ビジネスロジックを美しく計測する
このクラスを使えば、既存のコードを汚すことなく、測定したいブロックを `Using` で囲むだけで済む。
Public Sub ProcessBusinessData()
‘ 全体の計測
Using New PerformanceScope(“データ処理プロセス全体”)
‘ 1. ファイル読み込みの計測
Dim rawData As String = String.Empty
Using New PerformanceScope(“CSVファイルロード”, thresholdMs:=100)
rawData = ReadCsvFile(“C:\data\large_input.csv”)
End Using
‘ 2. データ加工・パースの計測
Dim records As List(Of String())
Using New PerformanceScope(“データパース処理”)
records = ParseCsv(rawData)
End Using
‘ 3. データベース更新の計測
Using New PerformanceScope(“DB一括更新（バッチ）”, thresholdMs:=500)
BulkInsertToDatabase(records)
End Using
End Using
End Sub
このコードの美しさが解るだろうか。
計測の開始と終了が`Using`ブロックのライフサイクルと完全に一致しているため、例外（Exception）が発生して処理が中断しても、Disposeが保証されて確実にパフォーマンスログが記録される。堅牢そのものだ。
—
4. 業務プログラムにおけるボトルネック特定と改善のアプローチ
Stopwatchを手にしたら、次に行うべきは「ボトルネックの主因を切り分ける」ことだ。業務プログラム（特にVB.NETで組まれるツール）で発生する低速化の原因は、90%が以下の3点に集約される。
① I/Oボトルネック（ファイルアクセス・ネットワーク）
- 症状: CSVなどのファイル読み込み、ログ出力が遅い。
- 対策: 1行ずつ `StreamReader.ReadLine()` を叩いて何度もディスクアクセスしていないか？ `File.ReadAllLines()` やメモリストリーム、またはバッファリングを活用する。
② DBアクセス・クエリのボトルネック（N+1問題）
- 症状: DB処理の件数が増えると指数関数的に時間がかかる。
- 対策: ループの中でSQL（SELECT/INSERT）を発行していないか？ 1000件のデータを挿入するのに1000回クエリを投げたら遅くて当たり前だ。バルクインサート（`SqlBulkCopy`等）やトランザクションのまとめ化を行え。
③ CPU・メモリのボトルネック（文字列結合とGC）
- 症状: データ量が多い場合のループ処理自体が遅い。
- 対策: VB.NETでループ内で `String = String & “data”` をやっていないか？ 不変（Immutable）である`String`の結合は毎回メモリ確保とコピーを発生させ、GC（Garbage Collection）を痛めつける。大量の文字列操作は`StringBuilder`一択だ。
—
5. 高精度計測における「落とし穴」と極意
最高峰のエンジニアを目指すなら、Stopwatchを使う際にも以下の2つの物理的制約・特性を理解しておかねばならない。
1. JITコンパイル（ウォームアップ）の罠
.NET（VB.NET含む）は中間言語（IL）から実行時にJITコンパイラによって機械語へ変換される。
そのため、「メソッドの初回実行時間」にはJITコンパイルのオーバーヘッドが含まれる。
- 正確なアルゴリズムの速度を計測したい場合は、「ダミーで1回実行（ウォームアップ）させた後に計測を開始する」のがプロの鉄則だ。
2. リリースビルド（Release Config）で計測せよ
デバッグモード（Debugビルド）では、コンパイラによる最適化が無効化されており、不要なNOP命令やデバッグシンボル生成が含まれている。
ボトルネックの最終評価は、必ず「Releaseビルド」かつ「デバッガをアタッチしない状態（Ctrl + F5）」で計測しなければ意味がない。
—
まとめ：測定なき改善は単なる不吉な勘に過ぎない
- 時間計測に `DateTime.Now` を使うのは今日限りでやめろ。分解能が低く、精度が破綻している。
- 高精度計測には `System.Diagnostics.Stopwatch` を使用せよ。
- `IDisposable` と `Using` を組み合わせたプロファイリングスコープ構造を導入し、業務ロジックを汚さずにエレガントに計測せよ。
- 計測結果から 「I/O」「DB（N+1）」「メモリ（文字列結合・GC）」 のどこに原因があるかをロジカルに特定し、改善を叩き込め。
「勘」でコードを修正するな。Stopwatchによる「正確な数字」だけを信じよ。
それが、堅牢で超高速なシステムを組み上げる唯一無二の道である。
