本文要讲的是本周我在线上排查的一个"死循环"问题,由于前人的疏忽,导致线上在某一时间段内疯狂调用第三方服务,并没有在预期时间内结束。
线上代码为采用多线程校验批量任务,如下所示为模拟场景,很容易可以看出,该段代码的逻辑如下:
- 首先采用一个大小为100的线程安全队列来模拟待校验任务
- 然后起10个线程,每个线程都有10s时间不断的取队列中的任务进行校验
- 每次校验都先从队列中取一个任务出来,校验不成功就把任务放回待校验队列,且每次校验完后会休息0.1s
- 编号为44的校验任务是一个永远都过不去的坎
public void multiThreadCheckTest(){
//初始化待校验队列,大小为100
ConcurrentLinkedQueue<Integer> queue = new ConcurrentLinkedQueue<>();
for (int i = 0; i < 100; i++) {
queue.add(i);
}
int threads = 10; //起10个线程来做校验任务
float maxCheckMillis = 10 * 1000;// 单个线程最长校验时间为10s
try{
final CountDownLatch latch = new CountDownLatch(threads);
float startCheckTime = System.currentTimeMillis();
for (int i = 0; i < threads; i++) {
new Thread(() -> {
try {
// 每个线程循环执行校验
while (!queue.isEmpty() && System.currentTimeMillis() - startCheckTime < maxCheckMillis) {
Integer ii = queue.poll();
// 模拟线上出现的问题,卡在44这里执行不过去
boolean checkResult = (ii == 44 ? false : true);
if(!checkResult){
queue.add(ii); //校验不成功则把任务重新加入到队列中
}
Thread.sleep(100);//休息0.1s
}
} catch (Exception e) {
//异常处理
} finally {
latch.countDown();
}
}).start();
}
latch.await();
while (!queue.isEmpty()) {
Integer iii = queue.poll();
System.out.println("No." + iii+ " task check failed within " + (System.currentTimeMillis() - startCheckTime) / 1000 + "s");
}
}catch (Exception e){
//异常处理
}
}
依上可知,每个线程每秒的检验能力为10次,所在在10秒时间10个线程的校验能力为: 10*10 *10 = 1000, 足以处理100个任务,所以这段代码的理想情况应该在10s左右的时间结束,可是实际执行情况如下:
竟然用了131s,比预期的10倍还多。
而我遇到线上的实际每个线程有4分钟时间来校验任务,且每次校验完后没有休息直接下一次校验!!!把这个4分钟如果放大10倍,如果有个任务一直校验不成功的话,相当于40分钟时间10个线程在不间断的执行校验任务(相当于死循环),且这个校验是调用第三方的接口,不仅会把自己给累死,还给了别人很大的压力。还好我们接收到了机器报警,及时重启了应用。
为什么会出现这种情况???
第一眼看到用了多线程,队列,还有CountDownLatch类,我还以为是哪里用得不当导致代码中产生了死锁,但不管是看代码还是分析线程堆栈,都发现不了问题。
只有另辟溪径了,除了上面的线程并发问题,接下来只可能是while循环的判断有问题了。这段代码有两个while循环,很明显每二个while没问题,所以只有第一个while的问题了:
while (!queue.isEmpty() && System.currentTimeMillis() - startCheckTime < maxCheckMillis)
这个while循环当队列为空或到执行了指定的时间后就会停止,队列明显不会为空,所以只能靠第二个条件了。
既然和线程并发无关,和队列无关,为了便于分析,对代码进行简化如下:
public void multiThreadCheckTest(){
try {
float maxCheckMillis = 10 * 1000;
float startCheckTime = System.currentTimeMillis();
while (System.currentTimeMillis() - startCheckTime < maxCheckMillis) {
Thread.sleep(100);//每校验一次休息0.1s
}
System.out.println((System.currentTimeMillis() - startCheckTime) / 1000);
} catch (Exception e) {
//异常处理
}
}
理想情况是输出一个接近10左右的值,可实际上输出的是131.072.
果不其然,出问题的就在这几行代码里了。对while循环里的左边的值进行打印:
public void multiThreadCheckTest(){
try {
float maxCheckMillis = 10 * 1000;
float startCheckTime = System.currentTimeMillis();
while (System.currentTimeMillis() - startCheckTime < maxCheckMillis) {
System.out.println(System.currentTimeMillis() - startCheckTime);
Thread.sleep(100);//每校验一次休息0.1s
}
System.out.println((System.currentTimeMillis() - startCheckTime) / 1000);
} catch (Exception e) {
//异常处理
}
}
输出却和预想中并不一样:
0.0
0.0
0.0
...
0.0
0.0
0.0
131.072
全部为0.0直到最后用了100多秒时间结束,所以问题只能出现在startCheckTime变量的初始化上了,System.currentTimeMillis()返回的是一个long类型的值,但这里却利用java基本数据类型的自动转换用一个float类型的值来接收,我们将float改为long后输出如下:
0
102
204
306
409
...
9790
9890
9991
10
最后就是在10秒结束,问题解决。
接着又试了一下将float改为double,输出如下:
0.0
102.0
208.0
311.0
...
9774.0
9879.0
9980.0
10.081
结果也符合预期!!!
看到这里你或许和我开始一样产生了如下的疑问:
long类型占用8个字节,double只占用4个字节,为什么long类型能转换为double?
为什么将startCheckTime变量类型改为long和double都可以,偏偏用float就不行呢?
接下来就带着这两个疑问来复习下基础知识了。
首先看看java中基本数据类型分类和占用的字节数:
支持的自动类型转换规则如下:
- 首先解决第一个疑问。
对于byte, short, int和long四个整数类而言,它们在内存中都是直接换算成二进制存储的, 下面以byte为例:
占用1字节即8bit,每一位都是二进制的0或1,且第一位为表示正负的符号位,最大为0111 1111,转换为10进制为127,最小为1111 1111,转换为十进制为-128(1000 000, 用补码计算, 负数的袚即原码非符号位取反加1, -128 = (-1) + (-127) = [1000 0001]原 + [1111 1111]原 = [1111 1111]补 + [1000 0001]补 = [1000 0000]补 ), 所以byte的取值范围为-128~127。同理
short(-32768~32767),
int(-2147483648~2147483647)
long(-9223372036854774808~9223372036854774807)
而浮点数是以科学计数法的形式存储,以单精度类型float为例,占用4个字节即32bit,第一个bit为符号位,接下来8bits为指数位(取值班范围为-128-127),剩下23bits为小数位。所以float的取值范围为3.402823e+38 ~ 1.401298e-45(e+38表示是乘以10的38次方,e-45表示乘以10的负45次方),同理double双精度有11个指数位52个小数位,取值范围为1.797693e+308~ 4.9000000e-324。
由于可知,因为在内存中的存储形式不同,虽然float类型只占4个字节,但是表示的数值范围远远大于long的数值范围, 所以long类型能转换为float类型。
- 接下来解决第二个问题。
浮点数之所以称为浮点,是因为它会产生精度丢失。计算机世界只能用二进制的小数来表达小数,而我们现实世界是用十进制的小数来表达。对于二进制小数,小数点右边能表达的值是 1/2, 1/4, 1/8, 1/16, 1/32, 1/64, 1/128 … 1/(2^n)。所有这些小数都是一点一点的拼凑出来的一个近似的数值, 所有才会不准确的。
举个例子, 现在用二进制来表示十进制的1.2:
1.01 = 1 + 1/4 = 0.25 , 偏大
1.001 = 1 + 1/8 = 0.125 , 偏小
1.0011 = 1 + 1/8 + 1/16 = 0.1875 ,
1.001101 = 1 + 1/8+ 1/16 + 1/64 = 0.203125 , 又偏大
1.0011001 = 1 + 1/8 + 1/16 + 1/128 = 0.1953125 ,
1.00110011 = 1 + 1/8+1/16+1/128+1/256 = 0.19921875 , 这个很接近
越来越接近…
这就是所谓的用二进制小数没法精确表达10进制小数的意思。
因为浮点数表示的小数位不同所以精度不同。
float:2^23 = 8388608,一共七位,这意味着最多能有7位有效数字,但绝对能保证的为6位,也即float的精度为6~7位有效数字;
double:2^52 = 4503599627370496,一共16位,同理,double的精度为15~16位。
回到我们要解决的问题,打印出System.currentTimeMillis()的一个值:
1543671830108 = 1.543671830108E+12
转换为float: 10 ^ 12 / 2^ 23 = 119209 ms = 119s (java中为131072ms = 131s, 有待考究)
转换为double: 10 ^ 12 / 2^ 52 = 0 可以忽略
通过上面计算把时时间戳转换为float后会损失精度,有一百多秒的精度损失, 转换为double后几乎没有精度损失,这就是为什么可以将时间戳转换为double而不能转换为float了, 当然最好还是直接使用long, 因为long已经足以表达时间戳。
调整后的代码如下, 不管怎样都不会再出现执行时间与预期时间不符的"死循环"了:
- 将maxCheckMillis, startCheckTime变量类型都改为long
- while循环里只有在校验不成功才暂停0.1s
public void multiThreadCheckTest(){
//初始化待校验队列,大小为100
ConcurrentLinkedQueue<Integer> queue = new ConcurrentLinkedQueue<>();
for (int i = 0; i < 100; i++) {
queue.add(i);
}
int threads = 10; //起10个线程来做校验任务
long maxCheckMillis = 10 * 1000;// 单个线程最长校验时间为10s
try{
final CountDownLatch latch = new CountDownLatch(threads);
long startCheckTime = System.currentTimeMillis();
for (int i = 0; i < threads; i++) {
new Thread(() -> {
try {
// 每个线程循环执行校验
while (!queue.isEmpty() && System.currentTimeMillis() - startCheckTime < maxCheckMillis) {
Integer ii = queue.poll();
// 模拟线上出现的问题,卡在44这里执行不过去
boolean checkResult = (ii == 44 ? false : true);
if(!checkResult){
//校验不成功则记录日志,并休息0.1s, 然后把任务重新加入到队列中
System.out.println(Thread.currentThread() + " check " + ii + " failed!");
Thread.sleep(100);//校验不成功则休息0.1s
queue.add(ii);
}
}
} catch (Exception e) {
//异常处理
} finally {
latch.countDown();
}
}).start();
}
latch.await();
while (!queue.isEmpty()) {
Integer iii = queue.poll();
System.out.println("No." + iii+ " task check failed within " + (System.currentTimeMillis() - startCheckTime) / 1000 + "s");
}
}catch (Exception e){
//异常处理
}
}
总结: 由于疏忽大意使用基本数据类型姿势不对,while循环内的条件判断没有在预期时间内为非,最多多出100多s, 也就是两分钟的时间一直在重复执行,让人误以为出现的死循环。所以平时写代码时还是要严于律己,不要给以后或后来人留坑。