.NET 效能測試首次執行偏慢現象解析

2018-12-22 10:17 AM

上回研究 Stopwatch 測量微秒精確度有個小插曲，第一次執行 MD5、SHA1 運算總會特別慢，慢了五倍有餘，先跑 MD5 慢的是 MD5，先跑 SHA1 慢的就是 SHA1，之後的數字才正常。

這個現象挺有趣，初次起始慢讓我們優先想到的原因多半與笨重資源有關，例如：建立網路連線、開啟檔案、配置記憶體... 等等，首次資源初始化後，後續執行可共用或重複利用，省去初始化時間因此變快。但回歸到單純的雜湊函數運算，不需要引用外部資源，然後不管用哪個雜湊演算法延遲的時間都差不多，就不是那麼容易想像延遲的來源。

我做了一個範例程式突顯這個現象。程式分別使用 MD5、SHA1、SHA256 三種雜湊演算法計算同一組資料的雜湊值，參數 1,2,3 決定測試順序，1 是 MD5、SHA1、SHA256，2 是 SHA1、MD5、SHA256，3 是 SHA256、MD5、SHA1，每回合測試用迴圈計算三次，每次程式執行跑兩回合。

using System;
using System.Diagnostics;
using System.Security.Cryptography;

namespace PerfTest
{
    class Program
    {
        static byte[] data = new byte[512 * 1024];
        private const int COUNT = 3;
        static void Main(string[] args)
        {
            var flag = args.Length > 0 ? args[0] : "1";
            switch (flag)
            {
                case "1":
                    Test1();
                    Test1();
                    break;
                case "2":
                    Test2();
                    Test2();
                    break;
                case "3":
                    Test3();
                    Test3();
                    break;
            }
        }

        static void Test(Action doJob, string name)
        {
            Stopwatch sw = new Stopwatch();
            sw.Start();
            doJob();
            sw.Stop();
            Console.Write("{0,-7} {1,7}μs\t", name, 
                $"{sw.Elapsed.TotalMilliseconds * 1000:n0}");
        }

        private static void Test1()
        {
            Console.WriteLine("=== Test 1 MD5 First ===");
            for (var i = 0; i < COUNT; i++)
            {
                Test(()=>MD5.Create().ComputeHash(data), "MD5");
                Test(()=>SHA1.Create().ComputeHash(data), "SHA1");
                Test(() => SHA256.Create().ComputeHash(data), "SHA256");
                Console.WriteLine();
            }
        }

        private static void Test2()
        {
            Console.WriteLine("=== Test 2 SHA1 First ===");
            for (var i = 0; i < COUNT; i++)
            {
                Test(() => SHA1.Create().ComputeHash(data), "SHA1");
                Test(() => MD5.Create().ComputeHash(data), "MD5");
                Test(() => SHA256.Create().ComputeHash(data), "SHA256");
                Console.WriteLine();
            }
        }
        private static void Test3()
        {
            Console.WriteLine("=== Test 3 SHA256 First ===");
            for (var i = 0; i < COUNT; i++)
            {
                Test(() => SHA256.Create().ComputeHash(data), "SHA256");
                Test(() => MD5.Create().ComputeHash(data), "MD5");
                Test(() => SHA1.Create().ComputeHash(data), "SHA1");
                Console.WriteLine();
            }
        }


    }
}

測試結果如下：

如同上回的測試，第一回合測試的第一個運算，不管是 MD5、SHA1、SHA256，總是比正常值慢 6-8ms，而這只會出現在第一回合，第二回合就正常了。

追進原始碼試著找原因。MD5.Create()、SHA1.Create()、SHA256.Create() 背後都會呼叫 CryptoConfig.CreateFromName()，其中呼叫 InitializeConfigInfo() 跑迴圈初始化，疑似拖累效能的嫌犯，另外還有幾個貌似笨重只需執行一次的屬性 CryptoConfig.DefaultNameHT、Type.DefaultBinder，我修改了程式，在呼叫 MD5.Create() 前先執行這些具有嫌疑的一次性方法：(InitializeConfigInfo、DefaultNameHT 為 private static，要用 Reflection 技巧摸進去觸發)

static byte[] data = new byte[512 * 1024];
private const int COUNT = 3;
static void Main(string[] args)
{
    Test(() =>
    {
        MethodInfo mi =
            typeof(CryptoConfig).GetMethod("InitializeConfigInfo",
            BindingFlags.Static | BindingFlags.NonPublic);
        mi.Invoke(null, null);
    }, "InitializeConfigInfo");
    Test(() =>
    {
        var pi = typeof(CryptoConfig).GetProperty("DefaultNameHT",
            BindingFlags.Static | BindingFlags.NonPublic);
        var o = pi.GetValue(null, null);

    }, "\nDefaultNameHT");
    Test(() =>
    {
        var binder = Type.DefaultBinder;
    }, "\nType.DefaultBinder");
    Console.WriteLine();
    var flag = args.Length > 0 ? args[0] : "1";
    switch (flag)
    {
        case "1":
            Test1();
            Test1();
            break;
        case "2":
            Test2();
            Test2();
            break;
        case "3":
            Test3();
            Test3();
            break;
    }
}

預先執行這些靜態方法、屬性後，第一次執行延遲明顯縮短(9ms -> 3ms)，測量得到 InitializeConfigInfo 耗時 6ms，DefaultNameHT 耗時 1ms，也接近原本首次執行出現 6-8ms 差距。ComputeHash() 的部分可能也有類似情況，但比重不高，我懶得繼續深入。

這個結果可印證我們的推論方向正確但仍稱不上鐵證，於是我想到可以 Line-By-Line 測量各方法耗時的神奇工具 - JetBrains dotTrace Profiler 並將程式碼簡化如下：

static byte[] data = new byte[512 * 1024];

static void TestMD5_First()
{
    var hash = MD5.Create().ComputeHash(data);
}

static void TestMD5_Second()
{
    var hash = MD5.Create().ComputeHash(data);
}
static void Main(string[] args)
{
    TestMD5_First();
    TestMD5_Second();
}

啟用 dotTrace Line-By-Line 欄截追蹤，程式執行速度雖因此嚴重變慢，但捕捉到的耗時比例卻極具參考價值。由以下結果可知第一次執行 MD5.Create() 耗時 218ms，第二次 MD5.Create() 則縮短到 1ms 搞定。而第一次 Create() 執行 InitializeConfigInfo() 耗时 142ms，第二次則為 0 秒，與先前的實驗結果相符。而其他如 GetConstructors()、GetParameters() 的第二次執行時間也是 0 ms。dotTrace 的追蹤結果為第一次執行較慢的現象提供了極具說服力的解釋。