工欲性能调优,必先利其器(1)

最近在排查 TiDB 性能问题的时候,通过工具发现了一些问题,觉得有必要记录一下,让自己继续深刻的去理解相关工具的使用,也同时让同学们对类似问题的时候别再踩坑。

使用 iostat 定位磁盘问题

在一个性能测试集群,我们选择了 AWS c3.4xlarge 机型,主要是为了在一台机器的两块盘上面分别跑 TiKV。在测试一段时间之后,我们发现有一台 TiKV 响应很慢,但是 RocksDB 并没有相关的 Stall 日志,而且慢查询也没有。

于是我登上 AWS 机器,使用 iostat -d -x -m 5 命令查看,得到如下输出:

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
xvdb              8.00 12898.00  543.00  579.00    31.66    70.15   185.84    51.93   54.39    7.03   98.79   0.60  66.80
xvdc              0.00     0.00  206.00 1190.00    10.58   148.62   233.56   106.67   70.90   13.83   80.78   0.56  78.40

上面发现,两个盘 xvdb 和 xvdc 在 wrqm/s 上面差距太大,当然后面一些指标也有明显的差距,这里就不在详细的解释 iostat 的输出。只是需要注意,大家通常将目光注意到 util 上面,但有时候光有 util 是反应不了问题的。

于是我继续用 fio 进行测试,fio -ioengine=libaio -bs=4k -direct=1 -thread -rw=write -size=10G -filename=test -name="PingCAP max throughput" -iodepth=4 -runtime=60,发现两个盘的写入有 2 倍的差距,xvdb 的写入竟然只有不到 70 MB,而 xvdc 有 150 MB,所以自然两个 TiKV 一个快,一个慢了。

对于磁盘来说,通常我们使用的就是 iostat 来进行排查,另外也可以考虑使用 pidstat,iotop 等工具。

使用 perf 定位性能问题

RC3 最重要的一个功能就是引入 gRPC,但这个对于 rust 来说难度太大。最开始,我们使用的是 rust-grpc 库,但这个库并没有经过生产环境的验证,我们还是胆大的引入了,只是事后证明,这个冒险的决定还是傻逼了,一些试用的用户跟我们反映 TiKV 时不时 coredump,所以我们立刻决定直接封装 c gRPC。因为现在大部分语言 gRPC 实现都是基于 c gRPC 的,所以我们完全不用担心这个库的稳定性。

在第一个版本的实现中,我们发现,rust 封装的 c gRPC 比 C Plus Plus 的版本差了几倍的性能,于是我用 perf stat 来分别跑 C Plus Plus 和 rust 的benchmark,得到类似如下的输出:

Performance counter stats for 'python2.7 tools/run_tests/run_performance_tests.py -r generic_async_streaming_ping_pong -l c++':

     216989.551636 task-clock (msec)         #    2.004 CPUs utilized
         3,659,896 context-switches          #    0.017 M/sec
             5,078 cpu-migrations            #    0.023 K/sec
         4,104,965 page-faults               #    0.019 M/sec
   729,530,805,665 cycles                    #    3.362 GHz
   <not supported> stalled-cycles-frontend
   <not supported> stalled-cycles-backend
   557,766,492,733 instructions              #    0.76  insns per cycle
   121,205,705,283 branches                  #  558.579 M/sec
     3,095,509,087 branch-misses             #    2.55% of all branches

     108.267282719 seconds time elapsed

上面是 C Plus Plus 的结果,然后在 rust 测试的时候,我们发现 context-switch 是 C Plus Plus 的 10 倍,也就是我们进行了太多次的线程切换。刚好我们第一个版本的实现是用 rust futures 的 park 和 unpark task 机制,不停的在 gRPC 自己的 Event Loop 线程和逻辑线程之前切换,但 C Plus Plus 则是直接在一个 Event Loop 线程处理的。于是我们立刻改成类似 C Plus Plus 架构,没有了 task 的开销,然后性能一下子跟 C Plus Plus 的不相伯仲了。

当然,perf 能做到的还远远不仅于此,我们通常会使用火焰图工具,关于火焰图,网上已经有太多的介绍,我们也通过它来发现了很多性能问题,这个后面可以专门来说一下。

使用 strace 动态追踪

因为我们有一个记录线程 CPU 的统计,通常在 Grafana 展示的时候都是按照线程名字来 group 的,并没有按照线程 ID。但我们也可以强制发送 SIGUSR1 信号给 TiKV 在 log 里面 dump 相关的统计信息。在测试 TiKV 的时候,我发现 pd worker 这个 thread 出现了很多不同线程 ID 的 label,也就是说,这个线程在不停的创建和删除。

要动态追踪到这个情况,使用 strace -f 是一个不错的方式,我同时观察 TiKV 自己的输出 log,发现当 TiKV 在处理分裂逻辑,给 PD worker 发送 message 的时候,就有一个新的线程创建出来。然后在查找对应的代码,发现我们每次在发消息的时候都创建了一个 tokio-timer,而这个每次都会新创建一个线程。

有时候,也可以使用 strace -c 来动态的追踪一段时间的系统调用。在第一版本的 rust gRPC 中,我们为了解决 future task 导致的频繁线程切换,使用 gRPC 自己的 alarm 来唤醒 Event Loop,但发现这种实现会产生大量的信号调用,因为 gRPC 的 alarm 会发送一个实时信号用来唤醒 epoll,后面通过火焰图也发现了 Event Loop 很多 CPU 消耗在 alarm 这边,所以也在开始改进。

这里需要注意,strace 对性能影响比较大,但对于内部性能测试影响还不大,不到万不得已,不建议长时间用于生产环境。

小结

上面仅仅是三个最近用工具发现的问题,当然还远远不止于此,后续也会慢慢补上。其实对于性能调优来说,工具只是一个辅助工具,最重要的是要有一颗对问题敏锐的心,不然即使工具发现了问题,因为不敏锐直接就忽略了。我之前就是不敏锐栽过太多的坑,所以现在为了刻意提升自己这块的能力,直接给自己下了死规定,就是怀疑一切能能怀疑的东西,认为所有东西都是有问题的。即使真的是正常的,也需要找到充足的理由去验证。

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

推荐阅读更多精彩内容