【发布时间】: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。性能没有变化。 -
所以人们可能会猜到罐子里的清单左右是急切地阅读的?如果罐子不可读会怎样?