今天线上的应用出问题了。
问题现象是
待渲染的页面一共要请求两个接口。这两个接口一直在请求,基本上要一分钟多响应完成,但完成并不是正常显示,而是返回500的错误服务器错误。 |
听到PM反馈问题后,经验主意上身,二话不说,上手开始分析。
第一步从线上服务器的日志开始入手。在线上日志查看时发现日志文件中最新的内容并不是附近的时间,而是一个小时前 -- 后续的日志都没有输出到文件中。
发现这个现象后,感觉日志输出不了,可能是和磁盘空间有关, 使用 df 命令开始查看空间。
果然,Tomcat 所在的目录,磁盘使用已经达到了100%。再切换回 Tomcat 日志目录发现大量的日志文件,果断把前面一些旧的已经数据分析统计过的删除。应用开始正常。
此时以为已经解决了问题,在群里和相关同学说是因为磁盘满导致的,一切OK。
中午吃个饭的时间,应用又出问题了,还是老样子。心想刚清的磁盘,空间还有一些,就开始使用上一篇刚写过的 jstack,打出 stackTrace 之后,分析内容中的Tomcat线程工作情况,又隔一段时间再打一个互相对比,自己感觉该比的都比了,也没发现任何有阻塞或者死锁的情况,此时应用的情况是偶尔一次页面会渲染成功,但也是比较慢的,大部分时候都不成功。
以前遇到过一次页面渲染慢是因为后台存放到云上的文件在保存完之后,没有进行 close 操作,把连接点满了,导致后面的请求都超时,当时通过 jstack 发现了问题之后快速解决了问题。所以这一次因循老路,还按这个思路来分析。
线上服务是部署在四台机器上,还分析了四台机器上的日志,也没看到请求的信息到达过其他机器上,所以一直在之前磁盘满的那一台机器上分析。
此时 QA 同学告知,另外三台机器上的日志一直没有刷出来,很长时间了。这时才想到可能是另外三台机器的磁盘空间也满了,日志输出不出来,在请求分配到这些节点上时分导致页面渲染不成功,而如果请求到达了第一台删除过的机器上,页面会渲染。
把另外三台机器的磁盘也清理了一下,果然,应用可能正常且快速的响应了。
这个问题分析时,在应用页面渲染慢时,分析了第一台机器的磁盘问题,之后就一根筋的顺着性能响应这条路去分析了,一会 jstack, 一会看下 GC 的执行是否正常 ...
忘了请求会分发到另外三台机器上,也没有在清理第一台机器磁盘时顺便上去看一下。
真的是手里拿着锤子,眼里就只能看到钉子。 甚至有些内容,即使和过往经验有类似的地方,也不见得就一定是同样的问题。有时候真需要放下锤子仔细看看,不能埋头就上啊。
想起之前暗时间的作者刘未鹏写过一次这样的经历:
说当时和他老婆一起到银行取钱。走到银行门前,发现需要刷卡才能进去,刷了下银行卡进去了。取完钱出来,未鹏拿了一张不是银行卡的普通卡,刷了一次也把门打开了,这时他认定是这门锁有问题,只有刷个卡就能进,不停的刷了好几张卡。
这时他老婆提醒道:万一是这门坏了呢,可能都不用卡。
未鹏伸手一推,门开了。
未鹏在写这个经历时说,有时候我们容易形成思维定势,更愿意从自己熟悉的角度去考虑问题,而忽视本来已经暴露出的现象。
有些时候,遇到问题时,放下手里的锤子,站远些看一看,可能会有新的认识。软件开发中还有一条著名的橡皮鸭法则,就是在陷入自己的思路时,向放在桌上的橡皮鸭讲一讲,可能在讲的过程中自己就明白了。不套用经验,多搜集信息,再分析,而不陷入思维定势中,也许才是解决问题的好方法。
【本文为51CTO专栏作者“侯树成”的原创稿件,转载请通过作者微信公众号『Tomcat那些事儿』获取授权】