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

V2EX = way to explore

V2EX 是一个关于分享和探索的地方

现在注册

已注册用户请登录

这是一个创建于 1937 天前的主题，其中的信息可能已经有所发展或是发生改变。

问题详情：请求一个接口，在服务器上第一次请求特别慢在 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

2019-08-05 11:01:12 +08:00

是不是第一次请求初始化加载太多数据了

samples

2019-08-05 11:05:14 +08:00

@wlfeng 如果是这个原因那么本地和服务器应该是一样的，但是本地第一次请求是正常的

micean

2019-08-05 11:07:48 +08:00

第一次应该就是连接数据库慢吧？
有些云服务在第一次连接自建数据库的时候特别慢

samples

2019-08-05 11:08:44 +08:00

老哥们给个排查的方向

samples

2019-08-05 11:09:55 +08:00

@micean 本地和服务器上连接的是同一个数据库

Raymon111111

2019-08-05 11:28:25 +08:00

测试建立数据库连接是不是问题

把数据库访问都去掉试试

gz911122

2019-08-05 11:30:24 +08:00

是不是用到 session 了
或者用到随机数了?

服务器环境噪音比较小,随机数生成第一时间会比较场

Aresxue

2019-08-05 11:33:13 +08:00

远程 debug 一下，看下是哪里慢

cheng6563

2019-08-05 11:34:00 +08:00 via iPhone

随机数问题吧
启动命令里加 -Djava.security.egd=file:/dev/./urandom
试试看

BBCCBB

2019-08-05 11:36:17 +08:00

第一次访问有些初始化工作要做,比如初始化数据库连接池等...

Caballarii

2019-08-05 11:38:19 +08:00

jdk 问题，9L 正解，LS 们不要乱猜了

micean

2019-08-05 11:42:33 +08:00

@samples 跟数据库没关系，我以前遇到过，应用放数据库服务器一点问题都没有，跨服务器几分钟都没响应，后来联系服务商，不知道他们怎么解决的

qqpkat2

2019-08-05 11:44:01 +08:00

9 11 楼都不对，尤其是 11 楼瞎几把乱说
随机数问题是导致 tomcat 启动非常慢的原因而不是楼主说的第一次慢

wysnylc

2019-08-05 11:46:08 +08:00

熵池初始化问题

hosaos

2019-08-05 11:47:33 +08:00

你不都打了耗时日志了么，哪一步慢呢？

Caballarii

2019-08-05 11:48:54 +08:00

@qqpkat2 LZ 用的 springboot，java -jar 启动，随机数导致第一次访问慢有什么问题？我这么说是因为我就碰到过，并且这样解决了。动不动说别人瞎几把乱说是不是脑子里有屎？

wangxiaoaer

2019-08-05 11:49:26 +08:00 via Android

预热？

休眠？

hellwys1

2019-08-05 11:50:23 +08:00

mark，遇到相同的问题，也是 save 时出现耗时过多的问题

jorneyr

2019-08-05 11:55:41 +08:00

我们这也会遇到第一次访问慢的情况，不过在 5s 左右，我们这的原因是第一次连接 MySQL 和 MongoDB 导致的，接下来就好了。

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

2019-08-05 11:58:09 +08:00

9 和 11 可能性不大，这种场景还是不要乱猜，用 Arthas 去 Trace Watch 一下就很清晰了。

https://github.com/alibaba/arthas

https://alibaba.github.io/arthas/

lff0305

2019-08-05 12:07:53 +08:00

@lff0305 忘说了直接用 JProfile 跟踪下就知道了，或者在卡的时候 jstack 下就知道卡在哪里了，我们当时是反复执行 jstack，发现 n 个线程都 block 在初始化数据库连接池 - 初始化 jdbc - 初始化 Oracle 连接 - 生成 SecureRandom 那里

samples

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 的方法。至于具体原因我再分析下。