引自博客：https://www.jianshu.com/p/44b7d2652d6d，以防后期作者删除，无法再参考相关经验，特复制出来一份。
Airflow秃头两天填坑过程：任务假死问题
既然秃头填坑, 那就该让这变得更加有价值, 有必要总结出来, 减少其他同事踩坑的可能。
毫无疑问, 所有的踩坑填坑都是很有价值的学习机会。
1. 基本徒劳的昨天
昨天下午，同事报告客户系统上的数据没有入库，Airflow没有跑数据，请求协助。根据同事反馈，问题是下午两三点左右突然就出现了，期间没有上线新代码，也没有对服务器做什么特别的操作, Airflow服务器负载也正常。这也意味着这个问题没法在本地重现，只能在线上处理，这本身就比较大风险，因为线上的数据量很大，搞不好就删库跑路的了。
由于没有Airflow一段时间了，只能硬着头皮一边重新熟悉Airflow，一边查找定位问题，一直到很晚，不过基本上没有摸到问题的关键所在，只是大概弄清楚症状：
Airflow中的Dag任务手动可以启动，调度器和worker也在跑，但是任务不会自动调度；
重启Airflow，手动执行任务等，都没有报错；
在界面上clear一个任务的状态时，会卡死，而通过命令来执行则耗时很长，最后也抛异常。
根据第二个症状判断，业务代码应该是没有问题的。
根据第三个症状，怀疑是Dag任务日志太多导致的，查Airflow的日志，确实很多，于是删删删。清掉了很多日志之后，问题依旧。
此路不通，那就回到第一个症状，怀疑是某些上游资源卡死导致的，最有可能就是数据库查询太慢卡住了。数据库可能出现问题的可能性比较大，毕竟几千万篇文章和上亿条评论都保存在数据库里，于是把缓存和数据库都查了一遍，并没有发现什么问题。
（当然也不是完全徒劳的，只是问题的症状是找到了，只是定位不对）
2. 今天上午：问题基本定位
经过一晚的满血复活，继续填坑。
网上有文章提到这可能是Airflow中的task_instance表的state字段缺少索引, 导致查询很慢导致的, 这就涉及到Airflow本身的问题了。
本想从慢查询入手, 但是客户线上的数据库并没有开启慢查询, 那就找正在执行的sql语句:
# 这个能查到正在执行的sql语句概要信息 SHOW PROCESSLIST; # 这个查看详细信息 select * from information_schema.`PROCESSLIST` where info is not null\G; *************************** 6. row *************************** ID: 387982 USER: xp_airflow HOST: 172.28.3.156:48870 DB: xp_airflow COMMAND: Query TIME: 3206 STATE: Sending data INFO: SELECT union_ti.dag_id AS union_ti_dag_id, union_ti.state AS union_ti_state, count(*) AS count_1 FROM ( SELECT task_instance.dag_id AS dag_id, task_instance.state AS state FROM task_instance INNER JOIN ( SELECT dag_run.dag_id AS dag_id, max(dag_run.execution_date) AS execution_date FROM dag_run INNER JOIN dag ON dag.dag_id = dag_run.dag_id WHERE dag_run.state != 'running' AND dag.is_active = true AND dag.is_subdag = false GROUP BY dag_run.dag_id ) AS last_dag_run ON last_dag_run.dag_id = task_instance.dag_id AND last_dag_run.execution_date = task_instance.execution_date UNION ALL SELECT task_instance.dag_id AS dag_id, task_instance.state AS state FROM task_instance INNER JOIN ( SELECT dag_run.dag_id AS dag_id, dag_run.execution_date AS execution_date FROM dag_run INNER JOIN dag ON dag.dag_id = dag_run.dag_id WHERE dag_run.state = 'running' AND dag.is_active = true AND dag.is_subdag = false ) AS running_dag_run ON running_dag_run.dag_id = task_instance.dag_id AND running_dag_run.execution_date = task_instance.execution_date ) AS union_ti GROUP BY union_ti.dag_id, union_ti.state
类似的语句还有几个, TIME字段是执行时间, 单位: 秒。有一个语句居然跑了快一个小时了, 还在运行, 仿佛开了一扇窗, 感觉要逼近真相了。而且这个语句还真是跟表task_instance有关。
在关闭Airflow之后, 就沿着这个表追查下去:
# 直接查询task_instance记录数不成功 select count(1) from task_instance; # 怀疑是长时间正在执行的sql把占用太多的资源 # kill到正在执行的 sqlkill 387948; # kill掉之后查询还是很慢 select count(1) from task_instance; # 可能是因为这个表的数据量可能很大 # 查询该表的索引 SHOW INDEX FROM task_instance\G; # 得到索引大概如下： 主键：task_id + dag_id + execution_date 唯一值的数量大概：780w ti_dag_state: dag_id + state ti_pool: pool + state + priority_weight ti_state_lkp: dag_id + task_id + execution_date + state ti_state: state ti_job_id: job_id # 查询字段类型 desc task_instance; +-----------------+---------------+------+-----+---------+-------+ | Field | Type | Null | Key | Default | Extra | +-----------------+---------------+------+-----+---------+-------+ | task_id | varchar(250) | NO | PRI | NULL | | | dag_id | varchar(250) | NO | PRI | NULL | | | execution_date | timestamp(6) | NO | PRI | NULL | | | start_date | timestamp(6) | YES | | NULL | | | end_date | timestamp(6) | YES | | NULL | | | duration | float | YES | | NULL | | | state | varchar(20) | YES | MUL | NULL | | | try_number | int(11) | YES | | NULL | | | hostname | varchar(1000) | YES | | NULL | | | unixname | varchar(1000) | YES | | NULL | | | job_id | int(11) | YES | MUL | NULL | | | pool | varchar(50) | YES | MUL | NULL | | | queue | varchar(50) | YES | | NULL | | | priority_weight | int(11) | YES | | NULL | | | operator | varchar(1000) | YES | | NULL | | | queued_dttm | timestamp(6) | YES | | NULL | | | pid | int(11) | YES | | NULL | | | max_tries | int(11) | YES | | -1 | | | executor_config | blob | YES | | NULL | | +-----------------+---------------+------+-----+---------+-------+
网上有文章说可能是state列没有索引导致的，但是显然state列是有索引的。
（Airflow表设计有问题，task_id和dag_id这两个字段这么重要，长度达到250，索引却直接建在这上面）
为什么select count(1)会执行这么慢？（按理说不到一千万的数据，不应该这么慢。这其实是一个重要线索, 不过开始的时候, 觉得其他的线索比这个重要）
上面还没有完全确认数据表的数据, 因为select count一直没有成功, 只另找途径来实现:
# 查询各表的行数 show table status; # 结果输出 # 保留一些行数比较多的 *************************** 6. row *************************** Name: dag_run Engine: InnoDB Version: 10 Row_format: Dynamic Rows: 971312 Avg_row_length: 117 Data_length: 113885184Max_data_length: 0 Index_length: 162676736 Data_free: 7340032 Auto_increment: 972581 Create_time: 2019-07-22 15:23:56 Update_time: 2021-08-26 10:31:09 Check_time: NULL Collation: utf8mb4_general_ci Checksum: NULL Create_options: Comment: *************************** 9. row *************************** Name: job Engine: InnoDB Version: 10 Row_format: Dynamic Rows: 7235247 Avg_row_length: 119 Data_length: 862978048 Max_data_length: 0 Index_length: 850362368 Data_free: 7340032 Auto_increment: 7925689 Create_time: 2019-07-22 15:23:56 Update_time: 2021-08-26 10:43:42 Check_time: NULL Collation: utf8mb4_general_ci Checksum: NULL Create_options: Comment: *************************** 14. row *************************** Name: log Engine: InnoDB Version: 10 Row_format: Dynamic Rows: 31244541 Avg_row_length: 236 Data_length: 7380926464 Max_data_length: 0 Index_length: 0 Data_free: 4194304 Auto_increment: 31794447 Create_time: 2019-07-22 15:23:56 Update_time: 2021-08-26 10:17:22 Check_time: NULL Collation: utf8mb4_general_ci Checksum: NULL Create_options: Comment: *************************** 18. row *************************** Name: task_instance Engine: InnoDB Version: 10 Row_format: Dynamic Rows: 7813375 Avg_row_length: 208 Data_length: 1629945856 Max_data_length: 0 Index_length: 2906046464 Data_free: 4194304 Auto_increment: NULL Create_time: 2019-07-22 15:23:57 Update_time: 2021-08-26 10:16:34 Check_time: NULL Collation: utf8mb4_general_ci Checksum: NULL Create_options: Comment: *************************** 21. row *************************** Name: xcom Engine: InnoDB Version: 10 Row_format: Dynamic Rows: 6536748 Avg_row_length: 122 Data_length: 800047104 Max_data_length: 0 Index_length: 382566400 Data_free: 7340032 Auto_increment: 6566181 Create_time: 2019-07-22 15:23:57 Update_time: 2021-08-26 10:16:34 Check_time: NULL Collation: utf8mb4_general_ci Checksum: NULL Create_options: Comment:
可以看到, task_instance表的数据量确实跟唯一索引中的唯一值是接近的, 也就是这个表的数据量大概就是780万。
再回头分析一下刚才看到的耗时巨大的语句, 格式化一下:
SELECT union_ti.dag_id AS union_ti_dag_id, union_ti.state AS union_ti_state, count(*) AS count_1FROM ( SELECT task_instance.dag_id AS dag_id, task_instance.state AS state FROM task_instance INNER JOIN ( SELECT dag_run.dag_id AS dag_id, max(dag_run.execution_date) AS execution_date FROM dag_run INNER JOIN dag ON dag.dag_id = dag_run.dag_id WHERE dag_run.state != 'running' AND dag.is_active = true AND dag.is_subdag = false GROUP BY dag_run.dag_id ) AS last_dag_run ON last_dag_run.dag_id = task_instance.dag_id AND last_dag_run.execution_date = task_instance.execution_date UNION ALL SELECT task_instance.dag_id AS dag_id, task_instance.state AS state FROM task_instance INNER JOIN ( SELECT dag_run.dag_id AS dag_id, dag_run.execution_date AS execution_date FROM dag_run INNER JOIN dag ON dag.dag_id = dag_run.dag_id WHERE dag_run.state = 'running' AND dag.is_active = true AND dag.is_subdag = false ) AS running_dag_run ON running_dag_run.dag_id = task_instance.dag_id AND running_dag_run.execution_date = task_instance.execution_date ) AS union_ti GROUP BY union_ti.dag_id, union_ti.state
这个语句真不是一般的复杂!!
涉及到的原始表有三个: task_instance, dag_run, dag。
后两个表的查询字段都能被索引覆盖, 但是task_instance这个表的查询字段是dag_id和execution_date, 看我们前面查到的索引就知道, 这两个字段并没有索引覆盖, 索引只能到dag_id, 而这个字段只是一个低基字段, 索引的效率并不高, 跟全表扫描也差不了多少。
到这里, 我大概有了两个解决方案:
给dag_id和execution_date添加联合索引;
清理掉一些历史数据(但是这个有风险, 容易产生不可逆的影响)
到这里上午的时间也耗完了。
客户在群里问, 下午5点前能否把问题解决? 当时其实并没有太大把握, 不过既然问题已经大致定位到了, 这两个方案下去应该能解决。
3. 今天下午: 柳暗花明的真相
下午就开始了建索引之旅:
# 给 task_instance 表的dag_id和execution_date字段建联合索引 # 数据量比较大，建索引预期会很慢 ALTER TABLE `task_instance` \ ADD INDEX ibbd_dag_exec_date(`dag_id`, `execution_date`); # 这里指定一个特别的索引名，方便以后维护，也避免了索引名冲突
这个建索引确实很慢, 期间都完成了一个面试, 建索引的语句却还没跑完。
这个慢是可能的, 但是这么慢却是有点出人意料的, 这时又想起了select count怎么那么慢, 因为就算是全表扫描也不至于这么慢。
这时开始怀疑我们前面的慢查询, 除了有索引原因之外, 可能还有其他的因素影响, 例如系统负载(CPU, 内存或者IO等)。但是这个得上阿里云的后台, 这个只能找客户, 客户再去找他们的运维工程师。
过了一段时间, 客户的运维工程师反馈CPU爆了:
而且这个爆的时间, 跟系统出问题的时间很吻合, 是它无疑了。
这个数据库是Airflow和业务系统共用的, 虽然Airflow停掉了且长时间在执行的sql也清理了, 不会有什么负载, 但是业务系统还一直在跑, 于是进业务系统的数据库看正在执行的sql进程:
show processlist;
显示有1200多个进程, 而且很多执行时间都好几十分钟了, 大部分都是来自同一个sql语句:
MySQL [xp_etl]> show processlist\G;# 大致信息如下 Id: 391824 User: xp_etl Host: 172.28.3.156:54010 db: xp_etl Command: Query Time: 522 State: Sending data Info: SELECT article_id,warning_id FROM warning_article FORCE INDEX(`post_time`) WHERE is_delete =
手动kill了几个, 发现这样不是个事, 应该是有批量的方法的:
# 生成kill sql进程的命令
# 本来可以一个语句直接写入文本文件的, 但是执行时没有权限
select concat('KILL ', id, ';')
from information_schema.processlist
where user='xp_etl';把输出结果写入一个文件中，如/tmp/test.txt
source /tmp/test.txt
kill掉之后, 观察一段时间发现没什么问题, 就重启了Airflow, 数据终于正常的 入库了。
然后找客户的运维工程师重新要来负载图：
负载真降了, 不过看着后面又升上去了, 看着有点危险。
于是又把刚才那个正在进行的sql语句拉出来, 在业务系统的代码里找到完整的语句:
SELECT article_id,warning_id FROM warning_article FORCE INDEX(`post_time`)WHERE is_delete = 0ORDER BY post_time DESC LIMIT 3 # 输出 +--------------------------+------------+ | article_id | warning_id | +--------------------------+------------+ | 5ef5f6b7e89d2534bc20585a | 37 | | 5ef5f6b8e89d2534bc205863 | 37 | | 5ef5f923e89d2531ac851ade | 37 | +--------------------------+------------+ 3 rows in set (1 min 29.41 sec)
这个查询看着挺简单, 就是要倒序拿前三条, 可为什么这么慢?
这只能从这个表的行数, 表结构及索引入手了:
MySQL [xp_etl]> desc warning_article; +------------+-------------+------+-----+-------------------+-----------------------------+ | Field | Type | Null | Key | Default | Extra | +------------+-------------+------+-----+-------------------+-----------------------------+ | id | int(11) | NO | PRI | NULL | auto_increment | | warning_id | int(11) | NO | MUL | NULL | | | article_id | varchar(45) | NO | | NULL | | | post_time | datetime | YES | MUL | NULL | | | created_at | datetime | YES | | CURRENT_TIMESTAMP | | | updated_at | datetime | YES | | CURRENT_TIMESTAMP | on update CURRENT_TIMESTAMP | | is_delete | tinyint(2) | YES | | 0 | | +------------+-------------+------+-----+-------------------+-----------------------------+ # 这个表数据量很大 MySQL [xp_etl]> select count(*) from warning_article; +----------+ | count(*) | +----------+ | 10130102 | +----------+ 1 row in set (27.98 sec) # 查看索引, post_time字段是有索引的 show index from warning_article;
这个表的数据一千多万, 确实不少, 不过这select count还是太慢了点, 看来这服务器的负载还是偏高的。(服务器加配置看来是要的了)
不过, 这个表一千多万数据感觉是不应该的, 不过这个只能留到后面去优化了。
4. 小结
"突然"这个词很具有迷惑性, 好像问题之前不存在, 到了某个时间点突然就出现了, 其实并不是, 就像雪崩, 问题其实在之前就一直在积累了, 只是没有被观察到。于是当问题出现的时候, 就感觉是突然出现的。
碰到问题的时候, 还是应该头脑清醒一点, 先对问题可能的原因做一个全面的分析:
能够导致任务产生假死这种情况的, 要么是Airflow中的ETL代码问题, 要是Airflow本身的问题, 而这两个问题的根源是: 要么是系统负载问题(本地资源问题), 要么是上游资源问题。
本地资源用htop命令是很容易观察的, 而上游资源则需要逐个去分析:
无论是MySQL还是Redis, 当连接不上的时候, 都会报错, 这个可以排除。
不要以为redis就不会产生查询慢的问题, 之前就试过有同事在redis中执行get all之类的命令, 把redis卡死的情况, 只是相对MySQL出问题的概率小了一些。
而MySQL的慢查询的根源就可能有几个:
数据量太大;
索引不合理;
系统负载过高
这几个原因通常不是单一存在的, 而可能是同时存在的, 他们往往是相互影响而成的。
最后:
不会填坑的工程师不是好架构师!