火焰图性能调优记

原创

黄奕坤

修改于 2017-08-17 10:01:01

2.4K0

修改于 2017-08-17 10:01:01

导语

最近手头开发维护的一个辅助小工具经常接到投诉可用性问题, 于是抽时间定位了下, 一看吓一跳, 起初不起眼的一个组件的日志量直接翻了两个数量级。这怎么吃得消 ! 幸好当时工具是Go写的,Go的周边工具集还是挺丰富和方便的,于是开启了调优之路。

背景

首先简介一下腾讯云CVM-CGW组件的日志查询工具，之前为了快速解决问题, 采用了straight forward的方案 : 实时从生产环节的机器进行尾随(tail -f)然后通过pipeline程序进行规则处理结构化 , 然后写入到后端DB进行持久化 , 然后另外有个前端进行查询，结构大概长这样。

今天的问题主角是上图的tailer程序, 它是日志收集和处理的核心部件。日志系统运营到一段时间之后, 发现随着业务的增长, 请求量呈攀升之势。特别是现网广州,上海,北京三个地域(国内用户太热情高涨了), 白天高峰期的时候会发现日志的写入速度跟不上采集的数据.现象是现网刚刚产生的日志数据,到写入DB存储之间的时间差越来越长。导致刚发生的请求需要等十几分钟才能查询到, 以及每小时后面几分钟的日志查询不到的, 现象如下图：

解决办法

tailer程序主要分日志采集, 日志解析处理,日志存储三个步骤。

肉眼调试法

简单打印调试分析了下, 排除了采集的性能问题.理论上这块的IO资源是绰绰有余的, 实践方法是把收集到的日志马上输出到标准输出, 然后和现网机器日志执行tail -f进行对比观察, 可以观察到两者几乎是同步输出的, 不存在拖后腿现象。

批量写入优化

然后是解析处理这个环节的排查, 排查效仿上一步骤, 把存储的步骤换成输出到标准输出观察, 观察了十来分钟发现基本和现网一致。

于是重点改进存储这块的性能, 采取的办法是把数据写入DB行为从逐行写入改为为批量写入。具体做法是把每行日志数据缓存下来, 使用LRU策略, 属于同一个请求的日志的行,都会缓存到同一个key, 检测到该请求的日志已经完了的时候,一次性把同一个请求的多行日志写入DB.大致逻辑是这样。

原有的处理逻辑:

handleLine(line) { // called line by line all the time
  struredLogLine = parseLine(line)
  saveDB(stcturedLogLine)
}

缓存策略后的处理逻辑:

handleLine(line) { // called line by line all the time
  struredLogLine = parseLine(line)
  struredLogStream = findLogStream(struredLogLine.key)
  if (struredLogStream.endOfRequest()) {
    batchSaveDB(struredLogStream)
  } else {
      struredLogStream.Add(struredLogLine)    
  }
}

具体代码戳这里

寻找瓶颈

优化了批量写入后很happy得部署运行, 跑了一段时间后,发现广州的效率的确得到提升, 然而上海地域由于还没扩容, 还是没达到预期效果, 每小时还是有接近十来分钟的间隔差距。这时候肉眼和经验派用不上用场了, 于是借助开源性能压测工具来查找瓶颈。

火焰图简介

之前在 dondonchen 同学了解到了火焰图这个工具, 它对程序的性能分析做了非常直观的可视化工作.感受下它的样子。戳这里可以感受它的交互。

简单介绍下怎么看这个图. 这里用的是CPU火焰图, 纵轴代表的是函数调用栈深度.越高代表调用栈越深,最顶层格子就是最后被调用的函数.。横轴是由一系列格子按字母排序的.每个格子代表一个行数调用。最底层的格子是入口函数,一般是main或者启动进程加载函数等。格子的宽度代表该函数执行的CPU时间占用比例.最后图的颜色默认是没什么含义的,可以当作色盲测试。更多原理和细节可以看Brendan Greg这篇pptt以及源码..ps,作者的blog是个学习linux系统实战知识的宝矿。

火焰图实践

原生火焰图生成工具使用起需要各种工具一起上, 研究了一圈最后选了uber开源的压测工具go-torch, 支持各种可视化图表. 使用起来非常方便.

只需要在import的地方加上_ "net/http/pprof"和程序入口加上两三行代码即可.

    go func() { log.Println(http.ListenAndServe("localhost:5001", nil))}()

然后启动tailer程序, 然后运行go-torch对程序进行无情的鞭策。

go-torch --time=20 --file "torch.svg"  --url http://localhost:5001

最后在当前目录生成了一个torch.svg文件, 在浏览器打开,即可调用栈火焰图。

从图中可以看到主要作业函数doTailFOverSSH所占用的比例大约是三分之一.这里右边的三分之二主要是sleep的系统调用,和tailer程序的主要干活负载进程无关. 这种svg格式的火焰图还带有交互功能, 鼠标点击doTailFOverSSH的格子,即可展开函数放大观察.

可以观察到doTailFOverSSH里面有一半时间阻塞在网络数据接收调度上runtime.selectgo, 所以这又进一步验证了采集端不够成瓶颈并且绰绰有余的肉眼观测现象. 另外占一半时间的Process函数做的就是读tail -f传过来的每一行日志,然后进行处理(解析和存储)ReadLine. 展开ReadLine进一步观测.

可以看到ReadLine里面的两大步骤解析和存储分别对应的是ParseLine和Save函数.可以看到改成批量后Save的比例已经只占用不到1/5的时间, 主要瓶颈在于ParseLine. 而ParseLine的调用栈发现MustCompile两座正则初始化大山. 于是猛然想到代码里面有类似于

outputRegExp = regexp.MustCompile(`cvm-cgw response:\s({.*})`)
leadRegExp = regexp.MustCompile(`\[\d{10}.\d{1,9}-\d{1,9}\]`)

这种日志格式固定,八百年不会改变的变量,不需要在每一行日志处理都进行Compile, 可以用全局变量进行提前初始化。另外一些变化较多但是量也有限的正则pattern也可以用缓存存起来避免重复初始化(MustCompile). 于是动手调整一把。

调整后ParseLine终于降下来了, 现在解析和存储占用时间比例相对。

而Process在doTailFOverSSH的整体占用时间也降下来了.还多出不少空闲。

最后总览全图可以看到主负载函数doTailFOverSSH也从原来的三分之一降到15.68%, 不到1/6.

结果

调整后程序再次上线运行,so far so good, 时间差距缩短到200ms以内(符合期望)。

目前可以轻松应付广州,上海,北京等大地域的高峰期请求.目测应该可以撑到业务翻翻.期待下次瓶颈的到来。

原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。

如有侵权，请联系 cloudcommunity@tencent.com 删除。

日志数据

原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。

如有侵权，请联系 cloudcommunity@tencent.com 删除。

日志数据

登录后参与评论

0 条评论

热度