記一次 .NET某智慧出行系統 CPU爆高分析

一：背景

1. 講故事

前些天有位朋友找到我，說他們的系統出現了CPU 100%的情況，讓我幫忙看一下怎麼回事？dump也拿到了，本想著這種情況讓他多抓幾個，既然有了就拿現有的分析吧。

二：WinDbg 分析

1. 為什麼會爆高

既然說是 100%，作為調試者得拿數據說話，可以使用 !tp 來觀測一下。

0:000:x86> !tp
CPU utilization: 100%
Worker Thread: Total: 382 Running: 382 Idle: 0 MaxLimit: 8191 MinLimit: 8
Work Request in Queue: 8694
    Unknown Function: 6f62b650  Context: 4a36bbbc
    Unknown Function: 6f62b650  Context: 4a36e1d4
    Unknown Function: 6f62b650  Context: 4a372384
    Unknown Function: 6f62b650  Context: 239adfec
    Unknown Function: 6f62b650  Context: 4a374994
    Unknown Function: 6f62b650  Context: 239b9e14
    Unknown Function: 6f62b650  Context: 2399fd9c
    ...

從卦中看,不得了，CPU 100% 之外,所有的線程池線程全部被打滿，人生自古最忌滿，半貧半富半自安。同時線程池隊列還累計了8694個任務待處理，說明這時候的線程池已經全面淪陷，要想找到這個答案，需要用 ~*e !clrstack 命令觀察每一個線程此時正在做什麼，輸出如下：

0:000:x86> ~*e !clrstack
OS Thread Id: 0x22f4 (429)
Child SP       IP Call Site
4bc1e060 0000002b [GCFrame: 4bc1e060] 
4bc1e110 0000002b [HelperMethodFrame_1OBJ: 4bc1e110] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
4bc1e19c 24aad7da System.Threading.Monitor.Wait(System.Object, Int32, Boolean)
4bc1e1ac 2376f0d6 ServiceStack.Redis.PooledRedisClientManager.GetClient()
4bc1e1dc 2420bbc6 xxx.Service.CacheService.GetClient()
...
4bc1e234 24206fbe xxxBLL.GetxxxCount(System.Collections.Generic.Dictionary`2<System.String,System.Object>)
4bc1e3e0 216e25f9 DynamicClass.lambda_method(System.Runtime.CompilerServices.Closure, System.Web.Mvc.ControllerBase, System.Object[])
4bc1e3f0 238b86b7 System.Web.Mvc.ActionMethodDispatcher.Execute(System.Web.Mvc.ControllerBase, System.Object[])
...
4bc1eee0 2353d448 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
4bc1efb8 00a9e3c2 [ContextTransitionFrame: 4bc1efb8] 

從卦中可以看到當前有 371個線程在 PooledRedisClientManager.GetClient 中的 Wait 上出不來，那為什麼出不來呢？

2. 探究源碼

要想找到這個答案，只能從源代碼中觀察，簡化後的代碼如下：

    public IRedisClient GetClient()
    {
        lock (writeClients)
        {
            AssertValidReadWritePool();
            RedisClient inActiveWriteClient;
            while ((inActiveWriteClient = GetInActiveWriteClient()) == null)
            {
                if (!Monitor.Wait(writeClients, PoolTimeout.Value))
                {
                    throw new TimeoutException("Redis Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use.");
                }
            }
        }
    }

    private RedisClient GetInActiveWriteClient()
    {
        int num = WritePoolIndex % writeClients.Length;
        for (int i = 0; i < ReadWriteHosts.Count; i++)
        {
            int num2 = (num + i) % ReadWriteHosts.Count;
            RedisEndPoint redisEndPoint = ReadWriteHosts[num2];
            for (int j = num2; j < writeClients.Length; j += ReadWriteHosts.Count)
            {
                if (writeClients[j] != null && !writeClients[j].Active && !writeClients[j].HadExceptions)
                {
                    return writeClients[j];
                }
            }
        }
        return null;
    }

仔細閱讀卦中代碼，之所以進入Wait主要是因為 GetInActiveWriteClient() 方法返回 null 所致，從異常信息看也知道此時是因為 writeClients 池已滿，那這個池是不是滿了呢？可以把 writeClients 數組挖出來，使用 !dso 命令。

0:429:x86> !dso
OS Thread Id: 0x22f4 (429)
ESP/REG  Object   Name
...
4BC1E0D0 0ea38d18 ServiceStack.Redis.RedisClient[]
4BC1E100 0ea38bb0 ServiceStack.Redis.PooledRedisClientManager
...

0:429:x86> !da 0ea38d18
Name:        ServiceStack.Redis.RedisClient[]
MethodTable: 237af1c0
EEClass:     0129a224
Size:        52(0x34) bytes
Array:       Rank 1, Number of elements 10, Type CLASS
Element Methodtable: 237ae954
[0] 0ea38dd4
[1] 0a9f9f58
[2] 0296e468
[3] 0c9786a0
[4] 0a9fe768
[5] 04a21f24
[6] 0aa0d758
[7] 10946d90
[8] 04a8c8b0
[9] 02a2a2a0

0:429:x86> !DumpObj /d 0ea38dd4
Name:        ServiceStack.Redis.RedisClient
MethodTable: 237ae954
EEClass:     2375d154
Size:        152(0x98) bytes
File:        C:\Windows\xxx\ServiceStack.Redis.dll
Fields:
...
0129aa48  4000169       7d       System.Boolean  1 instance        1 <Active>k__BackingField
...

從卦中看 writeClients 池只有10個大小，並且都是 Active=1，所以返回 null 就不足為奇了。

3. 為什麼client都在使用中呢

要想找到這個答案，需要看下上層的 xxxBLL.GetxxxCount 方法是如何調用的，為了保護隱私，就多模糊一點。

從圖中可以看到，問題出在用 foreach 去不斷的迭代 ServiceStack.Redis 導致 writeClient 池耗盡，導致大量的請求在不斷的阻塞，不要忘了這裡有371個線程在爭搶哦，真是大忌。

接下來順帶洞察下這個 foreach 要 foreach 多少次？ 繼續用 !dso 去挖。

0:429:x86> !DumpObj /d 077cec20
Name:        System.Collections.Generic.List`1[[xxxInfo, xxx]]
MethodTable: 241ad794
EEClass:     0193166c
Size:        24(0x18) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
01860eec  4001891        4     System.__Canon[]  0 instance 077e0048 _items
0129c9b0  4001892        c         System.Int32  1 instance      307 _size
0129c9b0  4001893       10         System.Int32  1 instance      307 _version
01296780  4001894        8        System.Object  0 instance 00000000 _syncRoot
01860eec  4001895        4     System.__Canon[]  0   static  <no information>

從卦中看當前需要迴圈307次，也就再次驗證了池耗盡的說法，我知道心細的朋友肯定會說，卡死這個我認，但能導致 CPU爆高 我就不能理解了，其實你仔細閱讀源碼就能理解了，這是經典的 鎖護送(lock convoy) 現象，因為滿足如下兩個條件。

1. 多線程的 foreach 高頻調用。
2. Wait 導致線程暫停進入等待隊列。

4. 如何解決這個問題

知道了前因後果，解決起來就比較簡單了，三種做法：

1. 將 foreach 迭代 改成 批量化處理，減少對 writeclient 的租用。
2. 增加 writeclient 的池大小，官網有所介紹。
3. ServiceStack.Redis 的版本非常老，又是收費的，最好換掉已除後患。

三：總結

這次生產事故分析還是非常有意思的，一個看似阻塞的問題也會引發CPU爆高，超出了一些人的認知吧，對，其實它就是經典的 lock convoy 現象，大家有任何dump問題可以找我，一如既往的免費分析。