| title | date |
|---|---|
记一次Bug排查（Spider） |
2017/02/21 14:47:11 |
Spider是基于Express框架结合socket.io（现已切换为ws）和Echarts2实现的即时性能监视工具。整体结构为前后端分离，通过express的static中间件来处理静态请求，Express本身则处理api请求。
用法上，只需要按照指定的格式post数据给Spider，那么当请求Spider展示时，将会自动将数据展示为图表。
项目地址：http://trgit2/backend_framework/spider
展示地址：http://developer.newegg.org/spider
Spider可以提供一段时间（最大30分钟）内特定操作的消耗时间统计图（散点图）。大概展示效果如下图：
该项目从15年3月发布，由于用户量较少，一直稳定运行。
近期，MPS团队使用它来监控业务请求各个阶段的耗时情况，用于定位性能问题。此时，问题出现，spider运行一段时间（10~30分钟）后将会消耗大量服务器内存，导致内存不足而崩溃。
此时，用户使用场景：
- 在c#程序中，收集各种类型操作的耗时数据，累计起来。
- 每隔1s将数据提交到spider后端。
- 打开监控页面，查看数据（可能会有多个监控端）
spider处理过程：
- 接收到请求数据之后，将数据进行处理，并存入内存；
- 如果发现有监控端运行，那么推送数据给监控端（每次收到请求数据都会触发一次推送）
- 监控端根据最新的数据绘制图表展示。
因为JS的闭包容易内存泄露，首先怀疑代码写法问题。
**验证：**经过仔细排查代码，并对有可能有泄露代码进行改写
**结果：**问题未解决，未缓解
由于客户端提交的数据是直接写入内存的，而刚好又是消耗内存，那么开始怀疑缓存数据的代码。
**验证：**重写了数据缓存代码（参考正常运行的缓存代码实现）
**结果：**问题未解决，未缓解
此时，把最常见的情况都验证了，无解。思绪中断，接着做了哪些事情呢？
- 查找有可能导致JS内存泄露的情况，一一确认。
- 安装JS的内存分析工具（条件苛刻，未安装成功）。
- 安装Node程序的监控包，进行大量本地测试（很难复现问题）。
- 此时陷入困境...
- 再次想方设法安装内存分析工具，在本地测试，未果（问题很难复现）。
- 线上测试，问题依旧，根据结果，发现大量字符串占用内存，导致内存不足。
- 分析代码，查找该字符串初现的位置。
- 开始新的猜测
###猜想3：socket.io内存泄露
从内存分析的结果来看，大量字符串占用了内存，该格式的字符串，是由socket.io分发到客户端的时候产生的。所以怀疑到了socket.io头上。
通过查资料，发现socket.io确实有内存泄露的前科，一度认为这就是原因。
**验证1：**升级socket.io到最新的版本
**结果1：**有一定的好转，但不明显（坚持的时间稍微久一点，内存偶尔能回收一下）
再次各种查资料，发现有提到强制node使用gc回收，可以处理非托管内存。
**验证2：**增加gc回收代码，定时执行
**结果2：**基本上看起来无效，和结果1并没有太大区别
此时，有点穷途末路了。问题还在，继续探索
**验证3：**考虑到项目本身不大，重新使用了一个新的WebSocket(ws)包来推送数据
**结果3：**有明显好转，坚持的时间更长了（一度认为解决了问题）
可是好景不长，较长时间（几小时）后，问题再次出现
此时未直接验证，切换到业界一个比较流行的缓存库(lru-cache)。
这个猜想，算来后面总结的。一开始怀疑过这个问题，想过降低推送频率，但没有实施。经@James分析也猜测问题可能会出现在此处，因为大量字符串占用内存，也满足这个猜想。想到就做：
**验证：**将每次收到数据触发推送，修改为间隔一定时间（5s）推送一次。
**结果：**内存趋于平稳，及时性在接收范围内。
至此，问题基本上算是解决了。
此次问题，是由于服务端推送数据量较大，而且频率较高，上次推送未完成，就触发了下一次推送。导致消息阻塞，越积越多，所以就耗尽内存而亡。
之后，spider运行一天多之后死掉过一次，但没有看到具体原因。重启之后，稳定运行至今。暂时性怀疑中途死掉的一次为意外（或者瞬时流量大增）
从发现该问题，到解决该问题，耗时大概在一周。虽然期间还处理了其他任务，但整体来说解决这个问题还是消耗了很长的时间。
究其原因：
- 对TCP底层传输数据不太熟悉
- 没有处理大量数据高频率推送的经验
- 发布时，只对程序进行了简单的本地测试，没有进行压力测试。
学到了什么：
- 对代码负责，以更严谨的态度来对待，减少出问题
- 对WebSocket的负载和相关设计有了更深刻的理解
- 多做一些测试，更稳定的保持代码质量