Strace 解决性能问题案例一则

前言

前面一篇文章说了因为公司同事在解决一个故障(性能问题)时利用到strace，在学习strace工具的时候也查看《性能之巅》第十三章中，大神解决性能问题的思路和方法。本文将我遇到的故障的解决过程记录下来，前车之鉴。

业务逻辑

业务写入A表，通过canal监听binlog产生消息，应用接收消息经过一定逻辑(a,b,c)对消息进行三次校验(查询DB)并且聚合，然后写入B表。抽象的逻辑图示如下:

                    [a]  [A]--->[binlog]--->[b] ---> [B]                    [c]

业务访问db的逻辑架构为:

  [app] ---> [proxy] ---> [DB]

故障现象

4月16号开始，随着业务业务高峰我们的业务系统在同步数据时出现大量延迟。

从业务的监控层来看监控收集到的数据表示a,c逻辑访问db的时间增加了，整体耗时从5ms增加到150-200ms。看到这个监控，相信相当一部分人会认为业务请求DB层面出问题。

排查过程

当一个业务系统出现性能问题时，可能大部分的人会想到db/网络/IO 等是否有问题，是否变慢了？这个也是一个近乎正确的思路。为什么说近乎呢？因为这个排查链路还缺少核心环节，也即应用本身。接到开发同学的反馈，组织一批运维以及消息中间件的paas研发的同学针对各自对应的环节进行排查。

数据库RT 问题的核心表现是延迟，也即正常情况下5-10ms左右即可同步完。出现问题时出现分钟级的延迟。开发同学第一反馈是处理a,b,c 三个逻辑查询db的耗时增加。DBA查看数据库监控

明显无异常，而且根据业务异常的监控数据，我们将数据库慢查询阈值从500ms调整为100ms，查看slow.log并未发现相应业务逻辑慢查询。陷入短暂的停滞，开发接着反馈不是还有一层proxy 吗？是不是网络问题，app到proxy网络问题？
网络,IO 从监控上看网络并无明显丢包，而且运维同学将涉及问题的业务的服务器迁移到性能更好的机器上。其实还有一个同时访问相同proxy的其他业务逻辑并未出现延迟的情况，说明从侧门说明 app到proxy的并没有问题。

其实问题排查到这里已经停滞并且出现矛盾点:开发根据业务埋点的监控一直认为坚持访问db出现问题，而运维包括DBA的排查证明访问DB层面无问题，接下来2天的业务高峰时间点依然出现数据同步延迟。

我找开发同学一起排查，并且尝试着去了解出现问题的业务逻辑a,c,他们的逻辑大致相似，其中a的逻辑是

func a{  do_something  t1=now()  call get_xxx_from_db()  do_something  rt=now()-t1  ## 计算耗时时间，这里就是监控显示异常的时间}

其中get_xxx_from_db() 才是访问db的核心逻辑，而且该函数里面也有部分业务逻辑。排查基础服务性能陷入了僵局，能不能怀疑业务逻辑本身呢？现实告诉我是徒劳的，开发坚持自己的业务实现逻辑无任何问题。(因为一直跑的好好的，没有做任何发布变更，只是突然出现性能问题，这点也可以理解)，我提议能不能将监控访问db RT的埋点内置到 getxxxfrom_db()这样监控db的rt才能更准确, 因为开发要修改整体的逻辑无疾而终。

柳暗花明

经过对基础服务网络，服务器主机，db等一系列的排，运维同学都将怀疑的对象往业务层面集中，于是一个同事祭出了linux性能问题诊断神器- strace 分析工具

利用前面介绍的命令对出现性能问题的进程进行debug分析

strace -T -tt -s 100 -o tmp/strace.log -p $PID

获取的日志如下(删减部分内容)

10:51:49.814118 gettimeofday({1524192709, 814130}, NULL) = 0 <0.000009>
10:51:49.814266 write(4, "<158>2018-04-20 10:51:49 worker001 info[9185]: topic=log.xxx.xxxx_sync EAGAIN (Resource temporarily unavailable) <0.099912>
10:51:49.914265 write(4, "\n", 1)  = -1 EAGAIN (Resource temporarily unavailable) <0.100881>10:51:50.015378 gettimeofday({1524192710, 15413}, NULL) = 0 <0.000006>
10:51:50.015436 gettimeofday({1524192710, 15443}, NULL) = 0 <0.000004>
10:51:50.015595 sendto(38, "|\0\0\0\3/*master*/SELECT * FROM idx_update_time WHERE 1 and `order_no` = '20180420104827060300005' and `kdt_id` = '110'", 128, MSG_DONTWAIT, NULL, 0) = 128 <0.000023>
10:51:50.015655 poll([{fd=38, events=POLLIN|POLLERR|POLLHUP}], 1, 12000) = 1 ([{fd=38, revents=POLLIN}]) <0.000526>
10:51:50.016213 recvfrom(38, "\1\0\0\1\7I\0\0\2\3def\5db", 24, MSG_DONTWAIT, NULL, NULL) = 24 <0.000007>
10:51:50.016243 poll([{fd=38, events=POLLIN|POLLERR|POLLHUP}], 1, 12000) = 1 ([{fd=38, revents=POLLIN}]) <0.000006>
10:51:50.016262 recvfrom(38, "idx_update_time\25idx_update_time\2id\2id\f?\0\n\0\0\0\3\3B\0\0\0Q\0\0\3\3def\5xxx\25idx_update_time\25idx_update_time\6kdt_id\6kdt_id\f?\0\v\0\0\0\3)@\0\0\0U\0\0\4\3def\5xxx\25idx_update_time\25order_idx_upd", 193, MSG_DONTWAIT, NULL, NULL) = 193 <0.000005>
10:51:50.016282 poll([{fd=38, events=POLLIN|POLLERR|POLLHUP}], 1, 12000) = 1 ([{fd=38, revents=POLLIN}]) <0.000005>
10:51:50.016299 recvfrom(38, "ate_time\10order_no\10order_no\f-\0x\0\0\0\375\5@\0\0\0O\0\0\5\3def\5xxx\25idx_update_time\25idx_update_time\5state\5state\f?\0\4\0\0\0\1!@\0\0\0[\0\0\6\3def\5xxx\25idx_update_time\25idx_update_time\vupdate_time\v", 193, MSG_DONTWAIT, NULL, NULL) = 193 <0.000004>
10:51:50.016318 poll([{fd=38, events=POLLIN|POLLERR|POLLHUP}], 1, 12000) = 1 ([{fd=38, revents=POLLIN}]) <0.000005>
10:51:50.016335 recvfrom(38, "update_time\f?\0\v\0\0\0\3!@\0\0\0S\0\0\7\3def\5xxx\25idx_update_time\25idx_update_time\7shop_id\7shop_id\f?\0\v\0\0\0\3!\0\0\0\0W\0\0\10\3def\5oc318\25idx_update_time\25idx_update_time\tshop_type\tshop_type\f?\0\4", 193, MSG_DONTWAIT, NULL, NULL) = 193 <0.000005>
10:51:50.016353 poll([{fd=38, events=POLLIN|POLLERR|POLLHUP}], 1, 12000) = 1 ([{fd=38, revents=POLLIN}]) <0.000005>
10:51:50.016370 recvfrom(38, "\0\0\0\1!\0\0\0\0\5\0\0\t\376\0\0\2\0\5\0\0\n\376\0\0\2\0", 193, MSG_DONTWAIT, NULL, NULL) = 27 <0.000007>
10:51:50.016539 gettimeofday({1524192710, 16554}, NULL) = 0 <0.000009>

其中每行末尾 < >表示一次网络/系统调用耗费的时间，单位是秒。

从上面的日志我们可以看到write写log动作调用耗时0.1s，而poll/recvfrom(处理db请求)则小于1ms。显然整体的性能瓶颈阻塞在写rsyslog上。 局面变的豁然开朗。基于此开发同学在业务逻辑去掉业务层写入log部分，减少对rsyslog的调用，

至此,业务延迟问题完全消失。

总结

解决问题耗时久的两个原因是开发一再坚持自己业务逻辑的正确性，配合排查的人陷入这个思维里面，转而在基础设施上耗费过多精力。另外就是基础运维的同学没有一开始就使用strace工具直接定位出现问题的业务程序。

整体排查问题的过程也算是蛮曲折的。所谓"眼见为实"不一定是"真实"的，因为我们看到的可能是表象，监控呈现出来的数据本身也可能是错误，以此为基础的所有判断也是错误的。