反復処理ではじめの処理があとのに比べて遅い訳を知りたい

疑問に思っていること

私はC#でコンソールアプリケーションを制作していた。
そのプログラムに中でStopwatchクラスを反復処理の中で使用しているところがあった。
プログラムを動かし、計測したところ、初回のみ処理が遅かった。

何故、初回のみ処理が遅いのか理由を知りたい。

試したこと

原因を探るために以下のコンソールアプリケーションのソースコードを制作した。
Stopwatchをインスタンスし、計測開始、経過時間を表示、計測終了。
という処理を5回繰り返すだけだ。
一見、5回とも同じ処理だから表示される時間はどれもほぼ一緒のなると思うだろう。

結果

以下のデバッグコンソールにある。
初回は00:00:00.0000037であった。
そしてその後は00:00:00.0000002、00:00:00.0000001となった。
明らかに初回のみ処理が遅い。

予想

私は初回のみ遅くなるのはstopwatchのメモリの確保する時間が含まれるからだと考えている。
初回にその文のメモリを確保するためにメモリを整理し、その後は初回で使ったところを使用するため整理する必要がなかったと考えている。

ソースコード

C#
1using System;
2using System.Diagnostics;
3namespace tester
4{
5    class Program
6    {
7        static void Main()
8        {
9            for (int i = 0; i < 5; i++)
10            {
11                Stopwatch stopwatch = new Stopwatch();
12
13                stopwatch.Start();
14
15                Console.WriteLine(stopwatch.Elapsed.ToString());
16
17                stopwatch.Stop();
18            }
19        }
20    }
21}

デバッグコンソール

00:00:00.0000037
00:00:00.0000002
00:00:00.0000002
00:00:00.0000001
00:00:00.0000002

###追記。さらに検証実験を行った
Zuishinさんの意見を取り入れ、追加の実験を行った。

行った実験

1 - forを使わない。
2 - ElapsedをListにAddしてあとからWirteLineする。
3 - Listではなく配列
4 - ビルドする。

###追加実験1ソースコード

C#
1using System.Diagnostics;
2using System;
3namespace tester
4{
5    class Program
6    {
7        static void Main()
8        {
9            Stopwatch stopwatch1 = new Stopwatch();
10
11            stopwatch1.Restart();
12
13            Console.WriteLine(stopwatch1.Elapsed);
14
15            Stopwatch stopwatch2 = new Stopwatch();
16
17            stopwatch2.Reset();
18
19            Console.WriteLine(stopwatch2.Elapsed);
20
21            Stopwatch stopwatch3 = new Stopwatch();
22
23            stopwatch3.Reset();
24
25            Console.WriteLine(stopwatch3.Elapsed);
26
27            Stopwatch stopwatch4 = new Stopwatch();
28
29            stopwatch4.Reset();
30
31            Console.WriteLine(stopwatch4.Elapsed);
32
33            Stopwatch stopwatch5 = new Stopwatch();
34
35            stopwatch5.Reset();
36
37            Console.WriteLine(stopwatch5.Elapsed);
38        }
39    }
40}

###追加実験1デバッグコンソール

00:00:00.0000033
00:00:00
00:00:00
00:00:00
00:00:00

最初との違いは見られなかった。
早すぎて秒未満が表示されなかった。

###追加実験2ソースコード

C#
1using System.Collections.Generic;
2using System.Diagnostics;
3using System;
4namespace tester
5{
6    class Program
7    {
8        static void Main()
9        {
10            List<TimeSpan> timeSpans = new List<TimeSpan>();
11
12            for (int i = 0; i < 5; i++)
13            {
14                Stopwatch stopwatch = new Stopwatch();
15
16                stopwatch.Start();
17
18                timeSpans.Add(stopwatch.Elapsed);
19
20                stopwatch.Stop();
21            }
22
23            foreach(TimeSpan time in timeSpans)
24            {
25                Console.WriteLine(time);
26            }
27        }
28    }
29}

###追加実験2デバッグコンソール

00:00:00.0000053
00:00:00.0000001
00:00:00.0000001
00:00:00.0000001
00:00:00.0000001

最初との違いは見られなかった。

###追加実験3ソースコード

C#
1using System.Diagnostics;
2using System;
3namespace tester
4{
5    class Program
6    {
7        static void Main()
8        {
9            TimeSpan[] timeSpans = new TimeSpan[5];
10
11            for (int i = 0; i < 5; i++)
12            {
13                Stopwatch stopwatch = new Stopwatch();
14
15                stopwatch.Start();
16
17                timeSpans[i] = stopwatch.Elapsed;
18
19                stopwatch.Stop();
20            }
21
22            foreach(TimeSpan time in timeSpans)
23            {
24                Console.WriteLine(time);
25            }
26        }
27    }
28}

###追加実験3デバッグコンソール

00:00:00.0000040
00:00:00
00:00:00.0000001
00:00:00.0000001
00:00:00

最初との違いは見られなかった。

###追加実験4ソースコード

C#
1最初のと同じ

###追加実験4コンソール

00:00:00.0000017
00:00:00.0000001
00:00:00.0000001
00:00:00.0000001
00:00:00

最初より早いが、はじめはやはり遅い。

###追追記（これで解決）
radianさんの回答からStopwatchクラスをforより前に使用してからやれば早くなるのではと予想。
それで以下のソースコードの実験を行った。

###追追加実験ソースコード

C#
1using System.Diagnostics;
2using System;
3namespace tester
4{
5    class Program
6    {
7        static void Main()
8        {
9            Stopwatch st = new Stopwatch();
10
11            st.Start();
12
13            _ = st.Elapsed;
14
15            for (int i = 0; i < 5; i++)
16            {
17                Stopwatch stopwatch = new Stopwatch();
18
19                stopwatch.Start();
20
21                Console.WriteLine(stopwatch.Elapsed.ToString());
22            }
23
24            Console.ReadLine();
25        }
26    }
27}

###追追加実験デバッグコンソール

00:00:00.0000001
00:00:00.0000002
00:00:00.0000001
00:00:00.0000002
00:00:00.0000002

こ・れ・は......！

初回が早くなった。
今までのソースコードはJITコンパイルを初回でやっていると考えれば、今回のソースコードではforの前にやっているのでその分の処理時間が省かれたと考えられる。

これらより、反復処理ではじめの処理があとのに比べて遅い訳はJITコンパイルを初回で行っているため、初回の処理が時間がかかったといえる。

今回の問題にご協力いただいた皆さんありがとうございました。

環境

visual studio 2019
Microsoft.NETCore.App 3.1.1 コンソールアプリケーション

Zuishin

2020/09/11 13:21

https://referencesource.microsoft.com/#System/services/monitoring/system/diagnosticts/Stopwatch.cs,16 Stopwatch のソースです。このクラス自身は Start と Stop の時刻を記録してるだけなので関係ないと思います。絡むとしたら JIT かデバッガか標準出力かコンソールかその辺じゃないでしょうか。

hihijiji

2020/09/12 02:19

試しに追加実験3ソースコードのストップウォッチの初期化 ``Stopwatch stopwatch = new Stopwatch();``をループより前に出して見てください。予想外の結果になると思いますが、デスクトップ版のWindowsで1000分の1秒未満なんて誤差の範囲です。実験としては面白いですが、OS自体が複雑すぎてその間にいろいろやってるはずなので結果にはあまり意味がありません。