某天某服务预警一直提示某服务性能不足,cpu已满负荷。很是纳闷,这个服务是纯内存数据,没有io操作;而且都运行了快3个月了,怎么突然就性能不足了?
步骤1
半夜从睡梦中被叫醒,先自己缕一缕思路(整个人都是懵的,基本缕不出思路),先解决线上问题, 让运维保存了一份fulldump,然后重启服务,线上正常,回去睡觉。
异常出现时需要哪些现场信息,比如日志、dump、cpu、内存状态……;因为平时有积累,比如cpu、内存信息主机是有程序在定时生成的;版本(svn、pdb、exe)是自动化编译自动保存的;……
步骤2
向运维取了当时的dump文件(提取码: q5kx),向版本服务器获取了匹配的pdb、svn记录,获取了当时的日志、cpu、内存信息。使用windbg 打开dump,发现是一个64位dump,看来运维偷懒了,没有用之前说的命令行方式获取dump,而是使用任务管理器获取dump。
步骤3
加载pdb,将64位dump切换到32位,然后打印所有线程。
1 2 3 4 | 0:000> .load wow64exts 0:000> !sw Switched to 32bit mode 0:000:x86> ~*kv |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 | 0 Id: c2c.a4c Suspend: 0 Teb: 7efdb000 Unfrozen *** ERROR: Symbol file could not be found. Defaulted to export symbols for ntdll.dll - *** ERROR: Symbol file could not be found. Defaulted to export symbols for kernel32.dll - ChildEBP RetAddr Args to Child WARNING: Stack unwind information not available. Following frames may be wrong. 0015f260 75dd1194 000000e4 ffffffff 00000000 ntdll_77b80000!NtWaitForSingleObject+0x15 0015f278 75dd1148 000000e4 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0x43 *** ERROR: Symbol file could not be found. Defaulted to export symbols for sechost.dll - 0015f28c 77717be6 000000e4 ffffffff e15460f0 kernel32!WaitForSingleObject+0x12 0015f330 77718040 0059f808 000000e4 00000000 sechost!I_ScIsSecurityProcess+0x8a7 0015f3e4 77718553 0015f3f8 00000000 00000001 sechost!RegisterServiceCtrlHandlerExA+0x27a *** WARNING: Unable to verify checksum for kubsvr.exe 0015f3fc 001dd97b 0015f408 0015f438 001dd850 sechost!StartServiceCtrlDispatcherA+0x68 0015f418 001c76ad 7aed560b 0002001d 00000000 kubsvr!CNTService::StartServiceA+0x2b 0015f91c 001de205 00000001 005938e0 0058cc28 kubsvr!main+0x28d (FPO: [Non-Fpo]) (CONV: cdecl) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\kubsvr\main.cpp @ 165] 0015f95c 75dd338a 7efde000 0015f9a8 77bb9902 kubsvr!__tmainCRTStartup+0xfd (FPO: [Non-Fpo]) (CONV: cdecl) [f:\dd\vctools\crt\crtw32\dllstuff\crtexe.c @ 626] 0015f968 77bb9902 7efde000 ec718eae 00000000 kernel32!BaseThreadInitThunk+0x12 0015f9a8 77bb98d5 001de26d 7efde000 ffffffff ntdll_77b80000!RtlInitializeExceptionChain+0x63 0015f9c0 00000000 001de26d 7efde000 00000000 ntdll_77b80000!RtlInitializeExceptionChain+0x36 1 Id: c2c.dfc Suspend: 0 Teb: 7ef9d000 Unfrozen *** ERROR: Symbol file could not be found. Defaulted to export symbols for user32.dll - ChildEBP RetAddr Args to Child WARNING: Stack unwind information not available. Following frames may be wrong. 0265fef4 001cf23b 0265ff0c 00000000 00000000 user32!DispatchMessageW+0x5c 0265ff2c 001dd91d 00000000 005a6b00 00000000 kubsvr!CMainService::Run+0x4b (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\kubsvr\service.cpp @ 68] 0265ff4c 777175a8 00000001 005a6b10 00000000 kubsvr!CNTService::ServiceMain+0xcd 0265ff60 75dd338a 005a6b00 0265ffac 77bb9902 sechost!I_ScIsSecurityProcess+0x269 0265ff6c 77bb9902 005a6b00 ee0188aa 00000000 kernel32!BaseThreadInitThunk+0x12 0265ffac 77bb98d5 77717587 005a6b00 ffffffff ntdll_77b80000!RtlInitializeExceptionChain+0x63 0265ffc4 00000000 77717587 005a6b00 00000000 ntdll_77b80000!RtlInitializeExceptionChain+0x36 ........................ ........................ |
步骤4
分析各个线程。从线程中可以看到总共有24个线程,其中有部分能看到代码,有部分不能看到代码。我们只能先从有代码的线程开始分析,因为这部分线程才是自己程序的主要处理模块。
可以看到大多线程都在处理 CSockServer::OnPlayerLogon 函数,查看对应的代码,理了下大概逻辑:服务程序使用8个线程接收用户登陆请求,并将用户信息保存在一个全局CMap中,CMay的key是用户id,value是一个类。这个dump线程反应出来的就是当时在处理很多用户的登陆信息,没有什么异常点啊???? 当时就觉的碰到坎了,认为导的dump可能不是引起cpu高时的运行栈, 后悔应该让运维多导几个dump,通过比较应该找的到高cpu时线程运行栈。
暂时没辙就打开看下当时的参数信息,慢慢的就看到了CMap的大小
切换到9号线程
~9s
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 | 0: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)没有让运维多导几个fulldump
3)CMap性能差真没想到,吃一堑长一智,看来都得用std::map 才行
后续的任务
1)写了个工具给运维可以正确导32位进程dump
2)全部门代码替换CMap为std::map