使用CMap导致服务高CPU

某天某服务预警一直提示某服务性能不足,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位,然后打印所有线程。

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 &>::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”


image

可以看到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

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 217,734评论 6 505
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,931评论 3 394
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 164,133评论 0 354
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,532评论 1 293
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,585评论 6 392
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,462评论 1 302
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,262评论 3 418
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,153评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,587评论 1 314
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,792评论 3 336
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,919评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,635评论 5 345
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,237评论 3 329
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,855评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,983评论 1 269
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 48,048评论 3 370
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,864评论 2 354

推荐阅读更多精彩内容