前往小程序,Get更优阅读体验!
立即前往
首页
学习
活动
专区
工具
TVP
发布
社区首页 >专栏 >程序这么慢罪魁祸首竟是它

程序这么慢罪魁祸首竟是它

作者头像
用户1278550
发布2020-08-12 09:37:40
5840
发布2020-08-12 09:37:40
举报
文章被收录于专栏:idba
一、问题背景:

最近几天我们几位同事一起在做业务压测,TPS始终上不去,始终在100上下,平均响应时间也在5、6秒左右,性能差得可想而知,但是数据库层压测期间所有的SQL平均响应时间均在30ms以下,CPU使用率也才达到40%而已,RDS整体性能并没有达到瓶颈。

由于是PHP程序,没法用现有的压测平台进行全链路压测跟踪到具体每一步的耗时。在经历了各种linux调优、PHP参数调优以后,效果仍然没有起色,气氛一度陷入尴尬。

二、phptrace简介

其实利用之前文章《MySQL DBA如何利用strace/pstack/gdb来定位问题》中的提到的strace也可以跟踪到某个线程的全部调用情况,但是同事推荐了另外一个项目:phptrace,可以专门针对PHP程序做链路追踪,效果跟strace类似。

项目地址如下:https://github.com/Qihoo360/phptrace

它可以跟踪PHP在运行时的函数调用、请求信息、执行流程,并且提供有过滤器、统计信息、当前状态等实用功能。在任何环境下,它都能很好的定位阻塞问题以及在高负载下Debug,尤其是线上生产环境。

具有以下特性:

  • 低开销,在只加载模块不开启Trace功能时对性能影响极低
  • 稳定性,已经稳定运行在Qihoo 360线上服务中,并针对主流框架进行测试
  • 易用性,对于未安装trace扩展的环境,也能够追踪运行状态

你可以利用如下方式来跟踪PHP程序

代码语言:javascript
复制
$ phptrace -p 3600
[pid 3600]    > Me->run() called at [example.php:57]
[pid 3600]        > Me->say("good night") called at [example.php:33]
[pid 3600]        < Me->say("good night") = NULL called at [example.php:33] ~ 0.000s 0.000s
[pid 3600]        > Me->sleep() called at [example.php:34]
[pid 3600]            > Me->say("sleeping...") called at [example.php:27]
[pid 3600]            < Me->say("sleeping...") = NULL called at [example.php:27] ~ 0.000s 0.000s
[pid 3600]            > sleep(2) called at [example.php:28]
[pid 3600]            < sleep(2) = 0 called at [example.php:28] ~ 2.000s 2.000s
[pid 3600]        < Me->sleep() = NULL called at [example.php:34] ~ 2.000s 0.000s
[pid 3600]        > Me->say("wake up") called at [example.php:35]
[pid 3600]        < Me->say("wake up") = NULL called at [example.php:35] ~ 0.000s 0.000s
[pid 3600]    < Me->run() = NULL called at [example.php:57] ~ 2.000s 0.000s

你也可以根据函数名或者url进行过滤

代码语言:javascript
复制
$ phptrace -p 3600 -f type=class,content=Me
[pid 3600]> Me->run() called at [example.php:57]
[pid 3600]> Me->say("good night") called at [example.php:33]
[pid 3600]< Me->say("good night") = NULL called at [example.php:33] ~ 0.000s 0.000s
[pid 3600]> Me->sleep() called at [example.php:34]
[pid 3600]> Me->say("sleeping...") called at [example.php:27]
[pid 3600]< Me->say("sleeping...") = NULL called at [example.php:27] ~ 0.000s 0.000s
[pid 3600]< Me->sleep() = NULL called at [example.php:34] ~ 2.000s 2.000s
[pid 3600]> Me->say("wake up") called at [example.php:35]
[pid 3600]< Me->say("wake up") = NULL called at [example.php:35] ~ 0.000s 0.000s
[pid 3600]< Me->run() = NULL called at [example.php:57] ~ 2.001s 0.000s
三、跟踪分析

在压测期间,我们利用phptrace做了跟踪,通过阅读trace日志,发现所有的调用时间基本上集中在了一个函数上,而其他部分消耗时间都很短。

代码语言:javascript
复制
[pid 22745]        < file_put_contents("/var/www/cp-activity/activity/da"..., "2020-07-17 04:35:28 front_money_"..., 8) = 254 called at [/var/www/cp-activity/activity/framework/class/service/cache/fcache.class.php:140] ~ 1.338s 1.338s

经过仔细勘察,这个file_put_contents函数的作用其实就是往nas上写日志,看到这里真的是有点内伤的感觉,写本地磁盘、写ES难道不香吗,为啥想不开写nas呢???

基于上述判断,我们在其中一台机器上注释掉了该函数的调用,然后再次做了压测(10000并发情况),压测期间监控到alive线程基本上保持在10左右,总的TPS峰值达到了接近400左右,这还是在只修改了一台的情况下的结果,相信如果6台应用全部注释掉该方法,TPS应该能够上升一个数量级(待继续验证)。

四、总结反思
  • 进展到这里,问题基本上可以说非常明确了,只需要做进一步验证即可
  • 那么如何来解决这个写日志慢的问题呢?最简单也是最稳妥的办法还是写本地文件,然后再通过ELK方法写入到ES做聚合统计以及日志查询等
  • 再牛逼的泥工也需要一把水平尺来砌墙,所以我们要学会利用工具来帮助我们进行链路跟踪,有助于确定根因,例如stracephptraceperf等工具
本文参与 腾讯云自媒体同步曝光计划,分享自微信公众号。
原始发表:2020-08-10,如有侵权请联系 cloudcommunity@tencent.com 删除

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

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

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

评论
登录后参与评论
0 条评论
热度
最新
推荐阅读
目录
  • 一、问题背景:
  • 二、phptrace简介
  • 三、跟踪分析
  • 四、总结反思
相关产品与服务
云数据库 MySQL
腾讯云数据库 MySQL(TencentDB for MySQL)为用户提供安全可靠,性能卓越、易于维护的企业级云数据库服务。其具备6大企业级特性,包括企业级定制内核、企业级高可用、企业级高可靠、企业级安全、企业级扩展以及企业级智能运维。通过使用腾讯云数据库 MySQL,可实现分钟级别的数据库部署、弹性扩展以及全自动化的运维管理,不仅经济实惠,而且稳定可靠,易于运维。
领券
问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档