likes
comments
collection
share

Troubleshooting系列-评论管理台接口超时问题定位分析

作者站长头像
站长
· 阅读数 8

1. 问题现象

有一天下午运营反馈管理台评论外放接口操作老是超时,处理不成功。

2. 问题定位分析过程

2.1 收集信息

出现问题后首先查看PINPOINT监控,发现那天下午有很多管理台接口超时,超时接口大部分都是如下

update comment set xxx=?

然后在ELK上搜索相关容器日志,发现有很多数据库报错日志,报错信息如下

RecoverableDataAccessException ### Error update database ...

从上面两个地方可以看出可能是数据库存在问题,查看数据库可能存在问题。 查看对应数据库监控,发现流量和IO基本正常,数据库连接数也正常。 接着查看是否是存在大的事务或者锁表

// 检索InnoDB存储引擎中当前活动事务的信息,并按照它们的开始时间进行排序。
SELECT 
    trX_id,
    trx_state,
    trx_started,
    trx_weight,
    trx_mysql_thread_id,
    trx_query,
    trx_operation_state
FROM
    information_schema.innodb_trX
ORDER BY
    trX_started DESC;
// 发现两个活跃事务,一个trx_started是下午 16:19 没有对应的sql trx_mysql_thread_id为1
// 另外一个trx_started是 17:56 对应的sql update comment_a xxx trx_mysql_thread_id为2

//继续使用sql查询InnoDB存储引擎中的锁等待情况,以便了解哪些事务正在被阻塞以及它们正在等待的资源

SELECT r.trx_id AS waiting_trx_id, r.trx_mysql_thread_id AS waiting_thread, LEFT(r.trx_query, 30) AS waiting_query,
       b.trx_id AS blocking_trx_id, b.trx_mysql_thread_id AS blocking_thread, LEFT(b.trx_query, 30) AS blocking_query
FROM information_schema.innodb_lock_waits AS W
INNER JOIN information_schema.innodb_trx AS b ON b.trx_id = W.blocking_trx_id
INNER JOIN information_schema.innodb_trx AS r ON r.trx_id = W.requesting_trx_id
ORDER BY blocking_thread DESC;

//发现其中为waiting_thread 为2 blocking_thread为1的记录,说明2在等待1完成

// 查看innodb_lock_wait_timeout参数配置时间,待确认

发现有超常事务,事务从下午4点多已经开始,一直没有释放,运营保障时已经接近6点。

2.2 紧急规避问题

有长事务未释放不太正常,联系运维将此事务KILL调,管理台操作正常

KILL 1

2.3 继续分析问题

KILL调进程时间段搜寻ELK日志,发现有数据库连接相关的报错,根据连接堆栈找到具体报错代码。 结合代码分析大概原因如下:

Troubleshooting系列-评论管理台接口超时问题定位分析

主要原因有两个:

3.问题解决

此处主要讲述问题解决措施:

  • 临时解决方案:kill 定时任务事务,避免再次出现大事务,与运营沟通暂停视频外放定时任务,改为人工执行
  • 长期解决方案:
      1. 破坏死锁产生条件,更新评论数据时,按照一致的顺序更新表
      1. 将视频外放大的事务拆小,每个视频外放一个事务,同时@Transactional增加超时时间
      1. 单个@Transactional拆小,保留其中数据库更新操作,其他如查询视频审核放在事务之外

4.举一反三

团队内加大对事务使用和死锁的认知,输出案例集和加入到编程规范中。