将大量JAR添加到类路径中时,Java File IO性能下降了30%以上

Question

测试代码:

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线/秒.

控制台输出如下:

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线/秒

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,除了classpath之外没有区别.
• 不是OS缓存.这可以复制.经过多次测试,结果是一样的.无论哪个测试先跑.
• 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线/秒.如果从类路径中移除超过2/3的罐子,性能大约为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;
        }
    }
}

运行并按回车主时间,性能不会改变.

Answer 1

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

正如问题中提到的，另一个测试是使用JDK 1.6.0_37，它的性能有所提高，但仍然存在差距。

因此，如果可能的话，升级 JDK。

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