CMap导致的性能问题分析记录

eumnq8

问题背景：
某天某服务预警一直提示某服务性能不足，cpu已满负荷。很是纳闷，这个服务是纯内存数据，没有io操作；而且都运行了快3个月了，怎么突然就性能不足了？

排查解决步骤：
步骤1
半夜从睡梦中被叫醒，先自己缕一缕思路（整个人都是懵的，基本缕不出思路），先解决线上问题， 让运维保存了一份fulldump，然后重启服务，线上正常，回去睡觉。
异常出现时需要哪些现场信息，比如日志、dump、cpu、内存状态……;因为平时有积累，比如cpu、内存信息主机是有程序在定时生成的；版本（svn、pdb、exe)是自动化编译自动保存的；……

步骤2
向运维取了当时的dump文件，向版本服务器获取了匹配的pdb、svn记录，获取了当时的日志、cpu、内存信息。使用windbg 打开dump，发现是一个64位dump。

步骤3
加载pdb，将64位dump切换到32位，然后打印所有线程。

0:000> .load wow64exts
0:000> !sw
Switched to 32bit mode
0:000:x86> ~*kv
  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

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 &>:perator[]+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:oWorkLoop+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 才行