火焰图性能调优记

导语

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

相关文章

来自专栏微服务生态

由多线程内存溢出产生的实战分析

一日凌晨,手机疯狂报警,短信以摧枯拉朽之势瞬间以百条的速度到达,我在睡梦中被惊醒,看到短信的部分内容如下:

786
来自专栏数据和云

SQL执行计划 - 查询转换hint的介绍和使用技巧

? 冷菠 冷菠,资深DBA,著有《Oracle高性能自动化运维》,有近10年的数据库运维、团队管理以及培训经验。擅长数据库备份恢复、数据库性能诊断优化以及数据...

35211
来自专栏顶级程序员

Linux吃掉我的内存

在Windows下资源管理器查看内存使用的情况,如果使用率达到80%以上,再运行大程序就能感觉到系统不流畅了,因为在内存紧缺的情况下使用交换分区,频繁地从磁盘...

3125
来自专栏微信终端开发团队的专栏

微信 iOS SQLite 源码优化实践

本文将分享在 SQLite 源码上进行的多线程并发、I/O性能优化等,并介绍优化相关的 SQLite 原理。

2910
来自专栏魏艾斯博客www.vpsss.net

搬瓦工 snapshots 快照备份和还原 VPS 数据功能介绍

1424
来自专栏北京马哥教育

Linux内存被吃掉了,它去哪里了?

在Windows下资源管理器查看内存使用的情况,如果使用率达到80%以上,再运行大程序就能感觉到系统不流畅了,因为在内存紧缺的情况下使用交换分区,频繁地从磁盘上...

802
来自专栏IT技术精选文摘

从Java视角理解系统结构(一)CPU上下文切换

在高性能编程时,经常接触到多线程. 起初我们的理解是, 多个线程并行地执行总比单个线程要快, 就像多个人一起干活总比一个人干要快. 然而实际情况是, 多线程之间...

1839
来自专栏吴伟祥

Linux 系统核心组成 原

  指挥linux系统稳定运行的核心是linux内核。这个内核相当于linux系统的“大脑”,linux系统的就是在linux内核上发展起来的。linux高可用...

673
来自专栏云计算

虚拟机备份和恢复的六大最佳实践

虚拟机( virtual machine,简称 VM)的体系结构与传统的本地环境存在较大差异,因此需要不同的数据备份技术。基于此,本文将对虚拟机备份的一些最佳实...

3097
来自专栏我是攻城师

重新认识同步与异步,阻塞和非阻塞的概念

在实际的开发中,我们经常会听到同步,异步,阻塞,非阻塞这些编程概念,每次遇到的时候都会蒙圈,然后就各种查网上似是而非的资料,结果越查越迷糊,大部分文章都千篇一律...

772

扫码关注云+社区