CMap导致的性能问题分析记录
问题背景:某天某服务预警一直提示某服务性能不足,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
0Id: 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 RetAddrArgs 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: ) (CONV: cdecl)
0015f95c 75dd338a 7efde000 0015f9a8 77bb9902 kubsvr!__tmainCRTStartup+0xfd (FPO: ) (CONV: cdecl)
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
1Id: c2c.dfc Suspend: 0 Teb: 7ef9d000 Unfrozen
*** ERROR: Symbol file could not be found.Defaulted to export symbols for user32.dll -
ChildEBP RetAddrArgs 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: ) (CONV: thiscall)
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 RetAddrArgs to Child
0377f87c 001b3a7d 0addba3c 0377f898 0377f890 kubsvr!CMap<int,int,_tagPLAYER_LOGON_MINI,_tagPLAYER_LOGON_MINI &>::GetAssocAt+0x61 (FPO: ) (CONV: thiscall)
0377f8a8 001bad38 0addba3c 005a1a58 200d99a8 kubsvr!CMap<int,int,_tagPLAYER_LOGON_MINI,_tagPLAYER_LOGON_MINI &>::operator[]+0x1d (FPO: ) (CONV: thiscall)
0377f8c0 001b7a53 0addba3c 0377f8e0 798f5637 kubsvr!CMap<int,int,_tagPLAYER_LOGON_MINI,_tagPLAYER_LOGON_MINI &>::SetAt+0x18 (FPO: ) (CONV: thiscall)
0377f920 001cfc90 1c8d1540 2008cb20 00593ee8 kubsvr!CSockServer::OnPlayerLogon+0xb3 (FPO: ) (CONV: thiscall)
0377f950 001d1904 1c8d1540 2008cb20 005a1a60 kubsvr!CSockServer::OnRequest+0x660 (FPO: ) (CONV: thiscall)
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]