Execute same method consume far less time

Question

When I analyzed my old posts exact solution, I found a contradiction so I try to code this in Form1 constructor (after InitializeComponent();)

Stopwatch timer = Stopwatch.StartNew();
var timeStartGetStatistic = DateTime.Now.ToString("HH:mm:ss:fff");
var timeEndGetStatistic = DateTime.Now.ToString("HH:mm:ss:fff"); 
timer.Stop();
Console.WriteLine("Convert take time {0}", timer.Elapsed);

Console.WriteLine("First StopWatch\nStart:\t{0}\nStop:\t{1}",
    timeStartGetStatistic, timeEndGetStatistic);

Stopwatch timer2 = Stopwatch.StartNew();
var timeStartGetStatistic2 = DateTime.Now.ToString("HH:mm:ss:fff");
var timeEndGetStatistic2 = DateTime.Now.ToString("HH:mm:ss:fff");
timer2.Stop();
Console.WriteLine("Convert take time {0}", timer2.Elapsed);

Console.WriteLine("Second StopWatch\nStart:\t{0}\nStop:\t{1}",
    timeStartGetStatistic2, timeEndGetStatistic2);

Result

Convert take time 00:00:00.0102284

First StopWatch

Start: 02:42:29:929

Stop: 02:42:29:939

Convert take time 00:00:00.0000069

Second StopWatch

Start: 02:42:29:940

Stop: 02:42:29:940

I found that only FIRST DateTime.Now.ToString("HH:mm:ss:fff"); consumes 10ms but 3 others consume less than 10us in same scope, may I know the exact reason?

Is it because the FIRST one make the code on the memory so the following 3 get the advantage of it to consume more less time to do the same things? thanks.

Did you answered yourself? if what you meant was that the first call must be JITed, and afterward it is cached in memory - then that is probably the answer. — Shlomi Borovitz, Mar 05 '14 at 18:56
nono, I dont have answer, by the way I found similar question in Java. http://stackoverflow.com/questions/16775170/second-method-call-takes-far-less-time-than-the-first?rq=1 — V-SHY, Mar 05 '14 at 18:57
not only if all thread doing allot of IO.. if you'll check Task manager, you'll see that the CPU is idle most of the time. so when the block ends, your thread would be rescheduled almost immediately — Shlomi Borovitz, Mar 05 '14 at 19:15

Shlomi Borovitz · Accepted Answer · 2014-03-05T19:41:28.653

At first, I thought it was indeed the JIT.. but it doesn't make sense because the framework itself is compiled AOT, when installed.

I think it is loading the current culture (ToString does that, and indeed it is the function that takes time)

================ EDIT =============

I did some tests, and there are two things which take time the first time they are called.

DateTime.Now make a call to the internal method TimeZoneInfo.GetDateTimeNowUtcOffsetFromUtc which take about half of the consumed time...

the rest is consumed by to string..

if instead of calling DateTime.Now you had called DateTime.UtcNow, you wouldn't notice that first-time impact of getting the local time offset.

and about ToString - what's consuming most of it's running time, was generating the DateTimeFormat for the current culture.

I think this answered your question pretty well :)

If I change the culture of 'ToString()', then will consider as another new first call?thanks — V-SHY, Mar 05 '14 at 19:36
about changing the culture - yes, it would take long time again — Shlomi Borovitz, Mar 05 '14 at 19:56

Alexei Levenkov · Answer 2 · 2014-03-05T19:10:31.217

2

First call to any individual method from a class requires JIT so first call is always slow (unless assembly pre-JITed with NGen).

There also additional cost to load necessary resources/data depending on method associated with first call. I.e. likely DateTime.Now and DateTime.ToString require some locale data to be loaded/preprocessed.

Standard way to measure performance with Stopwatch is to call function/code that you want to measure once to kick all JIT related to the code and than do measurement. Usually you'd run code many times and average results.

// --- Warm up --- ignore time here unless meauring startup perf.
var timeStartGetStatistic = DateTime.Now.ToString("HH:mm:ss:fff");
var timeEndGetStatistic = DateTime.Now.ToString("HH:mm:ss:fff"); 


// Actual timing after JIT and all startup cost is payed.
Stopwatch timer2 = Stopwatch.StartNew();
// Consider multiple iterations i.e. to run code for about a second.
var timeStartGetStatistic2 = DateTime.Now.ToString("HH:mm:ss:fff");
var timeEndGetStatistic2 = DateTime.Now.ToString("HH:mm:ss:fff");
timer2.Stop();
Console.WriteLine("Convert take time {0}", timer2.Elapsed);

Console.WriteLine("Second StopWatch\nStart:\t{0}\nStop:\t{1}",
    timeStartGetStatistic2, timeEndGetStatistic2);

edited Mar 05 '14 at 19:10

answered Mar 05 '14 at 18:58

Alexei Levenkov

98,904
14
127
179

first call means in whole class or first call in same scope or else? thanks – V-SHY Mar 05 '14 at 19:00
2

first call, of every method, in every type... but what troubles me, is that `ToString` (the method which consumes the time), is part of the framework itself, which means it's not JITed, rather compiled AOT.. maybe it is loading the culture – Shlomi Borovitz Mar 05 '14 at 19:03
1

@V-SHY - first call to any individual method (unless assembly is pre-JITed with NGen), there is additional cost for first usage of type too. `DateTime` methods are likely pre-JITed, so as Shlomi Borovitz pointed out initial cost may be due loading resources. – Alexei Levenkov Mar 05 '14 at 19:08
yes, the most of the time consuming part is ToString but not DateTime.Now. – V-SHY Mar 05 '14 at 19:08
How can we know which is assembly Pre-JITed? Visual studio feature? Thanks. – V-SHY Mar 05 '14 at 19:26
1

@V-SHY http://stackoverflow.com/questions/2282397/determine-if-gaced-ngened-assemblies-are-being-used – Alexei Levenkov Mar 05 '14 at 19:28

score 0 · Answer 3 · answered Mar 05 '14 at 19:04

0

As already noted you're measuring wrong. You should not include first call to any code as it needs to be jited, that time will be included.

Also it is not good to rely on result just ran only once; You need to run the code number of times and you should be calculating the average time taken.

Be sure that you do it in release mode without debugger attached.

answered Mar 05 '14 at 19:04

Sriram Sakthivel

72,067
7
111
189

Before this,I have no idea about JITed, so I coded like that. Is it in release mode will have far less first time calling time consume? Sorry if my noun is not technically and please correct me,thanks – V-SHY Mar 05 '14 at 19:32
1

Yes, [it will be bit faster in release mode](http://stackoverflow.com/questions/2446027/c-sharp-debug-vs-release-performance) – Sriram Sakthivel Mar 05 '14 at 19:35

Execute same method consume far less time

Result

3 Answers3