7
Kiểm tra Code:Java tập tin hiệu suất IO giảm hơn 30% khi thêm nhiều lọ vào classpath
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());
}
}
}
thử nghiệm Env: Hệ điều hành: Linux, File Size: 7.2G (file văn bản csv, hơn 1k mỗi dòng), phiên bản java "1.6.0_32"
Test Run:
mã này được đóng gói vào một jar. Tôi chạy theo hai thử nghiệm trên cùng một máy chủ, sử dụng cùng một cái lọ, đọc cùng một tệp.
1) Chạy ./java -cp=my.jar ReadLine TestFile.txt Hiệu suất ổn định ở khoảng 150k dòng/s.
điều khiển đầu ra giống như:
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) Không có thay đổi mã, lọ chỉ gia tăng (sử dụng trong môi trường sản xuất) vào classpath (cần thiết trong sản xuất, nhưng không phải nó chương trình này), như ./java -cp=my.jar:hundreds_of_other_jars ReadLine TestFile.txt. Việc thực hiện giảm xuống còn khoảng 90k dòng/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
phân tích của tôi:
Sự khác biệt duy nhất là classpath. Đường dẫn lớp của bài kiểm tra thứ hai có hàng trăm JAR trong classpath. Nhưng không ai trong số họ được sử dụng trong chương trình này.
- Không liên quan đến môi trường. Mã này được đóng gói vào JAR và cả hai thử nghiệm đều sử dụng cùng một JAR. Cả hai thử nghiệm chạy trên cùng một máy chủ, đọc cùng một tệp, sử dụng cùng một mã. Tôi cũng so sánh System.getEnv và System.getProperties, không có sự khác biệt nào ngoài classpath.
- Không phải bộ nhớ cache của hệ điều hành. Điều này có thể được sao chép. Sau nhiều lần kiểm tra, kết quả là như nhau. Không có vấn đề mà thử nghiệm chạy đầu tiên.
- jmap cho thấy việc sử dụng bộ nhớ không có sự khác biệt lớn và tất cả các thế hệ không được sử dụng nhiều.
- jstack cho thấy các cuộc gọi stack cho cả thử nghiệm là nhiều khả năng được như
này
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)
hoặc
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)
Nhìn vào các cuộc gọi stack những trường hợp thử nghiệm có khả năng sử dụng cùng một mã.
- Điều này không được gây ra bởi một JAR nhất định trong đường dẫn lớp. Tôi đã cố gắng để loại bỏ 50% đầu tiên của classpath để chạy thử nghiệm, hiệu suất là khoảng 110k line/s. Sau đó, tôi loại bỏ 50% cuối cùng để chạy thử nghiệm, hiệu suất cũng là khoảng 110k dòng/s. Nếu loại bỏ hơn 2/3 lọ từ classpath, hiệu suất là khoảng 120k line/s. Vì vậy, từ bài kiểm tra, vấn đề hiệu suất này chỉ liên quan đến bao nhiêu JAR nằm trong classpath.
- Sau đó, tôi đã cố gắng đóng gói tất cả các JAR này vào một JAR lớn. Đáng buồn là hiệu suất giảm từ 90k xuống 60k .... Vì vậy, để được chính xác, dựa trên thử nghiệm của tôi, hiệu suất giảm này là do có bao nhiêu lớp trong classpath.
- Tôi đã chạy hai thử nghiệm trên một máy khác với một tệp khác (kích thước và định dạng tệp tương tự), kết quả giống nhau. Vì vậy, điều này chắc chắn có thể được sao chép.
NHƯNG tôi nghĩ điều này không có ý nghĩa. Tôi đã bỏ lỡ bất cứ điều gì? Nếu điều này thực sự là đúng nguyên nhân gốc rễ là gì?
---------- More gỡ lỗi -----------------
GC và Perm Kích
gia tăng -Xmx2432m -Xms256m -XX:MaxNewSize=700m -XX:MaxPermSize=1024m -XX:+PrintGCDetails cho cả hai bài kiểm tra. Có tất cả chỉ có PSYoungGen GC. Và hiệu suất là như nhau cho cả hai.
Output Chi tiết
dài CP một:
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)
Một Jar 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 Initial
Tôi rất mong đợi này là nguyên nhân vì đây là hợp lý. Nhưng sau khi sử dụng mã sau:
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;
}
}
}
Chạy và nhấn vào thời gian chính, hiệu suất không thay đổi.
Tôi đã thử phiên bản java "1.6.0_37", nó có nhiều cải tiến. Đối với "rất nhiều lọ trong cp" một, tốc độ là 150k line/s. Và đối với "jar đơn trong cp", tốc độ là 180k line/s. Khoảng 20% hiệu suất giảm và vẫn có thể được sao chép, vẫn không làm cho sence cho tôi ... – DeepNightTwo
cũng có giá trị nhìn vào biểu đồ gc với jconsole hoặc một số công cụ tương tự. cố gắng tăng kích thước permgen, có thể nó được đầy đủ vì tất cả những lọ và gc liên tục cố gắng để làm sạch nó. –
Tôi tự hỏi liệu hệ thống IO vẫn đang bị đẩy trong quá trình khởi động JVM khi điểm chuẩn của bạn bắt đầu (ví dụ: bằng cách tìm kiếm danh sách dài các lọ và quét chúng); do đó JVM và điểm chuẩn của bạn đang cạnh tranh để truy cập tệp? Một cách để kiểm tra điều này là chạy điểm chuẩn của bạn hai hoặc ba lần, ngủ đủ lâu để bụi lắng xuống và sau đó thực hiện điểm chuẩn của bạn để loại bỏ các giá trị đầu tiên. –