CPU上涨100%的问题排查

最近修改了一个快一年没有发过特性的服务；修改只对深圳set生效；但是服务发布到三地后，三地的CPU分别从20%增长到40%或40%增长到80%；也就是CPU增长了100%；因为本次改动只对深圳有效，而其他两地的CPU也增长，那么可以确认是一年中其他修改导致了CPU的增长。

排查CPU增长情况的工具首先是TOP命令查看占用CPU最多的是哪几个进程，毫无疑问就是我的SPP服务的几个worker进程。于是进一步高手告诉我要用perf工具，perf工具可以看到是哪个函数哪个地方调用分别占用CPU的比例；所以菜鸟第一次开始学习perf工具；按照网友教程学样先用了/usr/local/tlinux/perf37/bin/perf record -e cpu-clock XXX （可执行程序）查看CPU是耗在哪个地方；发现CPU耗在SPP的几个进程但是并没有如网友例子里说的那样显示耗在哪个函数我这边是显示了一个地址，如图：



这样完全不知道耗在哪里，于是接着读教程发现有一个参数是-p 查看某个进程CPU消耗情况，于是用了这条指令：

/usr/local/tlinux/perf37/bin/perf record -g --call-graph -p pid

得到了结果：



发现CPU主要耗在pb里面的反射，打印函数里面；进一步想通过perf查看调用情况使用了参数-g --call-back

展开也并没有如教程中的示例那样，很顺利地看到了最终是哪个函数调用了这些pb相关的函数。

所以最后采用了比较无奈但是管用的方法，二分查找svn版本，定位导致CPU上涨的版本。居然只是因为把日志函数要打印的内容从一个普通的字符串变成了调用pb的Utf8DebugString；正是Utf8DebugString里面用到了pb 反射打印的函数导致了CPU的上涨。而很好奇的是并没有打印日志，日志的级别是DEBUG级别的为何会出现这样的问题呢？？研究了一下打印日志这个宏的定义，这个宏没有进行日志级别的判断直接将参数传给了打印日志的函数，所以这里会先调用Utf8DebugString生成所需的参数，此时再在打印的函数里面判断级别也是没用的了。而glog这个地方就不是，glog现在宏里面进行了日志级别的判断所以不会出现这样的问题。

终于经过两天找到了这个问题，不过还是有些疑惑的是为何我用perf -g --call-graph为何没有达到预期得到calling graph，求教高手给出解释。