最近在日志中发现一些特别奇怪的日志,疑似LTS的任务执行失败结果无法发出去
timestamp 2017-03-06 15:18:58.307
[LTS] Retry send job result failed! jobResults=[{"action":"EXECUTE_EXCEPTION","jobWrapper"……"triggerTime":1484529900000}
经过排查是因为异常message太大,导致无法把整个执行失败的结果发出去。但查了一下数据发现当天任务是执行成功的。百思不得其解,突然注意到 triggerTime,直接转成Date看了一下时间发现是Mon Jan 16 09:25:00 CST 2017。与日志的时间完全不符合。这是怎么回事呢?
初步判断可能是很久之前的失败结果一直保存在机器本地,LTS会定时尝试把这些失败的结果发出去,但无论怎么尝试,都会遇到message太大而无法发出。
最近一段时间公司LTS出现多次问题,中间件团队进行了深入研究。
主要是下面这些问题:
1. 年前年后都爆出的job一直在执行状态的问题
2. 偶尔出现在服务器上的jobtracker not found异常
3. 经常出现的“invokeSync: wait response timeout exception”
4. 偶尔出现的leveldb异常,“org.fusesource.leveldbjni.internal.NativeDB$DBException: IO error: lock /home/work/.lts/TASK_TRACKER/market_task_tracker/failstore/leveldb/94735A3FD25A4CA5A4AAA1836EB9A3D6/LOCK: already held by process“
5. 偶尔出现的“IOException: Connection reset by peer”异常
这些问题初步排查结果如下:
首先,排查问题时发现lts tasktracker上有一个线程安全问题:
多线程并发时的bug。对于tasktracker启动的时候,会同时通过HeartBeatMonitor.ping()和HeartBeatMonitor的subscribe node add来并发添加jobtracker到jobtracker列表,有可能加入重复的jobtracker对象,影响业务逻辑(发送大的tasktracker result到jobtracker上出现异常,会把jobtracker对象临时从列表删除,下次发往新的jobtracker,结果却又一次拿到原来的jobtracker,会导致发送到jobtracker上次数增多,而且不容易抛出jobtracker not found异常)
具体原因是HeartBeatMonitor.check(Node jobTracker)方法中,调用了remotingClient.addJobTracker(jobTracker),这个方法不是线程安全的:
public void addJobTracker(Node jobTracker) {
boolean contains = contains(jobTracker);
System.out.println(">>>>>>>>>>>>>>>>>>>>> contains:" +contains);
if (!contains) {
jobTrackers.add(jobTracker);
}
}
测试这个线程安全问题的日志在附件中。还好