黄太孙耐克裁判坐牢冠 发表于 2024-8-8 12:46:04

记一次 .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: 6f62b650Context: 4a36bbbc
    Unknown Function: 6f62b650Context: 4a36e1d4
    Unknown Function: 6f62b650Context: 4a372384
    Unknown Function: 6f62b650Context: 239adfec
    Unknown Function: 6f62b650Context: 4a374994
    Unknown Function: 6f62b650Context: 239b9e14
    Unknown Function: 6f62b650Context: 2399fd9c
    ...从卦中看,不得了,CPU 100% 之外,所有的线程池线程全部被打满,人生自古最忌满,半贫半富半自安。同时线程池队列还累计了8694个任务待处理,说明这时候的线程池已经全面沦陷,要想找到这个答案,需要用 ~*e !clrstack 命令观察每一个线程此时正在做什么,输出如下:
0:000:x86> ~*e !clrstack
OS Thread Id: 0x22f4 (429)
Child SP       IP Call Site
4bc1e060 0000002b
4bc1e110 0000002b 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
从卦中可以看到当前有 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;
            for (int j = num2; j < writeClients.Length; j += ReadWriteHosts.Count)
            {
                if (writeClients != null && !writeClients.Active && !writeClients.HadExceptions)
                {
                  return writeClients;
                }
            }
      }
      return null;
    }仔细阅读卦中代码,之所以进入Wait主要是因为 GetInActiveWriteClient() 方法返回 null 所致,从异常信息看也知道此时是因为 writeClients 池已满,那这个池是不是满了呢?可以把 writeClients 数组挖出来,使用 !dso 命令。
0:429:x86> !dso
OS Thread Id: 0x22f4 (429)
ESP/REGObject   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
0ea38dd4
0a9f9f58
0296e468
0c9786a0
0a9fe768
04a21f24
0aa0d758
10946d90
04a8c8b0
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:
...
0129aa484000169       7d       System.Boolean1 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[]
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
01860eec4001891      4   System.__Canon[]0 instance 077e0048 _items
0129c9b04001892      c         System.Int321 instance      307 _size
0129c9b04001893       10         System.Int321 instance      307 _version
012967804001894      8      System.Object0 instance 00000000 _syncRoot
01860eec4001895      4   System.__Canon[]0   static<no information>从卦中看当前需要循环307次,也就再次验证了池耗尽的说法,我知道心细的朋友肯定会说,卡死这个我认,但能导致 CPU爆高 我就不能理解了,其实你仔细阅读源码就能理解了,这是经典的 锁护送(lock convoy) 现象,因为满足如下两个条件。

[*]多线程的 foreach 高频调用。
[*]Wait 导致线程暂停进入等待队列。
4. 如何解决这个问题

知道了前因后果,解决起来就比较简单了,三种做法:

[*]将 foreach 迭代 改成 批量化处理,减少对 writeclient 的租用。
[*]增加 writeclient 的池大小,官网有所介绍。
[*]ServiceStack.Redis 的版本非常老,又是收费的,最好换掉已除后患。
三:总结

这次生产事故分析还是非常有意思的,一个看似阻塞的问题也会引发CPU爆高,超出了一些人的认知吧,对,其实它就是经典的 lock convoy 现象,大家有任何dump问题可以找我,一如既往的免费分析。

来源:https://www.cnblogs.com/huangxincheng/p/18348453
免责声明:由于采集信息均来自互联网,如果侵犯了您的权益,请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容,谢谢合作!
页: [1]
查看完整版本: 记一次 .NET某智慧出行系统 CPU爆高分析