火焰图性能调优记

导语

最近手头开发维护的一个辅助小工具经常接到投诉可用性问题, 于是抽时间定位了下, 一看吓一跳, 起初不起眼的一个组件的日志量直接翻了两个数量级。 这怎么吃得消 ! 幸好当时工具是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以内(符合期望)。

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

原创声明,本文系作者授权云+社区发表,未经许可,不得转载。

如有侵权,请联系 yunjia_community@tencent.com 删除。

编辑于

黄奕坤的专栏

1 篇文章1 人订阅

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏阮一峰的网络日志

程序员小测试:保守派 vs 自由派

最近,我在阅读 Steve Yegg 的文集《程序员的呐喊》。 ? 这是一本非常有趣的书,里面甚至包含了一个小测试(原文),区分一个程序员到底是保守派还是自由派...

2696
来自专栏SAP梦心的SAP分享

【SAP业务模式】之ICS(四):组织单元的配置

      SAP的ICS业务后台配置主要有以下几个配置点:       1、组织单元的配置(公司代码、销售组织、工厂、采购组织等);       2、主数据的...

20310
来自专栏java一日一条

13个不容错过的Java项目

GitHub可谓一座程序开发的大宝库,有些素材值得fork,有些则能帮助我们改进自有代码或者学习编程技能。无论如何,开发工作当中我们几乎不可能绕得开GitHub...

521
来自专栏张善友的专栏

Microsoft StreamInsight 构建物联网

最近关于“物联网”(IoT) 的争论有很多,而且理由都很充分。 Ericsson 的 CEO Hans Vestberg 预测到 2020 年将有 500 亿台...

1805
来自专栏腾讯Bugly的专栏

Luakit的前世今生

最近发布了一个跨平台的app开发框架Luakit。那怎么会想到做这样一个东西呢?

2194
来自专栏博岩Java大讲堂

Java虚拟机--Java发展史Java虚拟机

3167
来自专栏杨建荣的学习笔记

远程协助解决重建索引的危机问题 (r8笔记第80天)

最近在工作忙碌之余也帮几位网友查看了几个问题,有一个问题让我印象挺深,其实也可以分享出来作为一些参考,问题之外还是有一些值得借鉴的地方。 首先是在周末的一...

3224
来自专栏张善友的专栏

尝试用微博记录 SQL Server 2012开发者训练营笔记

花了2天时间参加微软的SQL Server 2012开发者训练营,全面的学习了SQL Server 2012上面的新特性,尝试使用微博做笔记。现在把它摘录到博客...

1829
来自专栏云计算

使用Apprenda和R分析应用程序工作负载数据

在权限范围内运行的访客应用程序的知识是平台即服务(PaaS)可以利用的最重要的数据来源之一。一个PaaS应该知道(译注:原文为know,此处应指可以获取并处理)...

2076
来自专栏SAP最佳业务实践

SAP最佳业务实践:按库存生产(145)-4分组件的生产订单处理

分组件的生产订单处理 1、MD04 CO40创建生产订单 日常的物料需求计划运行会为内部生产的零件创建计划订单。到达计划转换日期时,系统将计划订单转换为生产订单...

2054

扫码关注云+社区