NexusPHP数据库锁表备份导致tracker数据统计异常bug分析

杯杯杯杯具 2020-11-19 PM 38℃ 0条

Screenshot_20201119_141513.png

一个有点奇妙的分析过程,感觉有点意思,记录一下(x

事情起因

  1. 去年x月北洋园开始每日凌晨3点(GMT+8)全量备份数据库及当月的图片(图片是按月分的文件夹),备份数据库使用的mysqldump,而且NexusPHP用了一大堆MyISAM所以锁表情况很严重,所以凌晨3点左右会出现一段时间服务不可用。(划重点一会儿要考)
  2. 11月4日用户A因上传超速被封禁,加入临时群要求限速后解封。
  3. 11月10日用户A再次因被封禁加群,并表示已经按要求限速,然而在封禁记录中显示上传速度达到了423.14Mib/s,但用户表示自己只用了1Gbps的盒子,并怀疑是tracker错误。

在之前双tracker在不同Tier中时我们倒是经常接到transmission乱报数据的issue,不过在改为同Tier双tracker后这种情况就基本没再发生过了,而且用户用的客户端是deluge(尽管自己改了announce间隔),因此确实不太应该发生这种汇报错误的情况。

扑朔迷离

接到issue后自然是到服务器上dump了用户A超速的种子的announce日志,然而导出的数据却让我十分意外——上传数据(uploaded)是很平缓增长的,event的值也十分正常。

重新看了看封禁时间,3点22分在announce日志中看到上传量是962.4GiB,而两分钟前的上传量是959.1GiB,2分钟3.3GiB的流量根本达不到封禁的阈值(100MiB/s)。

这时发现3点20分的announce返回的并不是HTTP200,而是HTTP502,看了一下HTTP502最初出现于3点00分,应该是由于3点的备份导致的。但等到数据库恢复时,tracker应该会记录2点58分-3点22分的数据,并用整体的上传量/整体的时间间隔来计算速度,而不会像现在这样直接计算错误并封禁,这就让我十分迷惑了,难道是tracker的逻辑问题?

意外发现+个人猜测

在不知道怎么解决时,尝试了一下把3点22分的962.4GiB数据减去超速日志中记录的区间内数据46.3GiB,以期找到这个区间的起点。在announce日志中搜索了一番,找到了3点01分时提交的916.1GiB,意外发现这个announce返回的HTTP返回码是504而非502,难道php接受了这个请求并正常处理了?但是这个时候MySQL应该无法工作才对,这次请求究竟发生了什么导致最后的错误。

此时脑中突然有了一个大胆的猜测,难道这个请求恰好在数据库可以被连接时(可能是两个表备份的中间?)成功连接了,然后就阻塞在了等待锁释放的某个SQL Query上,这个阻塞一直阻塞到了3点20分以后数据库被全部备份完成。PHP脚本继续运行,运行到了更新peers和snatched表时使用了当前时间(3点20分)而非脚本刚刚运行时的时间(3点01分),因此系统记录了3点20分上传量为916.1GiB,而3点22分tracker收到了一个962.4GiB的汇报,自然是秒封了。

第一时间,我是想否定我的这个思路的,因为我之前在PHP的设置中设置了单页的超时,一个PHP脚本怎么可能运行20分钟还不被kill。但在查了max_execution_timeset_time_limit解释后,这个猜测似乎有了一些可能性。

set_time_limit()函数和配置指令max_execution_time只影响脚本本身执行的时间。任何发生在诸如使用system()的系统调用,流操作,数据库操作等的脚本执行的最大时间不包括其中,当该脚本已运行。在测量时间是实值的Windows中,情况就不是如此了。

因此目前我个人对这个问题的解释也就是上面的那个猜测了,在有了这个备份之后从来没有出现过这种情况,不知道这个用户是幸运还是不幸(笑

后续改进(TODO)

  • 在announce.php开头就把时间固定下来,去掉后面的所有获取当前时间的操作
  • 在备份前关闭php-fpm.service,进一步避免数据脏读脏写
  • 优化备份,或许可以尝试一下XtraBackup等第三方备份工具?
标签: PHP, NexusPHP, 北洋园

非特殊说明,本博所有文章均为博主原创。

评论啦~