My static method seems to perform faster with reuse. Why? Does it become cached?

Question

I created code to see how fast my static compression method takes to execute, and I noticed that the first execution takes 8,500,000 nanoseconds, the second about half that, and then everything after that executes at 0 nanoseconds. Why?

private void CheckPerformance()
{
    while (KeepRunning)
    {
        //generates a complex random 500 character string
        string text = GenerateString(500, 4);


        DateTime beginTime = DateTime.Now;

        byte[] bytes = Compress(text); // < - timing this

        long elapsedTicks = DateTime.Now.Ticks - beginTime.Ticks;
        Console.WriteLine("   {0:N0} nanoseconds", elapsedTicks * 100);

        //sleep for 5 seconds
        Thread.Sleep(5000);
    }
}

public static byte[] Compress(string text)
{
    using (MemoryStream output = new MemoryStream())
    {
        using (DeflateStream ds = new DeflateStream(output, CompressionMode.Compress))
        {
            using (StreamWriter writer = new StreamWriter(ds, Encoding.UTF8))
            {
                writer.Write(text);
            }
        }
        return output.ToArray();
    }
}

CodingYoshi · Accepted Answer · 2016-12-29T14:04:50.070

The DateTime.Now gets updates around 10 times per second but don't quote me on this (could be depending on hardware and software setting). It's also slow because it needs to figure out what timezone the system is on. UtcNow is faster but will still be cached for a bit. Therefore, it could be using the cached version on subsequent calls.

Use StopWatch instead for more accurate measurement. StopWatch uses high precision by utilizing hardware. You can check that using Stopwatch.IsHighResolution.

using System.Diagnostics;

Stopwatch sw = new Stopwatch();

sw.Start();

// code to benchmark 

sw.Stop();

Let's see if you get same metrics.

EDIT

While it is true that your method needs to be JIT compiled, the difference cannot be due to JIT compilation because it will be JIT compiled only once (not always but in your case it will be once) and then reused. Therefore, only the first call should take longer and the subsequent calls should be the same. To throw this assumption away, simply call Compress once outside the benchmarking phase so it is JIT compiled. Then benchmark it, and now the JIT compilation will not occur, and DateTime will still give you random results because it is cached.

Note: The JIT compiler does not necessarily always compile the whole method into machine code but only when execution passes through the code. So if you have if statements, the blocks may not be compiled until execution is passed through the block. But yours have no if statements so that is why it will be JIT compiled once.

Furthermore, we cannot say with confidence this was due to JIT compilation since it is possible Compress method could have been inlined but in your case it was most likely not inlined since you most likely had the debugger on and therefore, JIT optimization will be disabled.

Try this code and you will notice it gives random results for elapsed time even though the same code is executed:

for (int i = 0; i < 1000; i++)
{
    DateTime beginTime = DateTime.UtcNow;

    var sw = Stopwatch.StartNew();

    while (sw.ElapsedTicks < 100)
    {
        Console.WriteLine("*");
    }
    long elapsedTicks = DateTime.UtcNow.Ticks - beginTime.Ticks;
    Console.WriteLine("   {0:N0} nanoseconds", elapsedTicks * 100);
}

On my system if I change this line to sw.ElapsedTicks < 2050, then there is always is a difference of non zero reported consistently. Which means right around there is when DateTime.Now gets a new value instead of using the cached one.

In conclusion, I do not buy that JIT compilation is the explanation for what you are noticing.

I was actually still getting numbers that increased, so I switched to sw.Restart() and got much more consistent (and awesome) numbers at around 100-250 elapsed "ticks" which was about 0 milliseconds. — Rich76, Dec 29 '16 at 06:58
Yes depending on how you used it, you may need to restart it but I figured you would know that. Plus while it's true the method needs to be Jit compiled, that difference is negligible and cannot explain the difference in the second and third time difference. — CodingYoshi, Dec 29 '16 at 12:12

score 1 · Answer 2 · answered Dec 29 '16 at 06:09

1

When you hit it the first time, it gets jitted. So that takes time. Not sure though why the second and third times differ.

answered Dec 29 '16 at 06:09

Aleksey Nikulshin

11
4

I had to switch my answer to yours, as I ended up getting the same results from the StopWatch, and your answer probably best explains why, and is reinforced by the following: >The answer is that Stopwatch does not compensate for "background noise" activity in .NET, such as JITing. Therefore the first time you run your method, .NET JIT's it first. The time it takes to do this is added to the time of the execution. Equally, other factors will also cause the execution time to vary. >[Calculate the execution time of a method](http://stackoverflow.com/a/14019738/5009753) – Rich76 Dec 29 '16 at 07:18
1

My guess would be more extensive optimization being applied after the initial pass. It probably sees that you're throwing away the result, and stops calculating it. Caching is certainly always another possibility when you call code repeatedly in a loop. – Cody Gray - on strike Dec 29 '16 at 13:35

My static method seems to perform faster with reuse. Why? Does it become cached?

2 Answers2