在一年一度的 1024 程序员节这一天,怀着激动而又憧憬的心情来到公司,因为万科A 这只房地产龙头股已经跌到26.78 元一股了(下方附上截止当日的日K图),价格已经低于下图上显示的所有日均线,恰好今天又是周四,股市又会迎来每周一大跌的日子,下午就可以开始第一轮买入了。

某位股市大佬统计了 2016年1月1日到 2019年5月23日沪深300指数和中证500指数,验证了周四下跌概率会上升,涨幅更小;跌幅更大。详见此文:发现每周四定投可以赚得更多

事故现象

开盘不久。。。9 点 43 分,催收部门的小伙伴发来急电:催收系统的数据(生产环境),身份证和姓名消失啦~

what the f*cking ?

事件背景

每天早上 9:40 分,催收部门分配案件的小伙伴会在催收系统查询到当天新增的催收数据。

然后将新增的催收数据分配给电催专员,电催专员则对分配到的数据进行电话催收。

催收系统的数据从何而来?

  1. 核算系统在每天早上 7:30 加工并生成截止今日 00:00 前的逾期数据,因为早上 6:00 - 7:00 是银行和机构推送还款信息最多的时间段,业内称为回盘。
  2. 数据处理系统核算系统处理完后,抓取其当日处理的数据并落库。
  3. 将落库的数据从信贷系统匹配客户基本信息并更新落库数据。
  4. 将落库的数据取出并在大数据仓库抓取其风险变量,然后调用风控系统接口打标(也就是标记这个客户的一些风险属性)。
  5. 做完以上这些操作,将最终的数据生成一个数据文件,推送到催收系统指定的 SFTP 服务器的指定目录 。
  6. 催收系统(外购无源码)配套导数工具,会定时检查目录下是否有符合规则的数据文件,若有则解析并导入。

好了,这就是截止目前我所知道的一切。来个图梳理一下:

我的角色

在此流程中,我负责:

  1. 核算系统中催收数据生成
  2. 数据处理系统催收数据加工并上送(上个月接手)

初步解决

因接手离职同事的项目,刚开始还一脸懵逼,加上外购的催收系统处理数据的规则经常变动,故第一反应是催收系统处理规则又调坏啦?

然而事情并没有这么简单,否则也不会有这一篇记录。

找到运维小伙伴拿到文件后,打开一看,数据文件里居然没有这些数据?

然后马上查库一看,数据完整,缺失的信息居然全都有。

任务重跑

然后运维小伙伴过来说在几个月前发生过这种情况,当时重跑了一次就好了,但是运维小伙伴不知道是重跑哪一个任务,所以我配合运维小伙伴重跑了此任务,然后运维小伙伴重新在催收导数工具将数据导入催收系统,查询一下,身份证和姓名等缺失字段均已完整显示,问题完美解决,大家各自归位。然后和小组长一起过了一遍数据文件的生成和上送逻辑,然后决定将缺失的数据字段添加日志记录重复跑几千次,即使是偶然触发的条件,几千次也应该可以触发一次了。

重新分配案件

然而事情并没有就此结束。。。。。。

10 点 51 分,分案小伙伴发来「贺电」,总体意思是:已分配的案件又回到了待分配案件池里。

催收系统是外购系统,运维小伙伴反馈,上次厂商驻点人员在的时候,恢复过一次数据,但是现在没有专业人员,之前参与过恢复的小伙伴也已经另谋高就了,虽然有备份数据,却没人能承担数据恢复失败的后果,最终也没有恢复,由分配案件的小伙伴重新分配了。

问题汇总

问题1:为什么在无任何操作的情况下,身份证、姓名等信息消失了?

问题2:为何上送的数据条数都不对?

问题3:为何已分配的案件又回到了待分配案件池里?

过程记录

数据缺失后查库,发现数据都有,然后就只重跑数据上送任务,取数还是要几分钟的,生成的数据文件有 31MB,上送到 SFTP 服务器还是需要那么几秒钟的,而任务是刚跑就会先在 SFTP 目录下创建一个空文件,然后再才开始将数据写入本地,写完后上送文件。

这种操作也是醉了,创建空文件那一步完全是多余的啊~~~。。。就因为这个导致小哥看到服务器上有文件了,就 down 下来发给我们,后来发现文件数据不完整,大家懵逼了半个多小时。。。

运维小伙伴将第一次和第二次上送的数据文件发过来,小组长就在对比两次生成的文件内容。

然后我回来继续刚才的处理,添加日志记录准备开跑了。这时候小组长似乎有了大发现,叫我过去一看,我的天哪,不仅内容丢失,连数据条数都不一样,第一次生成的数据丢失的文件,只有 19000 条,第二次上送的文件 24500 条,然后让我再次确认数据库落地数据多少。

在数据库查询一看。。。32140条,两份文件都不对。。。

然后服务器本地生成的数据 down 下来一看。数据完整、条数正确,差点逼着小哥检查当时的网络情况了。

不过在这过程中,伟大的老领导回忆起来一个重要的事情:如果已分配的案件在下一次导入中不存在,则视为已结清无需催收了,催收系统会自动结案。

然后和催收小伙伴确认数据历史情况,还果然如此,问题三的原因就这么被找到啦。

然后开始寻找前两个问题产生的原因。

第一步当然是查 log,看看能否找到什么蛛丝马迹。果不其然,一打开日志就发现如下内容:

1
2
2019-10-24 09:10:53,301 INFO [] xxxx.GenerateAndSendFileDataJob.execute:85 [xxxx.GenerateAndSendFileDataJob_Worker-1] [dfds] - sendFile to FTP is SUCCESS:true
2019-10-24 09:50:11,222 INFO [] xxxx.PullDataJob.execute:107 [xxxx.PullDataJob_Worker-1] [dfds] - DataPullJob took 7211214 ms to run

以上内容显示:

  1. 数据文件上送完成时间是 9:10
  2. 取数任务完成时间是 09:50

这。。数据都没取完,就上送啦?

然后将每一个任务启动和结束的日志记录分析对比,然后结合当时任务的触发条件结合,发现了问题所在。

取数:

1
2
3
2019-10-24 07:50:06,715 INFO [] xxxx.PullDataJob.execute:57 [xxxx.PullDataJob_Worker-1] [dfds] - 从核算取数数量:32140
2019-10-24 09:46:25,429 INFO [] xxxx.PullDataJob.execute:60 [xxxx.PullDataJob_Worker-1] [dfds] - 核算取数完成,开始信贷取数····
2019-10-24 09:50:11,222 INFO [] xxxx.PullDataJob.execute:107 [xxxx.PullDataJob_Worker-1] [dfds] - DataPullJob took 7211214 ms to run

生成数据文件上送:

1
2019-10-24 09:10:53,301 INFO [] xxxx.GenerateAndSendFileDataJob.execute:85 [xxxx.GenerateAndSendFileDataJob_Worker-1] [dfds] - sendFile to FTP is SUCCESS:true

发现了啥?

  1. 07:50 开始从核算取数,数量 32140,09:46 才取数完毕,用时约 2 小时。
  2. 09:46 开始从信贷取数,这一步是匹配客户信息,即身份证和姓名等。
  3. 数据文件上送完成时间是 9:10,也就是说,取数都没完成就将数据文件上送了,所以上送文件必然条数也会少很多。

那么接下来,所有的问题都集中在从核算取数花了 2 小时这个现象上了。

取数的表数据总量 899997 条,本次任务需要处理的数据是 32140 条,是按分页取数每次 500 条,避免一次取数过多造成内存溢出,循环取数直至完成。

以下是每次执行查询的日志,前面 55 次执行,每次需要约 2 分钟,最后 10 次查询每次约 1 分钟,共执行查询 65 次,其它操作耗时几乎不计,共用时 1 小时 56 分 18 秒。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
2019-10-24 07:50:06,716 DEBUG - ==>  Preparing: SELECT * FROM ldps.dm_data_info ddi where date_format( input_date, '%Y-%m-%d' ) = ? limit ?,? 
2019-10-24 07:50:06,716 DEBUG - ==> Parameters: 2019-10-23(String), 0(Integer), 500(Integer)
2019-10-24 07:52:17,525 DEBUG - <== Total: 500

2019-10-24 07:52:17,526 DEBUG - ==> Preparing: SELECT * FROM ldps.dm_data_info ddi where date_format( input_date, '%Y-%m-%d' ) = ? limit ?,?
2019-10-24 07:52:17,526 DEBUG - ==> Parameters: 2019-10-23(String), 500(Integer), 500(Integer)
2019-10-24 07:54:24,693 DEBUG - <== Total: 500

# 。。。。。省略 61 组执行日志。。。

2019-10-24 09:44:18,641 DEBUG - ==> Preparing: SELECT * FROM ldps.dm_data_info ddi where date_format( input_date, '%Y-%m-%d' ) = ? limit ?,?
2019-10-24 09:44:18,641 DEBUG - ==> Parameters: 2019-10-23(String), 31500(Integer), 500(Integer)
2019-10-24 09:45:21,072 DEBUG - <== Total: 500

2019-10-24 09:45:21,072 DEBUG - ==> Preparing: SELECT * FROM ldps.dm_data_info ddi where date_format( input_date, '%Y-%m-%d' ) = ? limit ?,?
2019-10-24 09:45:21,073 DEBUG - ==> Parameters: 2019-10-23(String), 32000(Integer), 140(Integer)
2019-10-24 09:46:22,428 DEBUG - <== Total: 140

这个表我有印象,核算系统在生成这个表数据前,会将当天的数据清理,避免任务重复执行导致数据重复,使用条件删除语句清理数据 delete from dm_data_info where input_date = '2019-10-23' ,随着数据的增加,起初这个字段没有索引导致事物超时发生过一次问题,后来加了索引也就相安无事了。

input_date 字段本身就是为了对某日数据查询做的优化,所以存储的 YYYY-MM-dd 格式日期字符串字面值。

没想到啊没想到,另一个系统中也因为这个字段发生了事故,但是这次出现的情况是 SQL 条件写法导致索引失效。

1
where date_format( input_date, '%Y-%m-%d' ) = '2019-10-23'

在条件语句中,等式左边使用函数或存储过程等会导致索引无效,带入语句在数据库执行验证,果然要 2 分钟左右,才 90 万的数据居然要这么长时间。

到此,终于找到问题的根本原因,问题一找到也就很 easy 啦。

既然索引以存在,只需让索引生效即可。在此场景下,改写为上方 delete 语句的方式即可。

若你的类似的日期字段存储的是 datetimetimestamp,那么可以使用范围查询:

1
where input_date >= '2019-10-23' and input_date < '2019-10-24'

然后提了一个生产 BUG,将任务的触发条件一起重构,引入核算系统使用的任务编排工具(此工具还由我全程协助专利申请公司申请的专利哦),将此有强依赖关联的任务,按执行顺序进行编排。

事情就此结束,由于影响太大,不知道绩效考核会受到多少影响。

彩蛋

晚上 21:20 ,吃完晚餐准备洗碗了,收到证券软件消息推送。可转债打新中签啦!这是第一次中签,然后紧接着第二天也中签啦,连续两天中签(此处应有掌声)。