某天某服务预警一直提示某服务性能不足,cpu已满负荷。很是纳闷,这个服务是纯内存数据,没有io操作;而且都运行了快3个月了,怎么突然就性能不足了?
步骤1
半夜从睡梦中被叫醒,先自己缕一缕思路(整个人都是懵的,基本缕不出思路),先解决线上问题, 让运维保存了一份fulldump,然后重启服务,线上正常,回去睡觉。
异常出现时需要哪些现场信息,比如日志、dump、cpu、内存状态……;因为平时有积累,比如cpu、内存信息主机是有程序在定时生成的;版本(svn、pdb、exe)是自动化编译自动保存的;……
步骤2
向运维取了当时的dump文件(提取码: q5kx),向版本服务器获取了匹配的pdb、svn记录,获取了当时的日志、cpu、内存信息。使用windbg 打开dump,发现是一个64位dump。
步骤3
加载pdb,将64位dump切换到32位,然后打印所有线程。1
2
3
40:000> .load wow64exts
0:000> !sw
Switched to 32bit mode
0:000:x86> ~*kv
1 | 0 Id: c2c.a4c Suspend: 0 Teb: 7efdb000 Unfrozen |
步骤4
分析各个线程。从线程中可以看到总共有24个线程,其中有部分能看到代码,有部分不能看到代码。我们只能先从有代码的线程开始分析,因为这部分线程才是自己程序的主要处理模块。
可以看到大多线程都在处理 CSockServer::OnPlayerLogon 函数,查看对应的代码,理了下大概逻辑:服务程序使用8个线程接收用户登陆请求,并将用户信息保存在一个全局CMap中,CMay的key是用户id,value是一个类。这个dump线程反应出来的就是当时在处理很多用户的登陆信息,没有什么异常点啊???? 当时就觉的碰到坎了,认为导的dump可能不是引起cpu高时的运行栈, 后悔应该让运维多导几个dump,通过比较应该找的到高cpu时线程运行栈。
暂时没辙就打开看下当时的参数信息,慢慢的就看到了CMap的大小
切换到9号线程
~9s1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
160:009:x86> kv
ChildEBP RetAddr Args to Child
0377f87c 001b3a7d 0addba3c 0377f898 0377f890 kubsvr!CMap<int,int,_tagPLAYER_LOGON_MINI,_tagPLAYER_LOGON_MINI &>::GetAssocAt+0x61 (FPO: [Non-Fpo]) (CONV: thiscall) [c:\program files (x86)\microsoft visual studio 12.0\vc\atlmfc\include\afxtempl.h @ 1542]
0377f8a8 001bad38 0addba3c 005a1a58 200d99a8 kubsvr!CMap<int,int,_tagPLAYER_LOGON_MINI,_tagPLAYER_LOGON_MINI &>::operator[]+0x1d (FPO: [Non-Fpo]) (CONV: thiscall) [c:\program files (x86)\microsoft visual studio 12.0\vc\atlmfc\include\afxtempl.h @ 1589]
0377f8c0 001b7a53 0addba3c 0377f8e0 798f5637 kubsvr!CMap<int,int,_tagPLAYER_LOGON_MINI,_tagPLAYER_LOGON_MINI &>::SetAt+0x18 (FPO: [Non-Fpo]) (CONV: thiscall) [c:\program files (x86)\microsoft visual studio 12.0\vc\atlmfc\include\afxtempl.h @ 1349]
0377f920 001cfc90 1c8d1540 2008cb20 00593ee8 kubsvr!CSockServer::OnPlayerLogon+0xb3 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\kubsvr\folder.cpp @ 1602]
0377f950 001d1904 1c8d1540 2008cb20 005a1a60 kubsvr!CSockServer::OnRequest+0x660 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\kubsvr\socksvr.cpp @ 166]
0377f978 001d818b 00000000 005be950 005bd800 kubsvr!CIocpWorker::DoWorkLoop+0xa4
0377f990 001d815b 0377f9d0 7347c01d 005a1a58 kubsvr!CBaseWorker::WorkerThreadProc+0x2b
0377f998 7347c01d 005a1a58 e2366994 00000000 kubsvr!CBaseWorker::WorkerThreadFunc+0xb
WARNING: Stack unwind information not available. Following frames may be wrong.
0377f9d0 7347c001 00000000 0377f9e8 75dd338a MSVCR120!_get_flsindex+0x6f
0377f9dc 75dd338a 005bd800 0377fa28 77bb9902 MSVCR120!_get_flsindex+0x53
0377f9e8 77bb9902 005bd800 ef138d2e 00000000 kernel32!BaseThreadInitThunk+0x12
0377fa28 77bb98d5 7347bfb4 005bd800 ffffffff ntdll_77b80000!RtlInitializeExceptionChain+0x63
0377fa40 00000000 7347bfb4 005bd800 00000000 ntdll_77b80000!RtlInitializeExceptionChain+0x36
打开windbg菜单“view”中的“local”、“calls”
可以看到CMap的m_nCount = 0n770036,放置了大约70w用户,调用CMap.SetAt()。难道SetAt性能不好?? 由于是前人的历史代码,我对CMap基本不熟悉,所以就抱着这个疑问写了个demo进行验证,果然,在CMap达到40w左右时,SetAt性能急剧下降,到70w左右插入可能需要10秒的时间。更换了std::map ,长期观察程序很稳定。
结论
在分析高cpu时有几个操作不对的地方,
1)没有让运维多导几个fulldump
2)CMap性能差真没想到,吃一堑长一智,看来都得用std::map 才行
后续的任务
1)全部门代码替换CMap为std::map