由于基本数据类型使用姿势不对导致的线上"死循环"问题排查

本文要讲的是本周我在线上排查的一个"死循环"问题,由于前人的疏忽,导致线上在某一时间段内疯狂调用第三方服务,并没有在预期时间内结束。

线上代码为采用多线程校验批量任务,如下所示为模拟场景,很容易可以看出,该段代码的逻辑如下:

  1. 首先采用一个大小为100的线程安全队列来模拟待校验任务
  2. 然后起10个线程,每个线程都有10s时间不断的取队列中的任务进行校验
  3. 每次校验都先从队列中取一个任务出来,校验不成功就把任务放回待校验队列,且每次校验完后会休息0.1s
  4. 编号为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左右的时间结束,可是实际执行情况如下:

image-20181201192159038

竟然用了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

结果也符合预期!!!

看到这里你或许和我开始一样产生了如下的疑问:

  1. long类型占用8个字节,double只占用4个字节,为什么long类型能转换为double?

  2. 为什么将startCheckTime变量类型改为long和double都可以,偏偏用float就不行呢?

接下来就带着这两个疑问来复习下基础知识了。

首先看看java中基本数据类型分类和占用的字节数:


image.png

支持的自动类型转换规则如下:

image-20181201204142952
  • 首先解决第一个疑问。

对于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已经足以表达时间戳。

调整后的代码如下, 不管怎样都不会再出现执行时间与预期时间不符的"死循环"了:

  1. 将maxCheckMillis, startCheckTime变量类型都改为long
  2. 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, 也就是两分钟的时间一直在重复执行,让人误以为出现的死循环。所以平时写代码时还是要严于律己,不要给以后或后来人留坑。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 206,968评论 6 482
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 88,601评论 2 382
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 153,220评论 0 344
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 55,416评论 1 279
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 64,425评论 5 374
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,144评论 1 285
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,432评论 3 401
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,088评论 0 261
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,586评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,028评论 2 325
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,137评论 1 334
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,783评论 4 324
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,343评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,333评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,559评论 1 262
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,595评论 2 355
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,901评论 2 345

推荐阅读更多精彩内容

  • 国家电网公司企业标准(Q/GDW)- 面向对象的用电信息数据交换协议 - 报批稿:20170802 前言: 排版 ...
    庭说阅读 10,869评论 6 13
  • 触碰 感情鲜勾勾肩 关系对搭搭背 妈妈 你知道吗 我有多想你 妈妈 再侧点身 这样 我踮着脚尖 就能搂着你了 妈妈...
    枕槿折槐阅读 902评论 6 8
  • 只需要这一个简单的套路,实现公众号文章阅读量10万+ 今天要分享的这个公众号套路,我相信很多人之前都在朋友圈,或是...
    三碗烈酒与友阅读 818评论 0 0
  • 什么是创新? 创新是指以现有的思维模式提出有别于常规或常人思路的见解为导向,利用现有的知识和物质,在特定的环境中,...
    EK_962d阅读 368评论 0 0