首页
学习
活动
专区
工具
TVP
发布
社区首页 >专栏 >Strace 解决性能问题案例一则

Strace 解决性能问题案例一则

作者头像
用户1278550
发布2018-08-09 14:18:55
4310
发布2018-08-09 14:18:55
举报
文章被收录于专栏:idbaidba

前言

前面一篇文章说了因为公司同事在解决一个故障(性能问题)时利用到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研发的同学针对各自对应的环节进行排查。

  1. 数据库RT 问题的核心表现是延迟,也即正常情况下5-10ms左右即可同步完。出现问题时出现分钟级的延迟。开发同学第一反馈是处理a,b,c 三个逻辑查询db的耗时增加。DBA查看数据库监控 明显无异常,而且根据业务异常的监控数据,我们将数据库慢查询阈值从500ms调整为100ms,查看slow.log并未发现相应业务逻辑慢查询。陷入短暂的停滞,开发接着反馈不是还有一层proxy 吗?是不是网络问题,app到proxy网络问题?
  2. 网络,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工具直接定位出现问题的业务程序。

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

本文参与 腾讯云自媒体分享计划,分享自微信公众号。
原始发表:2018-05-19,如有侵权请联系 cloudcommunity@tencent.com 删除

本文分享自 微信公众号,前往查看

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

本文参与 腾讯云自媒体分享计划  ,欢迎热爱写作的你一起参与!

评论
登录后参与评论
0 条评论
热度
最新
推荐阅读
目录
  • 前言
  • 业务逻辑
  • 故障现象
  • 排查过程
    • 柳暗花明
    • 总结
    相关产品与服务
    消息队列 TDMQ
    消息队列 TDMQ (Tencent Distributed Message Queue)是腾讯基于 Apache Pulsar 自研的一个云原生消息中间件系列,其中包含兼容Pulsar、RabbitMQ、RocketMQ 等协议的消息队列子产品,得益于其底层计算与存储分离的架构,TDMQ 具备良好的弹性伸缩以及故障恢复能力。
    领券
    问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档