一、结论
为了提高看本文的效率，我就先写结论。如果对我发现这个问题的过程感兴趣的阅读目录中的[问题发现]部分。
服务器重启时会有网络对时的过程。如果程序依赖系统时间并把系统时间当作一个状态来使用，在服务器重启时可能会因为对时延时使得程序拿到错误的系统时间而引起程序错误。
二、问题发现和解决
案发现场
某天S同学收到通知，由于某台服务器有问题需要对其进行手动重启。于是刚接手这个项目的S同学准备在低峰期在控制台重启服务器，由于不涉及到代码的改动，只需要从注册中心将节点摘除就可以重启，重启后服务会通过Supervisor自动启动并重新注册到注册中心。
于是S同学在当天低峰期的某一时刻14:48对这台机器进行了重启，并隔段时间看看监控：重启后只要CPU、内存等单机指标正常，流量回归正常水位，异常不增加，上游没有明显地抖动就算是重启成功了。
然而S同学虽然看到CPU、内存、GC等系统打点正常，但是请求量、异常数和一些服务埋下的Trace打点都消失了。所幸业务方好像都没有受到影响，S同学慌忙把这个节点从注册中心摘除，开始Debug。
现场分析
首先最直观的一点：系统打点正常而业务打点缺失。基于这个现象开始查找这两种打点之间有什么差异。通过扒Trace团队的源码(打点都是由接入了Trace团队的jar包实现的)发现系统打点是将每个点发送到一个特定的MQ中由Trace服务对其进行消费，而业务打点是直接调Trace的接口进行打点。
- 怀疑这台机器是否能够正常与Trace服务器通信
既然与Trace服务器的连接是通的，那应该只有两个原因
1. 根本没有调用Trace服务器打点发到Trace服务器的
2. 点是错误的点，不会被打出来
继续啃了一晚上Trace的源码，终于发现原因是前者，即根本没有调用Trace服务器打点。这个问题由于本地是完全没有办法复现的，只能在线上已有的机器进行复现，所以只能使用arthas对进程的各个可以的方法进行watch，所以花了一晚上的时间。不过arthas再强也没法像本地debug一样，我们还是没有办法确定到底是为什么没有调用Trace服务器打点。（虽然服务已经从注册中心摘除，但是它是有定时任务在跑的，所以依然会有一些业务打点）
陷入僵局
截至此时，比较的线索已经断了，我们不做断点debug得到每一个调用栈的参数的话，要确定为什么没有调用Trace服务实在是太困难了，于是我们开始没有目的地乱查。
S同学将某一时刻的dump文件下载到本地看了好一会，发现有Metric-Producer线程一直处于Waiting状态，经过询问后发现这个Metric-Producer线程就是Trace用来生成打点的线程!
这里根据这个Trace的线程名相信大家也猜到了这个Trace的代码实际上是进行异步打点的，Metric-Producer只是生成一些打点缓存到本地列表，真正打点是通过一个叫Metric-Consumer线程来进行的，它会将内存中的Trace列表一次性调用Trace服务打出来。
根据这个栈S同学很快找到了代码中对应的地方，确实是ReentrantLock的一个Condition在await()，它正在等待着某样东西唤醒。
至此，我们确定了确实是我们服务本身的问题，因为Metric-Producer一直在等待，所以是因为服务中由于某些原因导致Trace的点没有生成导致的，但是是什么导致的，我们已经把arthas给玩遍了也没有个结论，我们也先暂时封锁现场，鸣金收兵了(当前时间22:37)。
破案
第二天一到公司，S同学首先看一下昨天留下的问题。打开监控看到的那一幕让所有人都大跌眼镜：昨晚22:53的时候业务打点居然出现了!
这意味着如果S同学昨晚要是晚半小时走的话，就能看到打点奇迹般地出现了，不过估计他会因此失眠一宿。
至此这个服务变得正常得不能再正常了，打点正常，系统指标正常，定时任务也能正常处理。如果想要继续调查这个案件，必须要让它复现，但是所有人都打赌即便现在重启这台服务器也不会再复现这个问题了，因为公司这么多服务没有一个人反映过这个问题的，我们都认为这个现象是个发生概率极低极低的现象。
即便现在服务是如此的正常，S同学还是不太敢直接把服务直接注册到注册中心，他决定再重启一次，确实保证这是一个正常的服务才将它注册到注册中心。
于是S同学在14:12的时候又重启了这台服务器，结果现实打了所有人的脸：这台机器的业务打点又消失了！
“稳定复现!”
S同学又开始了积极排查，对他来说，今天的情况跟昨天相比有一点点不同，昨天由于所有人都认为只是重启而已，对这种事不以为意，而今天则是第一时间发现了打点缺失的情况。所以今天的日志是新鲜的，启动日志不至于被浩浩荡荡的业务日志给淹没。
S同学立刻将这台机器从注册中心摘除，开始从启动日志开始排查错误。
当S同学在日志文件中找到服务启动日志的第一条时，差点激动得跳起来，心里暗喊破案了。当时太激动没有截图，不过我可以将大概的日志打出来让大伙看看:
2020-12-01 22:13:57.044 ERROR SQLLogFilter[worker-31]: [xxxx…xxx.xxxx.xxx.xxx] ## Failure ! sql context is quit, clientConnId=593119546 cRecv0,sSend0,sRecv0,cSend0, CLIENT_FAKE_AUTH unknown_user transId=q0 , quitTrace type=conn.das.send2client.broken
大家看到这个日志有没有发现什么不寻常的地方呢？其实这个错误确实不是那么明显，不过如果认真读过标题和认真观察我在上文把时间都加醋的同学应该能发现这个日志的时间是不对的。不光时间不对，还不对的很有规律，这个日志的时间刚好是真正的启动时间+8h。8h对某些程序员来说应该是要比较敏感的，这里就放一个公式吧，是我自己瞎写的，这是我记住格林威治时间(GMT)的手段: CST + 8h = GMT
到这里，S同学开始猜想服务一开始拿到的时间其实是GMT，而后这个时间一定会变成正确的CST(毕竟如果不变回CST，我们其他的服务早出现时间不对的问题了)。因此S同学大胆预测，在几行之后，这个时间就会变成14:xx:xx。不一会儿这个命题就被证实了。(这个截图被留下了，因为被S同学发到了群里并提出他的时差说)
结论和证明
结论：当服务器重启时，对时进程和服务进程并行进行。服务启动时拿到的时间是GMT(格林威治时间)，而之后拿到的时间是CST(中国标准时间)。Trace服务会将服务启动时拿到的时间当作一个状态进行后续的逻辑判断，由于这个时间错误导致了后续的逻辑判断错误。
通过啃源码，S同学将出现逻辑错误的代码扒出来了：
图一：启动时会将当前时间(22:xx)存到成员变量start中
图二：打点时会用当前时间(14:xx)减去start与2000比较，这个逻辑在8消失内一定是false。不用去纠结后面两个条件，只要没有成功打过点它们就都是false。
此时再回过头来看之前的那张监控图，打点缺失的时间大概是8小时。继续求证的办法就是现在预言在晚上22:12左右，打点又会重新出现，不过现在S同学用了更快的求证办法。S同学在Supervisor启动脚本开头添加系统对时命令，即服务启动前先强制对时再进行重启，结果可想而知，服务和打点都好起来了。
后记
之前有个问题可能大家还有疑惑：为什么这么大个公司只有我出现了这个必现的问题呢？因为:
1. 系统对时也是网络对时，对时的时间会根据网络延时的不同而不同。
2. 一般不会做重启操作，平时的服务发布，服务重启都不是直接重启机器的，所以我们这重启机器数据极低频的操作。
3. 公司全面上云后大部分服务已经部署到docker中，系统对时是与宿主机的对时，由于是本地对时所以速度极快，而我们这个服务刚好不是部署在docker的。
关于Trace打点丢失的问题，我之前画了个时序图，帮助大家理解，如果看了以后也还不太明白的话不用纠结，这不是重点
中二的评价
S同学把这个现象和结果发给了运维的大佬，得到了这样一个中二的评价
