【问题标题】:Java File IO performance dropped over 30% when adding lots of JARs into classpath在类路径中添加大量 JAR 时,Java 文件 IO 性能下降超过 30%
【发布时间】:2026-02-23 02:45:02
【问题描述】:

测试代码:

import java.io.BufferedReader;
import java.io.FileReader;
import java.io.IOException;
import java.util.Map.Entry;

public class ReadLine {

    /**
     * @param args
     * @throws IOException
     */
    public static void main(String[] args) throws IOException {
        System.getenv();
        System.getProperties();

        BufferedReader br = new BufferedReader(new FileReader(args[0]), 2 << 17);
        int lineTotal = 0;
        int lineDone = 0;
        long start = System.currentTimeMillis();
        long totalSincePre = System.currentTimeMillis();
        while (br.readLine() != null) {
            lineTotal++;
            if (lineTotal % 100000 == 0) {
                long end = System.currentTimeMillis();
                System.out.println("total speed=" + lineTotal / (end - totalSincePre) + "k/s. curr speed="
                        + (lineTotal - lineDone) / (end - start));
                start = end;
                lineDone = lineTotal;
            }
        }
        printEnv();
    }

    static void printEnv() {

        for (Entry<?, ?> e : System.getenv().entrySet()) {
            System.out.println(e.getKey() + ":" + e.getValue());
        }

        for (Entry<?, ?> e : System.getProperties().entrySet()) {
            System.out.println(e.getKey() + ":" + e.getValue());
        }
    }
}

测试环境: 操作系统:Linux,文件大小:7.2G(csv文本文件,每行超过1k),java版本“1.6.0_32”

测试运行:

代码被打包到一个 jar 中。我在同一个主机上运行了两个测试,使用同一个 jar,读取同一个文件。

1) 运行./java -cp=my.jar ReadLine TestFile.txt 性能稳定在 150k line/s 左右。

控制台输出如下:

total speed=251k/s. curr speed=251
total speed=304k/s. curr speed=384
total speed=323k/s. curr speed=371
total speed=337k/s. curr speed=387
total speed=350k/s. curr speed=414
total speed=358k/s. curr speed=401
total speed=363k/s. curr speed=395
total speed=349k/s. curr speed=277
total speed=304k/s. curr speed=150
total speed=277k/s. curr speed=153
total speed=258k/s. curr speed=154
total speed=244k/s. curr speed=152
total speed=233k/s. curr speed=152
total speed=225k/s. curr speed=154
total speed=218k/s. curr speed=153
total speed=196k/s. curr speed=149
total speed=193k/s. curr speed=146
......stabled.......
total speed=163k/s. curr speed=150
total speed=162k/s. curr speed=155
total speed=162k/s. curr speed=155
total speed=162k/s. curr speed=149
total speed=162k/s. curr speed=147
total speed=162k/s. curr speed=150
total speed=161k/s. curr speed=148
total speed=161k/s. curr speed=145
total speed=161k/s. curr speed=151
total speed=161k/s. curr speed=154
total speed=161k/s. curr speed=163
total speed=161k/s. curr speed=179

2) 没有代码更改,只是将 JAR(在生产环境中使用)添加到类路径中(在生产中需要,但本程序不需要),例如 ./java -cp=my.jar:hundreds_of_other_jars ReadLine TestFile.txt。性能下降到90k线/s左右

total speed=312k/s. curr speed=383
total speed=335k/s. curr speed=393
total speed=348k/s. curr speed=395
total speed=361k/s. curr speed=423
total speed=369k/s. curr speed=414
total speed=374k/s. curr speed=404
total speed=342k/s. curr speed=214
total speed=264k/s. curr speed=93
total speed=224k/s. curr speed=95
total speed=200k/s. curr speed=95
total speed=182k/s. curr speed=94
total speed=170k/s. curr speed=94
total speed=161k/s. curr speed=95
total speed=154k/s. curr speed=95
total speed=148k/s. curr speed=93
.....stabled.....
total speed=139k/s. curr speed=92
total speed=135k/s. curr speed=92
total speed=132k/s. curr speed=92
total speed=129k/s. curr speed=92
total speed=127k/s. curr speed=92
total speed=125k/s. curr speed=90
total speed=123k/s. curr speed=91
total speed=121k/s. curr speed=92
total speed=120k/s. curr speed=89
total speed=118k/s. curr speed=92
total speed=117k/s. curr speed=91
total speed=116k/s. curr speed=91
total speed=115k/s. curr speed=91
total speed=114k/s. curr speed=90
total speed=113k/s. curr speed=91

我的分析:

唯一的区别是类路径。第二个测试的类路径在类路径中有数百个 JAR。但是在这个程序中没有使用它们。

  • 与环境无关。此代码被打包到 JAR 中,并且两个测试都使用相同的 JAR。两个测试都在同一台主机上运行,​​读取相同的文件,使用相同的代码。我还比较了 System.getEnv 和 System.getProperties,除了类路径没有区别。
  • 不是操作系统缓存。这可以重现。经过多次测试,结果都是一样的。无论哪个测试先运行。
  • jmap 显示内存使用没有太大差异,并且所有代都没有被高度使用。
  • jstack 显示这两个测试的调用堆栈最有可能是

这个

at java.io.FileInputStream.available(Native Method)
at sun.nio.cs.StreamDecoder.inReady(StreamDecoder.java:343)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:304)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)
 - locked <0xb4220388> (a java.io.FileReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.readLine(BufferedReader.java:299)
- locked <0xb4220388> (a java.io.FileReader)
at java.io.BufferedReader.readLine(BufferedReader.java:362)
at com.amazon.invhealth.metrics.transform.topasin.RL.main(RL.java:24)

at sun.nio.cs.UTF_8$Decoder.decodeArrayLoop(UTF_8.java:240)
at sun.nio.cs.UTF_8$Decoder.decodeLoop(UTF_8.java:305)
at java.nio.charset.CharsetDecoder.decode(CharsetDecoder.java:544)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:298)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)
- locked <0xb4220388> (a java.io.FileReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.readLine(BufferedReader.java:299)
- locked <0xb4220388> (a java.io.FileReader)
at java.io.BufferedReader.readLine(BufferedReader.java:362)
at com.amazon.invhealth.metrics.transform.topasin.RL.main(RL.java:24)

查看调用堆栈,这些测试用例很可能使用相同的代码。

  • 这不是由类路径中的某个 JAR 引起的。我尝试删除类路径的前 50% 来运行测试,性能约为 110k line/s。然后我去掉最后的 50% 运行测试,性能也是 110k line/s 左右。如果从类路径中删除超过 2/3 的 jar,则性能约为 120k line/s。所以从测试来看,这个性能问题只与类路径中有多少 JAR 有关。
  • 然后我尝试将所有这些 JAR 打包到一个大 JAR 中。可悲的是,性能从 90k 下降到 60k....所以准确地说,根据我的测试,这种性能下降是由类路径中有多少类引起的。
  • 我在不同的机器上用不同的文件(文件大小和格式相似)运行了这两个测试,结果是一样的。所以这绝对可以重现。

但我认为这没有意义。我错过了什么吗?如果这确实是真的,那么根本原因是什么?

---------更多调试------

GC 和 Perm 大小

在两个测试中添加了-Xmx2432m -Xms256m -XX:MaxNewSize=700m -XX:MaxPermSize=1024m -XX:+PrintGCDetails。有所有只是有PSYoungGen GC。两者的性能相同。

输出细节

长CP一:

total speed=114k/s. curr speed=91
[GC [PSYoungGen: 247888K->16K(238272K)] 248810K->938K(413056K), 0.0003290 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
total speed=113k/s. curr speed=92
[GC [PSYoungGen: 238096K->16K(228864K)] 239018K->938K(403648K), 0.0003840 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
total speed=113k/s. curr speed=92
[GC [PSYoungGen: 228816K->16K(220096K)] 229738K->938K(394880K), 0.0006030 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
total speed=112k/s. curr speed=92
[GC [PSYoungGen: 219984K->16K(211584K)] 220906K->938K(386368K), 0.0004380 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
total speed=111k/s. curr speed=93
[GC [PSYoungGen: 211536K->16K(203584K)] 212458K->938K(378368K), 0.0005160 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
total speed=111k/s. curr speed=92
[GC [PSYoungGen: 203472K->16K(195840K)] 204394K->938K(370624K), 0.0005920 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
total speed=110k/s. curr speed=94
[GC [PSYoungGen: 195792K->16K(188608K)] 196714K->938K(363392K), 0.0004010 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 188496K->16K(181568K)] 189418K->938K(356352K), 0.0004440 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

......................

Heap
 PSYoungGen      total 145984K, used 81767K [0xc8560000, 0xd7780000, 0xf4160000)
  eden space 145920K, 56% used [0xc8560000,0xcd535d18,0xd13e0000)
  from space 64K, 25% used [0xd7760000,0xd7764000,0xd7770000)
  to   space 64K, 0% used [0xd7770000,0xd7770000,0xd7780000)
 PSOldGen        total 174784K, used 922K [0x5c160000, 0x66c10000, 0xc8560000)
  object space 174784K, 0% used [0x5c160000,0x5c246ae8,0x66c10000)
 PSPermGen       total 16384K, used 2032K [0x1c160000, 0x1d160000, 0x5c160000)
  object space 16384K, 12% used [0x1c160000,0x1c35c260,0x1d160000)

一罐CP:

total speed=180k/s. curr speed=148
[GC [PSYoungGen: 87248K->16K(87296K)] 87904K->672K(262080K), 0.0005300 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 87248K->16K(87296K)] 87904K->672K(262080K), 0.0004950 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 87248K->16K(87296K)] 87904K->672K(262080K), 0.0005020 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
total speed=179k/s. curr speed=150
[GC [PSYoungGen: 87248K->16K(87296K)] 87904K->672K(262080K), 0.0005360 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 87248K->16K(87296K)] 87904K->672K(262080K), 0.0005190 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
total speed=178k/s. curr speed=151
[GC [PSYoungGen: 87248K->16K(87296K)] 87904K->672K(262080K), 0.0005360 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 87248K->16K(87296K)] 87904K->672K(262080K), 0.0005400 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC [PSYoungGen: 87248K->16K(87296K)] 87904K->672K(262080K), 0.0003510 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
total speed=177k/s. curr speed=150

Heap
 PSYoungGen      total 87296K, used 83826K [0xc8580000, 0xcdad0000, 0xf4180000)
  eden space 87232K, 96% used [0xc8580000,0xcd758928,0xcdab0000)
  from space 64K, 25% used [0xcdab0000,0xcdab4000,0xcdac0000)
  to   space 64K, 0% used [0xcdac0000,0xcdac0000,0xcdad0000)
 PSOldGen        total 174784K, used 656K [0x5c180000, 0x66c30000, 0xc8580000)
  object space 174784K, 0% used [0x5c180000,0x5c224080,0x66c30000)
 PSPermGen       total 16384K, used 2022K [0x1c180000, 0x1d180000, 0x5c180000)
  object space 16384K, 12% used [0x1c180000,0x1c379bb0,0x1d180000)

JVM 初始值

我非常期待这是原因,因为这是合理的。但是使用以下代码后:

String filepath = args[0];
while (true) {
    BufferedReader br = new BufferedReader(new FileReader(filepath), 2 << 17);
    System.out.println("Press Enter to start...");
    while (System.in.read() != '\n')
        ;
    int lineTotal = 0;
    int linePre = 0;
    long start = System.currentTimeMillis();
    long totalStart = System.currentTimeMillis();
    while (br.readLine() != null) {
        lineTotal++;
        if (lineTotal % 100000 == 0) {
            long end = System.currentTimeMillis();
            System.out.println("total speed=" + lineTotal / (end - totalStart) + "k/s. curr speed="
                    + (lineTotal - linePre) / (end - start));
            start = end;
            linePre = lineTotal;
        }
    }
}

运行并按回车主次,性能不会改变。

【问题讨论】:

  • 我试过java版本“1.6.0_37”,它有很多改进。对于“cp中的很多罐子”之一,速度是150k线/秒。而对于“cp中的单个jar”,速度为180k line/s。大约 20% 的性能下降,仍然可以复制,但对我来说仍然没有意义......
  • 也值得用 jconsole 或类似工具研究 gc 图。尝试增加 permgen 大小,可能因为所有这些 jars 而它已满,而 gc 一直在尝试清理它。
  • 我想知道当你的基准测试开始时,IO 系统是否仍然在 JVM 启动期间被颠簸(例如,通过搜索长长的 jar 列表并扫描它们);因此 JVM 和您的基准测试正在竞争文件访问?对此进行测试的一种方法是运行您的基准测试 2 或 3 次,睡眠足够长的时间让尘埃落定,然后执行您的基准测试以真正丢弃第一个值。
  • 向两者添加了-Xmx2432m -Xms256m -XX:MaxNewSize=700m -XX:MaxPermSize=1024m -XX:+PrintGCDetails。性能没有变化。
  • 所以人们可能会猜到罐子里的清单左右是急切地阅读的?如果罐子不可读会怎样?

标签: java file io


【解决方案1】:

我找到了解决方案,但仍然不知道为什么。我使用JDK 1.7.0_21再次运行测试,两个测试用例的性能相同,稳定在180k线/秒。

正如问题中提到的,另一个测试是使用JDK 1.6.0_37,它有性能提升但仍有差距。

所以,如果可能的话,升级 JDK。

如果有人知道根本原因并告诉我原因,我将不胜感激:-)

【讨论】:

    【解决方案2】:

    我认为这取决于您导入文件的方式。

    如果速度是一个问题,请始终只导入您使用的类。

    认为它的方式是计算机正在做更多的事情来做它之前做的更少的事情。

    【讨论】:

    • 做更多的事情,但是?读取循环中几乎没有任何操作会依赖于类路径,并且明显的操作(更新字符串以包含新行)不应该受到干扰。