V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
samples
V2EX  ›  程序员

javaweb 请求一个接口,第一次请求特别慢在 20-40s,随后请求正常,这是什么问题?

  •  
  •   samples · 2019-08-05 10:58:05 +08:00 · 7049 次点击
    这是一个创建于 1938 天前的主题,其中的信息可能已经有所发展或是发生改变。

    问题详情:请求一个接口,在服务器上第一次请求特别慢在 20-40s,随后请求正常。本地测都是正常的,无论是不是第一请求,都可以在 2s 内响应。

    下面贴出测出的一些数据

    1.两个 service 都有事务,但应该与事务无关,去除事务后耗时是一样的 2.“保存耗时” 在 20-40s,其他耗时基本在 200ms 以内 3.环境:springboot spring-data-jpa

    applyService

        @Override
        public Apply save(LawCase lawCase) {
            long l = System.currentTimeMillis();
            LawCase law = lawCaseService.save(lawCase);
            long l1 = System.currentTimeMillis();
            System.out.println("保存耗时" + (l1 - l));
            Apply apply = new Apply();
            // set 一些属性值
            applyRepository.save(apply);
            long l2 = System.currentTimeMillis();
            System.out.println("保存记录耗时" + (l2 - l1));
            return apply;
        }
    

    lawCaseService

        @Override
        public LawCase save(LawCase lawCase) {
            // 处理关系和初始化标题顺序不可颠倒
            long l = System.currentTimeMillis();
            handleRelation(lawCase);
            long l1 = System.currentTimeMillis();
            initTitle(lawCase);
            long l2 = System.currentTimeMillis();
            lawCaseRepository.save(lawCase);
            long l3 = System.currentTimeMillis();
            System.out.println("处理关系" + (l1 - l));
            System.out.println("初始化标题" + (l2 - l1));
            System.out.println("保存 db" + (l3 - l2));
            return lawCase;
        }
    
    第 1 条附言  ·  2019-08-05 12:07:40 +08:00
    嗯嗯,问题找到了是哪里了。谢谢大家。具体的原因我再分析。

    出问题的是 IdUtil.simpleUUID(); 这个方法。这个是 hutool 库的方法。

    我记得这个库有重写了 jdk 的 UUID,生成 uuid 会更快。

    所以我是没有想到会是它的,都没有给这个方法打 bug 测下耗时。

    具体这个方法为啥会耗时这么长时间,后续我再分析。
    36 条回复    2019-08-07 09:06:12 +08:00
    wlfeng
        1
    wlfeng  
       2019-08-05 11:01:12 +08:00
    是不是第一次请求初始化加载太多数据了
    samples
        2
    samples  
    OP
       2019-08-05 11:05:14 +08:00
    @wlfeng 如果是这个原因那么本地和服务器应该是一样的,但是本地第一次请求是正常的
    micean
        3
    micean  
       2019-08-05 11:07:48 +08:00
    第一次应该就是连接数据库慢吧?
    有些云服务在第一次连接自建数据库的时候特别慢
    samples
        4
    samples  
    OP
       2019-08-05 11:08:44 +08:00
    老哥们给个排查的方向
    samples
        5
    samples  
    OP
       2019-08-05 11:09:55 +08:00
    @micean 本地和服务器上 连接的是同一个数据库
    Raymon111111
        6
    Raymon111111  
       2019-08-05 11:28:25 +08:00
    测试建立数据库连接是不是问题

    把数据库访问都去掉试试
    gz911122
        7
    gz911122  
       2019-08-05 11:30:24 +08:00
    是不是用到 session 了
    或者用到随机数了?

    服务器环境噪音比较小,随机数生成第一时间会比较场
    Aresxue
        8
    Aresxue  
       2019-08-05 11:33:13 +08:00
    远程 debug 一下,看下是哪里慢
    cheng6563
        9
    cheng6563  
       2019-08-05 11:34:00 +08:00 via iPhone
    随机数问题吧
    启动命令里加 -Djava.security.egd=file:/dev/./urandom
    试试看
    BBCCBB
        10
    BBCCBB  
       2019-08-05 11:36:17 +08:00
    第一次访问有些初始化工作要做,比如初始化数据库连接池等...
    Caballarii
        11
    Caballarii  
       2019-08-05 11:38:19 +08:00
    jdk 问题,9L 正解,LS 们不要乱猜了
    micean
        12
    micean  
       2019-08-05 11:42:33 +08:00
    @samples 跟数据库没关系,我以前遇到过,应用放数据库服务器一点问题都没有,跨服务器几分钟都没响应,后来联系服务商,不知道他们怎么解决的
    qqpkat2
        13
    qqpkat2  
       2019-08-05 11:44:01 +08:00
    9 11 楼都不对,尤其是 11 楼瞎几把乱说
    随机数问题是导致 tomcat 启动非常慢的原因而不是楼主说的第一次慢
    wysnylc
        14
    wysnylc  
       2019-08-05 11:46:08 +08:00   ❤️ 1
    熵池初始化问题
    hosaos
        15
    hosaos  
       2019-08-05 11:47:33 +08:00
    你不都打了耗时日志了么,哪一步慢呢?
    Caballarii
        16
    Caballarii  
       2019-08-05 11:48:54 +08:00
    @qqpkat2 LZ 用的 springboot,java -jar 启动,随机数导致第一次访问慢有什么问题?我这么说是因为我就碰到过,并且这样解决了。动不动说别人瞎几把乱说是不是脑子里有屎?
    wangxiaoaer
        17
    wangxiaoaer  
       2019-08-05 11:49:26 +08:00 via Android
    预热?

    休眠?
    hellwys1
        18
    hellwys1  
       2019-08-05 11:50:23 +08:00
    mark,遇到相同的问题,也是 save 时出现耗时过多的问题
    jorneyr
        19
    jorneyr  
       2019-08-05 11:55:41 +08:00
    我们这也会遇到第一次访问慢的情况,不过在 5s 左右,我们这的原因是第一次连接 MySQL 和 MongoDB 导致的,接下来就好了。
    lff0305
        20
    lff0305  
       2019-08-05 11:58:04 +08:00
    遇到过 9 楼的问题,排查到最后,是因为
    1. 测试环境是 VMware Esxi 虚拟机;
    2. 第一次访问,系统初始化数据库连接池,连接池初始化 JDBC 驱动,ORACLE jdbc 驱动在连接的初始化时要生成 SecureRandom 做秘钥。
    3. 在那个 Esxi 环境,生成 SecureRadom 极其缓慢。因为缺少某些“硬件操作信息”来生成真随机数

    同样的凡是使用了 SecureRandom 的所有类库( https/ssl,rsa 等等等)都有类似的问题。
    这个问题在物理机上无法重现。

    修改:按照 9 楼的方法修改 jvm 启动参数,即用基数种子的数学伪随机数来替换基于硬件操作信息的真随机数
    blackboom
        21
    blackboom  
       2019-08-05 11:58:09 +08:00
    9 和 11 可能性不大,这种场景还是不要乱猜,用 Arthas 去 Trace Watch 一下就很清晰了。

    https://github.com/alibaba/arthas

    https://alibaba.github.io/arthas/
    lff0305
        22
    lff0305  
       2019-08-05 12:07:53 +08:00
    @lff0305 忘说了直接用 JProfile 跟踪下就知道了,或者在卡的时候 jstack 下就知道卡在哪里了,我们当时是反复执行 jstack,发现 n 个线程都 block 在初始化数据库连接池 - 初始化 jdbc - 初始化 Oracle 连接 - 生成 SecureRandom 那里
    samples
        23
    samples  
    OP
       2019-08-05 12:12:39 +08:00
    @Raymon111111
    @gz911122
    @Aresxue
    @cheng6563
    @BBCCBB
    @Caballarii
    @micean
    @qqpkat2
    @wysnylc
    @hosaos
    @Caballarii
    @wangxiaoaer
    @hellwys1
    @jorneyr
    @lff0305
    @blackboom
    谢谢老哥们。找到问题了,确实是生成 uuid 的方法出了问题。这个是 hutool 库的一个生成 id 的方法。至于具体原因我再分析下。
    opengps
        24
    opengps  
       2019-08-05 12:18:05 +08:00 via Android
    服务器是虚拟机的话,硬盘必然比本地慢一拍
    再说首次访问确实需要很多组件都从硬盘添加到内存
    lawler
        25
    lawler  
       2019-08-05 12:22:24 +08:00
    移除 hutool 吧。这个库问题真的很多,之前拦截全局 cookies。会导致所有 http 相关的类受影响。
    msg7086
        26
    msg7086  
       2019-08-05 12:25:08 +08:00
    可以装个虚拟随机数生成器试试。Debian 下有个 haveged 可以用,特别适合虚拟机。
    nicoljiang
        27
    nicoljiang  
       2019-08-05 13:44:37 +08:00
    一般是云服务器的「熵」不足。
    Java 需要调整一下生成随机数的方式。
    samples
        28
    samples  
    OP
       2019-08-05 14:04:36 +08:00
    @lawler 嗯嗯有这个打算
    liuxey
        29
    liuxey  
       2019-08-05 14:09:01 +08:00
    久闻 hutool 大名,就是一直没用过,楼主查出问题了能否 @ 我一下,让我继续放弃使用这个库
    qqpkat2
        30
    qqpkat2  
       2019-08-05 17:18:12 +08:00
    @Caballarii 你连别人问题都没看清楚就来回复,认真审题好么
    什么叫第一次调用接口,那是系统已经起来了去调用
    lolizeppelin
        31
    lolizeppelin  
       2019-08-05 19:26:48 +08:00
    看样子像是 linux 随机不够?
    如果是的话, 有个命令能刷新这玩意的
    srx1982
        32
    srx1982  
       2019-08-05 19:37:13 +08:00 via Android
    @nicoljiang 非常有可能
    nickchenyx
        33
    nickchenyx  
       2019-08-05 22:52:37 +08:00
    @liuxey 这和 Hutool 又没关系,问题在于 JDK 自身的随机数生成问题,你这个赖到 Hutool 上不道义
    CEBBCAT
        34
    CEBBCAT  
       2019-08-05 22:59:58 +08:00
    随机数产生器这么热手的么……
    liuxey
        35
    liuxey  
       2019-08-05 23:02:25 +08:00
    @nickchenyx 没仔细看,抱歉了
    samples
        36
    samples  
    OP
       2019-08-07 09:06:12 +08:00
    @nickchenyx 这个怎么说呢,hutool 调用的也是 jdk 的 SecureRandom,jdk 的 UUID 也是用的 SecureRandom,但不知为何 hutool 的第一次调用就需要非常长的时间,难道它把一些随机数加再到内存了?
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   实用小工具   ·   1008 人在线   最高记录 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 26ms · UTC 18:53 · PVG 02:53 · LAX 10:53 · JFK 13:53
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.