一：背景
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)
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 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
从卦中看当前需要循环307次，也就再次验证了池耗尽的说法，我知道心细的朋友肯定会说，卡死这个我认，但能导致 cpu爆高 我就不能理解了，其实你仔细阅读源码就能理解了，这是经典的 锁护送(lock convoy) 现象，因为满足如下两个条件。
- 多线程的 foreach 高频调用。
- wait 导致线程暂停进入等待队列。
4. 如何解决这个问题
知道了前因后果，解决起来就比较简单了，三种做法：
- 将 foreach 迭代 改成 批量化处理，减少对 writeclient 的租用。
- 增加 writeclient 的池大小，d88尊龙官网手机app官网有所介绍。
- servicestack.redis 的版本非常老，又是收费的，最好换掉已除后患。
三：总结
这次生产事故分析还是非常有意思的，一个看似阻塞的问题也会引发cpu爆高，超出了一些人的认知吧，对，其实它就是经典的 lock convoy 现象，大家有任何dump问题可以找我，一如既往的免费分析。
