テストコード:
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());
}
}
}
テスト環境: OS: Linux、ファイル サイズ: 7.2G (csv テキスト ファイル、1 行あたり 1k 以上)、Java バージョン "1.6.0_32"
テスト走行：
コードは 1 つの jar にパッケージ化されています。同じホストで、同じjarを使用して同じファイルを読み取って、次の2つのテストを実行しました。
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 行/秒に低下しました
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
私の分析：
唯一の違いはクラスパスです。2 番目のテストのクラスパスには、クラスパスに数百の JAR があります。しかし、このプログラムではそれらのどれも使用されていません。
- 環境関係なし。このコードは JAR にパッケージ化され、両方のテストで同じ JAR が使用されました。どちらのテストも同じホストで実行され、同じファイルを読み取り、同じコードを使用します。System.getEnv と System.getProperties も比較しましたが、クラスパス以外に違いはありません。
- 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 行/秒です。次に、テストを実行するために最後の 50% を削除します。パフォーマンスも約 110k ライン/秒です。クラスパスから 2/3 以上の jar を削除すると、パフォーマンスは約 120k 行/秒になります。したがって、テストから、このパフォーマンスの問題は、クラスパスに含まれる JAR の数に関連しています。
- 次に、これらすべての JAR を 1 つの大きな JAR にパッケージ化しようとしました。悲しいことに、パフォーマンスは 90k から 60k に低下しました....正確には、私のテストに基づいて、このパフォーマンスの低下は、クラスパスにあるクラスの数によって引き起こされます。
- 別のファイルを使用して別のマシンで 2 つのテストを実行しました (ファイル サイズと形式は類似しています)。結果は同じです。ですから、これは間違いなく再現できます。
しかし、これは意味がないと思います。何か見逃しましたか？これが本当なら、根本的な原因は何ですか？
----------その他のデバッグ-----------------
GCとパーマサイズ
-Xmx2432m -Xms256m -XX:MaxNewSize=700m -XX:MaxPermSize=1024m -XX:+PrintGCDetails両方のテストに追加されました。すべて PSYoungGen GC を持っているだけです。そして性能はどちらも同じです。
出力の詳細
ロング CP 1:
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;
}
}
}
実行してEnterキーを押しても、パフォーマンスは変わりません。