本文介绍了JAVA I / O：使用BufferedReader顺序读取文件和并发读取文件之间意想不到的性能差异的处理方法，对大家解决问题具有一定的参考价值，需要的朋友们下面随着小编来一起学习吧！
问题描述
我基本上试图使用缓冲读取器加载6个大文件（平均每个文件500MB）。在一次运行中，我一个一个地加载了这些文件。另一方面，我并行加载文件。这两次运行所消耗的时间似乎有显着差异：$ ul
我的主要问题
- 我注意到，在打印出的GC详细信息中，程序的顺序运行具有较高的使用率的Eden空间，但OldGen的使用率较低（并且拥有更多的Full GC），而Parallel运行的情况正好相反。
- 因此，我尝试将-XX：NewRatio调整为较小的数字，最大堆大小通过-XMS和-XMS到2G，这也没有帮助。
- 如果这是由于争用I / O，是否有一些工具，我可以使用确认这一点？我目前使用VirtualVM，我可以做类的采样和分析CPU时间。但是我不知道是否有其他的工具可以用更清晰的方式来检查。
以下是简化的代码
b$ b
public class BufferedReaderConcurentPerfTest {
//并行或串行
public static boolean isParallel = true ;
public static boolean isToPrintInfo = true;
public static String ORIGINAL_LOG_DIR =.\\largeFiles;
public static void main（String args []）throws Exception {
long startTime = System.currentTimeMillis（）;
processFiles（）;
double totalProcessDuration =（System.currentTimeMillis（） - startTime）/（（double）1000）;
printInfo（TOTAL PROCESS TIME：+ totalProcessDuration +s）;
public static void processFiles（）
throws Exception {
File [] files = new File（ORIGINAL_LOG_DIR）.listFiles（）;
if（isParallel）{
ExecutorService fixThreadPoolES = Executors.newFixedThreadPool（files.length）;
List> handleLogfutures = new ArrayList>（）; （文件file：files）{
if（file.isFile（））{
//打印开始处理文件
printInfo （--START REPLAYING {File：+ file.getName（）+}）;
//提交一个Callable任务来重放文件
HandleLogFileTaskCallable handleLogFileTaskCallable = new HandleLogFileTaskCallable（file）;
handleLogfutures.add（fixThreadPoolES.submit（handleLogFileTaskCallable））;
}
}
gatherFileReplayResult（handleLogfutures）;
//等待终止
fixThreadPoolES.shutdown（）;
printInfo（Right after shutdown（））;
fixThreadPoolES.awaitTermination（Long.MAX_VALUE，TimeUnit.NANOSECONDS）;
printInfo（Right after awaitTermination（））; （文件file：files）{
if（file.isFile（））{
processLargeFile（file）;
} else {
$ b public static synchronized void gatherFileReplayResult（List> handleLogfutures）throws InterruptedException，ExecutionException {
for（Future结果：handleLogfutures）{
printInfo（Gather Result：+ result.get（））;
private static class HandleLogFileTaskCallable implements Callable {
File _file = null;
public HandleLogFileTaskCallable（final File file）{
_file = file;
$ b $ @Override
public String call（）throws Exception {
//处理日志文件的重放
字符串handleLogResult =--Process {+ _file.getName（）+}取了+ String.valueOf（replayFile（））+s;
返回handleLogResult;
public double replayFile（）throws Exception {
long startTime = System.currentTimeMillis（）;
processLargeFile（_file）;
double processDuration =（System.currentTimeMillis（） - startTime）/（（double）1000）;
printInfo（---- processLargeFile（）：{+ _file.getName（）+}：
+ processDuration +s）;
return processDuration;
$ b public static void processLargeFile（File largeFile）throws IOException {
long currStart = System.currentTimeMillis（）;
long currTime;
FileReader OriginalLogFileReader = null;
尝试{
OriginalLogFileReader = new FileReader（largeFile.getAbsolutePath（））;
catch（FileNotFoundException fne）{
throw new RuntimeException（fne）;
BufferedReader originalLogBuffReader = new BufferedReader（OriginalLogFileReader，（int）（largeFile.length（）/ 10））;
// - 记录Perf数据
currTime = System.currentTimeMillis（）;
long initBufferReaderDuration = currTime - currStart;
currStart = currTime;
printInfo（---- Time Init BufferReader for：{+ largeFile.getName（）+}：
+ initBufferReaderDuration /（double）1000 +s）;
//开始读取原始日志文件
String logLine = originalLogBuffReader.readLine（）;
// - 记录Perf数据
currTime = System.currentTimeMillis（）;
long readFirstLineDuration = currTime - currStart;
currStart = currTime;
printInfo（----读取第一行：{+ largeFile.getName（）+}：
+ readFirstLineDuration /（double）1000 +s）;
int numLines = 0;
long bufferReadLineDurationTotal = 0;
while（logLine！= null）{
currStart = System.currentTimeMillis（）;
//读取下一行
logLine = originalLogBuffReader.readLine（）;
numLines ++;
// - 累计Perf数据
currTime = System.currentTimeMillis（）;
bufferReadLineDurationTotal + = currTime - currStart;
currStart = currTime;
}
- 记录Perf数据
printInfo（---- Total Time Reading：{+ largeFile.getName（）+}：
+ bufferReadLineDurationTotal /（double）1000 +s
+; Read Lines：+ numLines）;
//完成读取原始日志文件
originalLogBuffReader.close（）;
// - 记录Perf数据
currTime = System.currentTimeMillis（）;
long closeBuffReaderDuration = currTime - currStart;
currStart = currTime;
printInfo（----关闭BufferedReader的时间为：{+ largeFile.getName（）+}：
+ closeBuffReaderDuration /（double）1000 +s）;
$ b $ public static void printInfo（String infoStr）{
if（isToPrintInfo）{
String outStr =########程序输出： {+ Thread.currentThread（）。getName（）+}+ infoStr;
System.out.println（outStr）;
$ b $ hr
顺序运行的GC和程序输出：
###### ## Program Output：{main} ---- Time Init BufferReader for：{File-2014-09-02.log}：0.02s
########程序输出：{main} - ---时间阅读第一行：{File-2014-09-02.log}：1.388s
1.791：[GC [PSYoungGen：32256K-> 400K（37632K）] 96663K-> 64807K（123712K）， 0.0083754秒] [时间：用户= 0.00 sys = 0.00，实际= 0.01秒]
1.814：[GC [PSYoungGen：32656K-> 224K（37632K）] 97063K-> 64631K（123712K），0.0005777秒] ：user = 0.00 sys = 0.00，real = 0.00 secs]
2.211：[GC [PSYoungGen：32480K-> 192K（37632K）] 96887K-> 64599K（123712K），0.0013634秒] [Times：user = = 0.00，实际= 0.00秒]
2.226：[GC [PSYoungGen：32448K-> 208K（69888K）] 96855K-> 64615K（155968K），0.0004087秒] [时间：用户= 0.00 sys = 0.00， 0.00秒]
2.541：[GC [PSYoungGen：64720K-> 176K（69888K）] 1 29127K-> 64583K（155968K），0.0006677秒] [时间：用户= 0.00SYS = 0.00，实际= 0.00秒]
2.924：[GC [PSYoungGen：64688K-> 192K（129472K）] 129095K-> 64599K （时间：用户= 0.03sys = 0.00，实际= 0.01秒）
3.748：[GC [PSYoungGen：129216K-> 64K（129472K）] 193623K-> 64631K（215552K），0.0007187秒用户= 0.00 sys = 0.00，real = 0.00秒]
4.513：[GC [PSYoungGen：129088K-> 96K（124032K）] 193655K-> 64663K（210112K），0.0005527秒] [Times：user = 0.00Sys = 0.00，实际= 0.00秒]
5.234：[GC [PSYoungGen：124000K-> 32K（119104K）] 188567K-> 64599K（205184K），0.0005023秒] [时间：用户= 0.06 sys = 0.00 ，实数= 0.00秒]
########程序输出：{main} ----总时间读数：{File-2014-09-02.log}：3.517s;读取行数：825157
########程序输出：{main} ----关闭BufferedReader的时间：{File-2014-09-02.log}：0.0010s
########程序输出：{main} ----时间Init BufferReader用于：{File-2014-09-03.log}：0.0030s
########程序输出：{main} ----时间读第一行：{File-2014-09-03.log}：0.317s
5.611：[GC [PSYoungGen：119072K-> 160K（190656K）] 183639K- >全部GC [PSYoungGen：160K-> 0K（190656K）] [PSOldGen：114131K-> 114291K（326336K），0.0254198秒] [时间：用户= 0.06 sys = 0.00，实际= 0.03秒] $ gt; 49705K（117440K）] 114291K-> 49705K（308096K）[PSPermGen：2724K-> 2724K（21248K）]，0.0454966秒] [时间：用户= 0.00 sys = 0.00，实际= 0.05秒]
6.783：[GC [PSYoungGen：190464K-> 96K（257856K）] 240169K-> 49801K（375296K），0.0005805秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
7.935：[GC [PSYoungGen：257504K- > 64K（266688K）] 307209K-> 49777K（384128K），0.0005826秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
######## Pr输出：{main} ----总时间读数：{File-2014-09-03.log}：2.587s;读取行数：665049
########程序输出：{main} ----关闭BufferedReader的时间：{File-2014-09-03.log}：0.0s
########程序输出：{main} ----时间Init BufferReader用于：{File-2014-09-04.log}：0.0030s
########程序输出：{main} ----时间读第一行：{File-2014-09-04.log}：0.315s
9.139：[GC [PSYoungGen：266304K-> 128K（266624K）] 316017K- > 100888K（384064K），0.0078761秒] [时间：用户= 0.00 sys = 0.00，实际= 0.01秒]
9.147：[Full GC [PSYoungGen：128K-> 0K（266624K）] [PSOldGen：100760K->
10.564：[GC：51188K（148160K）] 100888K-> 51188K（414784K）[PSPermGen：2725K-> 2725K（21248K）]，0.0104032秒] [时间：用户= 0.02 sys = 0.00，实际= 0.01秒] [PSYoungGen：266240K-> 64K（357184K）] 317428K-> 51252K（505344K），0.0005645秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
########程序输出：{main} ----总时间读数：{File-2014-09-04.log}：2.519s;读取行数：690290
########程序输出：{main} ----关闭BufferedReader的时间：{File-2014-09-04.log}：0.0s
########程序输出：{main} ----时间Init BufferReader用于：{File-2014-09-08.log}：0.0030s
########程序输出：{main} ----时间读第一行：{File-2014-09-08.log}：0.305s
12.190：[GC [PSYoungGen：356864K-> 160K（357184K）] 408052K- > 1009636K-> 101096K（505344K），0.0080207秒] [时间：用户= 0.06 sys = 0.00，实际= 0.01秒]
12.198：[Full GC [PSYoungGen：160K-> 0K（357184K）] [PSOldGen：100936K->
#### [％] = [0096]（其中，用户= 0.02 sys = 0.00，实际= 0.01秒）
#### ####程序输出：{main} ----总时间读数：{File-2014-09-08.log}：1.581s;读取行数：665277
########程序输出：{main} ----关闭BufferedReader的时间：{File-2014-09-08.log}：0.0s
12.979：[GC [PSYoungGen：346295K-> 128K（470656K）] 396170K-> 50002K（643008K），0.0003402秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
##### ###程序输出：{main} ----时间Init BufferReader用于：{File-2014-09-10.log}：0.0040s
########程序输出：{main} ----读取第一行：{File-2014-09-10.log}：0.069s
13.794：[GC [PSYoungGen：470656K-> 96K（478144K）] 520530K-> 96079K（650496K） ，0.0074520秒] [时间：用户= 0.06 sys = 0.00，实际= 0.01秒]
########程序输出：{main} ----读取的总时间：{File-2014- 09-10.log}：0.829s;读取行数：628732
########程序输出：{main} ----关闭BufferedReader的时间：{File-2014-09-10.log}：0.0010s
########程序输出：{main} ----时间Init BufferReader用于：{File-2014-09-11.log}：0.0030s
########程序输出：{main} ----时间读取第一行：{File-2014-09-11.log}：0.079s
14.597：[GC [PSYoungGen：477856K-> 96K（577216K）] 573839K- > 149576K（749568K），0.0190215秒] [时间：用户= 0.03 sys = 0.03，实际= 0.02秒]
14.616：[Full GC [PSYoungGen：96K-> 0K（577216K）] [PSOldGen：149480K->
#### 53640K（208064K）] 149576K-> 53640K（785280K）[PSPermGen：2728K-> 2728K ####程序输出：{main} ----总时间读数：{File-2014-09-11.log}：0.955s;读取行数：900463
########程序输出：{main} ----关闭BufferedReader的时间：{File-2014-09-11.log}：0.0s
########程序输出：{main}总进程时间：14.634s
堆
PSYoungGen总计577216K，使用234148K [0x00000007d5f60000，0x00000007fb250000，0x0000000800000000）
eden space 576896K， 40％使用[0x00000007d5f60000,0x00000007e4409098,0x00000007f92c0000）从空间320K使用
，使用0％[0x00000007f9310000,0x00000007f9310000,0x00000007f9360000）
到空间320K，使用0％[0x00000007f92c0000,0x00000007f92c0000,0x00000007f9310000）
PSOldGen总计208064K，使用53640K [0x0000000781e00000,0x000000078e930000,0x00000007d5f60000）
对象空间208064K，使用25％[0x0000000781e00000,0x00000007852622d8,0x000000078e930000）
PSPermGen总计21248K，使用2736K [0x000000077cc00000,0x000000077e0c0000,0x0000000781e00000）
对象空间21248K，使用12％[0x000000077cc00000， 0x000000077ceac088,0x000000077e0c0000）
并行运行的GC和程序输出：
########程序输出：{main} --START REPLAYING {File：File-2014 -09-02.log}
########程序输出：{main} --START REPLAYING {File：File-2014-09-03.log}
#### ####程序输出：{main} --START REPLAYING {File：File-2014-09-04.log}
########程序输出：{main} --START REPLAYING {文件：File-2014-09-08.log}
########程序输出：{main} --START REPLAYING {File：File-2014-09-10.log}
########程序输出：{main} --START REPLAYING {File：File-2014-09-11.log}
########程序输出：{pool- 1-thread-4} ----时间Init BufferReader用于：{File-2014-09-08.log}：0.041s
########程序输出：{pool-1-thread -2} ---- Init Init BufferReader for：{File-2014-09-03.log}：0.055s
########程序输出：{pool-1-thread-3} ----时间Init BufferReader用于：{File -2014-09-04.log}：0.054s
########程序输出：{pool-1-thread-5} ----时间Init BufferReader for：{File-2014- 09-10.log} 0.043s
########程序输出：{pool-1-thread-6} ----时间Init BufferReader for：{File-2014-09-11 .log}：0.045s
########程序输出：{pool-1-thread-1} ----时间Init BufferReader for：{File-2014-09-02.log} ：0.068s
########程序输出：{pool-1-thread-3} ----时间读取第一行：{File-2014-09-04.log}：7.173 s
7.478：[GC [PSYoungGen：32256K-> 336K（37632K）] 346588K-> 314668K（373824K），0.0011522秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
########程序输出：{pool-1-thread-6} ----读取第一行：{File-2014-09-11.log}：9.678s
9.947： [GC [PSYoungGen：32592K-> 288K（37632K）] 346924K-> 314620K（373824K），0.0014428秒] [时间：用户= 0.00 SYS = 0.00，真= 0.00秒]
9.980：[GC [PSYoungGen： 32544K-> 224K（37632K）] 346876K-> 314556K（373824K），0.0020556秒] [次数：用户= 0.00 sys = 0.0 0，real = 0.00 secs]
########程序输出：{pool-1-thread-5} ----时间读取第一行：{File-2014-09-10。日志}：11.273s
11.538：[GC [PSYoungGen：32480K-> 240K（69888K）] 346812K-> 314572K（406080K），0.0014329secs] [times：user = 0.05sys = 0.00，real = 0.00secs]
########程序输出：{pool-1-thread-1} ----时间读取第一行：{File-2014-09-02.log}：11.821s
12.119：[GC [PSYoungGen：64752K-> 240K（69888K）] 379084K-> 314572K（406080K），0.0016242秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
18.125： GC [PSYoungGen：64752K-> 224K（62656K）] 379084K-> 314556K（398848K），0.0017085秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
18.235：[GC [PSYoungGen：62624K - > 64K（60416K）] 376956K-> 314612K（396608K），0.0015684秒] [时间：用户= 0.00 SYS = 0.00，真= 0.00秒]
20.149：[GC [PSYoungGen：60416K-> 32K（58496K ）] 374964K-> 314580K（394688K），0.0014622秒] [Times：user = 0.01 sys = 0.02，real = 0.00 secs]
########程序输出：{p ool-1-thread-4} ----读取第一行：{File-2014-09-08.log}：25.276s
25.555：[GC [PSYoungGen：58464K-> 32K（57024K） 373012K-> 314588K（393216K），0.0013281秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
26.241：[GC [PSYoungGen：56608K-> 32K（54848K）] 371164K-> 314608K （391040K），0.0017878秒] [Times：user = 0.00 sys = 0.00，real = 0.00 secs]
########程序输出：{pool-1-thread-2} ----时间阅读第一行：{File-2014-09-03.log}：27.289s
27.577：[GC [PSYoungGen：54816K-> 64K（53568K）] 369392K-> 314656K（389760K），0.0015123秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
27.817：[GC [PSYoungGen：53184K-> 32K（51584K）] 367776K-> 314632K（387776K），0.0008322秒] 0.00 sys = 0.00，real = 0.00 secs]
28.787：[GC [PSYoungGen：51552K-> 64K（50432K）] 366152K-> 314694K（386624K），0.0013182 secs]实际= 0.00秒]
31.020：[GC [PSYoungGen：50048K-> 32K（48576K）] 364678K-> 314678K（384768K），0.0010936秒s] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
31.041：[GC [PSYoungGen：48544K-> 32K（78080K）] 363190K-> 314694K（414272K），0.0034260秒]用户= 0.00 sys = 0.00，real = 0.00秒]
32.105：[GC [PSYoungGen：77664K-> 64K（124288K）] 392326K-> 314734K（460480K），0.0010284秒] 0.00 =实际= 0.00秒]
32.841：[GC [PSYoungGen：124288K-> 128K（127296K）] 438958K-> 314834K（463488K），0.0010359秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
40.904：[GC [PSYoungGen：127040K-> 32K（174336K）] 441746K-> 314746K（510528K），0.0020523秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
50.823：[GC [PSYoungGen：173984K-> 32K（174336K）] 488698K-> 314762K（510528K），0.0015654秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
56.807：[GC [PSYoungGen：173984K-> 64K（166720K）] 488714K-> 314826K（502912K），0.0016695秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
60.568：[GC [PSYoungGen：166720K- > 32K（160000K）] 481482K-> 314802K（496192K）， 0.0014042秒] [时间：用户= 0.00 SYS = 0.00，真= 0.00秒]
66.389：[GC [PSYoungGen：159712K-> 32K（153152K）] 474482K-> 314810K（489344K），0.0013505秒] [时报：用户= 0.00 SYS = 0.00，真= 0.00秒]
69.967：[GC [PSYoungGen：153120K-> 96K（147136K）] 467898K-> 314890K（483328K），0.0010909秒] [时间：用户= 0.00 SYS = 0.00，实际= 0.00秒]
74.727：[GC [PSYoungGen：146912K-> 64K（140864K）] 461706K-> 314874K（477056K），0.0016454秒] [时间：用户= 0.00 sys = 0.00， 0.00秒]] [时间：用户= 0.05sys = 0.01，实际= 0.00秒] $ b $ 78.912：[GC [PSYoungGen：140864K-> 96K（135360K）] 455674K-> 314930K（471552K）0.0013360秒$ b ########程序输出：{pool-1-thread-6} ----读取总时间：{File-2014-09-11.log}：69.007s;读取行数：900463
########程序输出：{pool-1-thread-6} ----关闭BufferedReader的时间：{File-2014-09-11.log}： 0.0010s
########程序输出：{pool-1-thread-6} ---- processLargeFile（）：{File-2014-09-11.log}：78.745s
83.932：[GC [PSYoungGen：135200K-> 64K（129728K）] 450034K-> 314906K（465920K），0.0018301秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
84.674： GC [PSYoungGen：129728K-> 32K（124736K）] 444570K-> 314898K（460928K），0.0013459秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
92.935：[GC [PSYoungGen：124512K - > 64K（119616K）] 439378K-> 314954K（455808K），0.0009738秒] [时间：用户= 0.00 SYS = 0.00，真= 0.00秒]
97.849：[GC [PSYoungGen：119616K-> 32K（115136K ）] 434506K-> 314930K（451328K），0.0013103秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
106.123：[GC [PSYoungGen：114912K-> 64K（110464K）] 429810K-> 314970K（446656K），0.0007003秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
112.326：[GC [PSYo用户= 0.00系统= 0.00，实际= 0.00秒]
112.444：[GC [PSYoungGen：106208K-> 32K（106432K）] 425370K-> 314954K（442624K），0.0015029秒]程序输出：{pool-1，32K（102208K）] 421130K-> 314962K（438400K），0.0009638 secs] [times：user = 0.00 sys = 0.00，real = 0.00 secs]
######## -thread-4} ----阅读时间总计：{File-2014-09-08.log}：88.921s;读取行数：665277
########程序输出：{pool-1-thread-4} ----关闭BufferedReader的时间：{File-2014-09-08.log}： 0.0010s
########程序输出：{pool-1-thread-4} ---- processLargeFile（）：{File-2014-09-08.log}：114.258s
116.242：[GC [PSYoungGen：102176K-> 96K（98496K）] 417106K-> 315042K（434688K），0.0018944秒] [时间：用户= 0.03 sys = 0.00，实际= 0.00秒]
### #####程序输出：{pool-1-thread-5} ----总读时间：{File-2014-09-10.log}：104.703s;读取行数：628732
########程序输出：{pool-1-thread-5} ----关闭BufferedReader的时间：{File-2014-09-10.log}： 0.0010s
########程序输出：{pool-1-thread-5} ---- processLargeFile（）：{File-2014-09-10.log}：116.039s
########程序输出：{pool-1-thread-2} ----读取总时间：{File-2014-09-03.log}：91.134s;读取行数：665049
########程序输出：{pool-1-thread-2} ----关闭BufferedReader的时间：{File-2014-09-03.log}： 0.0010s
########程序输出：{pool-1-thread-2} ---- processLargeFile（）：{File-2014-09-03.log}：118.497s
119.999：[GC [PSYoungGen：98400K-> 32K（94720K）] 413346K-> 314986K（430912K），0.0008738秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
### #####程序输出：{pool-1-thread-3} ----读取总时间：{File-2014-09-04.log}：112.568s;读取行数：690290
########程序输出：{pool-1-thread-3} ----关闭BufferedReader的时间：{File-2014-09-04.log}： 0.0s
########程序输出：{pool-1-thread-3} ---- processLargeFile（）：{File-2014-09-04.log}：119.813s
120.410：[GC [PSYoungGen：94688K-> 96K（91328K）] 409642K-> 315066K（427520K），0.0007063秒] [时间：用户= 0.00 sys = 0.00，实际= 0.00秒]
### #####程序输出：{pool-1-thread-1} ----总读时间：{File-2014-09-02.log}：108.343s;读取行数：825157
########程序输出：{pool-1-thread-1} ----关闭BufferedReader的时间：{File-2014-09-02.log}： 0.0010s
########程序输出：{pool-1-thread-1} ---- processLargeFile（）：{File-2014-09-02.log}：120.243s
########程序输出：{main}收集结果： - 进程{File-2014-09-02.log}花了120.243s
########程序输出：{main}收集结果： - 进程{File-2014-09-03.log}花了118.497s
########程序输出：{main}收集结果：--Process {File -2014-09-04.log}花了119.813s
########程序输出：{main}收集结果： - 进程{File-2014-09-08.log}花了114.258s
########程序输出：{main}收集结果： - 进程{File-2014-09-10.log}花了116.039s
########程序输出：{main}收集结果： - 进程{File-2014-09-11.log}花了78.745s
########程序输出：{main} b $ b ########程序输出：{main}在awaitTermina之后灰（）
########程序输出：{主}总处理时间：120.317s
堆
PSYoungGen总91328K，58978K使用[0x00000007d5f60000，0x00000007e4c60000，0x0000000800000000）
eden space 91136K，使用了64％[0x00000007d5f60000,0x00000007d98e0a18,0x00000007db860000）
从空间192K，使用了50％[0x00000007e4c00000,0x00000007e4c18000,0x00000007e4c30000）
到空间192K，使用了0％[0x00000007e4c30000,0x00000007e4c30000 ，0x00000007e4c60000）
PSOldGen总计336192K，使用314970K [0x0000000781e00000,0x0000000796650000,0x00000007d5f60000）
对象空间336192K，使用93％[0x0000000781e00000,0x0000000795196808,0x0000000796650000）
PSPermGen总计21248K，使用2934K [0x000000077cc00000 ，0x000000077e0c0000，0x0000000781e00000）
对象空间21248K，使用13％[0x000000077cc00000,0x000000077cedd928,0x000000077e0c0000）
一些默认参数设置为JVM打印出来
uintx InitialHeapSize = 132154176 {product}
uintx MaxGCPauseMillis = 4294967295 {product}
uintx MaxHeapFreeRatio = 70 {产物}
uintx MaxHeapSize：= 2116026368 {产物}
布尔UseConcMarkSweepGC =假{产物}
布尔UseParNewGC =假{产物}
布尔UseParallelGC：= true {product}
bool UseParallelOldGC = false {product}
bool UseParallelOldGCCompacting = true {product}
bool UseParNewGC = false {product}
计算机详细信息：
64位，i7-370 @ 3.4ghz，8-core，8g memo，NTFS with 137gb Free Space
解决方案
具体来说，文件的顺序加载可能充分利用操作系统磁盘控制器缓存和预读。每次在读取不同文件的两个线程之间存在上下文切换时，多个文件的并行加载可能会使磁盘缓存无效，这可能是非常低效的，这取决于所涉及的确切参数，例如磁盘高速缓存大小，VM中的缓冲区大小等。 / p>
注意这个结果是依赖于系统的;在不同的磁盘控制器和不同的磁盘配置或RAID配置的机器上，你可能会发现相反的结果，并发的文件读取效率更高。
最后，我会注意到，在Eclipse中进行性能测试可能不是一个好主意，除非你真的要在生产环境中从Eclipse中运行代码。
I basically trying to load 6 large file (500MB per file on average) using buffered reader. In one run, I loaded the files one by one; In the other run, I loaded the files in parallel. There appeared to be a significant difference in term of time consumed by the two runs:
- Sequential Run: 14.634s
- Parallel Run: 120.317s
- NOTE that this difference shows up clearly on the 1st time reading these files into the JVM. In subsequent reads, duration shortens significantly, which I assume is due to caching. Therefore, I recreate these files (e.g. delete them under the current dir and copy them from somewhere to the current dir again) before I ran two independent Eclipse instances (I also tried ran them as two runnable jars from cmd line, same result).
- Sub-question: Is there a way to eliminate this caching effect to stop it affecting my experiment before I do the run? e.g. In windows, I deleted all the Java temp files through Control Panel -> Java -> Settings -> Delete Files ... as well as doing something like this to clear windows cache
My Main Question is: What caused such vast difference? I have already tried the following:
- I notice that as in the GC details printed out, the Sequential run of the program has a high usage of Eden space but low usage of OldGen (and had more Full GCs), while the opposite is true to the Parallel run.
- Therefore I tried to adjust the -XX:NewRatio to a lower number but it didn't help.
- Then I increased both the min and max heap size via -Xms and -Xms to 2g, which didn't help either.
- If this is due to contention for I/O, is there some tool that I can use to confirm this? I currently use VirtualVM which I can do Sampling and Profiling of the CPU time for classes. But I wonder if there is some other tool to check this in a clearer way.
Following are the simplified code
public class BufferedReaderConcurentPerfTest {
// Parallel or Serial
public static boolean isParallel = true;
public static boolean isToPrintInfo = true;
public static String ORIGINAL_LOG_DIR = ".\\largeFiles";
public static void main(String args[]) throws Exception {
long startTime = System.currentTimeMillis();
processFiles();
double totalProcessDuration = (System.currentTimeMillis() - startTime) / ((double) 1000);
printInfo("TOTAL PROCESS TIME:" + totalProcessDuration + "s");
}
public static void processFiles()
throws Exception {
File[] files = new File(ORIGINAL_LOG_DIR).listFiles();
if (isParallel){
ExecutorService fixThreadPoolES = Executors.newFixedThreadPool(files.length);
List> handleLogfutures = new ArrayList>();
for(File file : files){
if(file.isFile()){
// Print Start of Processing the file
printInfo("--START REPLAYING {File: " + file.getName() + "}");
// Submit a Callable task to Replay the file
HandleLogFileTaskCallable handleLogFileTaskCallable = new HandleLogFileTaskCallable(file);
handleLogfutures.add(fixThreadPoolES.submit(handleLogFileTaskCallable));
}
}
gatherFileReplayResult(handleLogfutures);
// wait for termination
fixThreadPoolES.shutdown();
printInfo("Right After shutdown()");
fixThreadPoolES.awaitTermination(Long.MAX_VALUE, TimeUnit.NANOSECONDS);
printInfo("Right After awaitTermination()");
} else {
for(File file : files){
if(file.isFile()){
processLargeFile(file);
}
}
}
}
public static synchronized void gatherFileReplayResult(List> handleLogfutures) throws InterruptedException, ExecutionException{
for(Future result: handleLogfutures){
printInfo("Gathered Result: " + result.get());
}
}
private static class HandleLogFileTaskCallable implements Callable {
File _file = null;
public HandleLogFileTaskCallable (final File file){
_file = file;
}
@Override
public String call() throws Exception {
// Handle the Replay of a log file
String handleLogResult = "--Process {" + _file.getName() + "} took " + String.valueOf(replayFile()) + "s";
return handleLogResult;
}
public double replayFile() throws Exception {
long startTime = System.currentTimeMillis();
processLargeFile(_file);
double processDuration = (System.currentTimeMillis() - startTime) / ((double) 1000);
printInfo("----processLargeFile(): {" + _file.getName() + "}: "
+ processDuration + "s");
return processDuration;
}
}
public static void processLargeFile(File largeFile) throws IOException {
long currStart = System.currentTimeMillis();
long currTime;
FileReader OriginalLogFileReader = null;
try {
OriginalLogFileReader = new FileReader(largeFile.getAbsolutePath());
}
catch (FileNotFoundException fne) {
throw new RuntimeException(fne);
}
BufferedReader originalLogBuffReader = new BufferedReader(OriginalLogFileReader, (int) (largeFile.length() / 10) );
// - Record Perf Data
currTime = System.currentTimeMillis();
long initBufferReaderDuration = currTime - currStart;
currStart = currTime;
printInfo("----Time Init BufferReader for: {" + largeFile.getName() + "}: "
+ initBufferReaderDuration / (double) 1000 + "s");
// Start reading the original log file
String logLine = originalLogBuffReader.readLine();
// - Record Perf Data
currTime = System.currentTimeMillis();
long readFirstLineDuration = currTime - currStart;
currStart = currTime;
printInfo("----Time Reading 1st line of: {" + largeFile.getName() + "}: "
+ readFirstLineDuration / (double) 1000 + "s");
int numLines = 0;
long bufferReadLineDurationTotal = 0;
while (logLine != null){
currStart = System.currentTimeMillis();
// Read the next line
logLine = originalLogBuffReader.readLine();
numLines++;
// - Accumulate Perf Data
currTime = System.currentTimeMillis();
bufferReadLineDurationTotal += currTime - currStart;
currStart = currTime;
}
// - Record Perf Data
printInfo("----Total Time Reading: {" + largeFile.getName() + "}: "
+ bufferReadLineDurationTotal / (double) 1000 + "s"
+ "; Read Lines: " + numLines);
// Completed reading the original log file
originalLogBuffReader.close();
// - Record Perf Data
currTime = System.currentTimeMillis();
long closeBuffReaderDuration = currTime - currStart;
currStart = currTime;
printInfo("----Time to close BufferedReader for: {" + largeFile.getName() + "}: "
+ closeBuffReaderDuration / (double) 1000 + "s");
}
public static void printInfo(String infoStr){
if (isToPrintInfo){
String outStr = "######## Program Output: {" + Thread.currentThread().getName() + "} " + infoStr;
System.out.println(outStr);
}
}
}
The GC and Program Outputs for Sequential Run:
######## Program Output: {main} ----Time Init BufferReader for: {File-2014-09-02.log}: 0.02s
######## Program Output: {main} ----Time Reading 1st line of: {File-2014-09-02.log}: 1.388s
1.791: [GC [PSYoungGen: 32256K->400K(37632K)] 96663K->64807K(123712K), 0.0083754 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
1.814: [GC [PSYoungGen: 32656K->224K(37632K)] 97063K->64631K(123712K), 0.0005777 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.211: [GC [PSYoungGen: 32480K->192K(37632K)] 96887K->64599K(123712K), 0.0013634 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.226: [GC [PSYoungGen: 32448K->208K(69888K)] 96855K->64615K(155968K), 0.0004087 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.541: [GC [PSYoungGen: 64720K->176K(69888K)] 129127K->64583K(155968K), 0.0006677 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.924: [GC [PSYoungGen: 64688K->192K(129472K)] 129095K->64599K(215552K), 0.0109592 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
3.748: [GC [PSYoungGen: 129216K->64K(129472K)] 193623K->64631K(215552K), 0.0007187 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
4.513: [GC [PSYoungGen: 129088K->96K(124032K)] 193655K->64663K(210112K), 0.0005527 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
5.234: [GC [PSYoungGen: 124000K->32K(119104K)] 188567K->64599K(205184K), 0.0005023 secs] [Times: user=0.06 sys=0.00, real=0.00 secs]
######## Program Output: {main} ----Total Time Reading: {File-2014-09-02.log}: 3.517s; Read Lines: 825157
######## Program Output: {main} ----Time to close BufferedReader for: {File-2014-09-02.log}: 0.0010s
######## Program Output: {main} ----Time Init BufferReader for: {File-2014-09-03.log}: 0.0030s
######## Program Output: {main} ----Time Reading 1st line of: {File-2014-09-03.log}: 0.317s
5.611: [GC [PSYoungGen: 119072K->160K(190656K)] 183639K->114291K(326336K), 0.0254198 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
5.637: [Full GC [PSYoungGen: 160K->0K(190656K)] [PSOldGen: 114131K->49705K(117440K)] 114291K->49705K(308096K) [PSPermGen: 2724K->2724K(21248K)], 0.0454966 secs] [Times: user=0.00 sys=0.00, real=0.05 secs]
6.783: [GC [PSYoungGen: 190464K->96K(257856K)] 240169K->49801K(375296K), 0.0005805 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
7.935: [GC [PSYoungGen: 257504K->64K(266688K)] 307209K->49777K(384128K), 0.0005826 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
######## Program Output: {main} ----Total Time Reading: {File-2014-09-03.log}: 2.587s; Read Lines: 665049
######## Program Output: {main} ----Time to close BufferedReader for: {File-2014-09-03.log}: 0.0s
######## Program Output: {main} ----Time Init BufferReader for: {File-2014-09-04.log}: 0.0030s
######## Program Output: {main} ----Time Reading 1st line of: {File-2014-09-04.log}: 0.315s
9.139: [GC [PSYoungGen: 266304K->128K(266624K)] 316017K->100888K(384064K), 0.0078761 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
9.147: [Full GC [PSYoungGen: 128K->0K(266624K)] [PSOldGen: 100760K->51188K(148160K)] 100888K->51188K(414784K) [PSPermGen: 2725K->2725K(21248K)], 0.0104032 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
10.564: [GC [PSYoungGen: 266240K->64K(357184K)] 317428K->51252K(505344K), 0.0005645 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
######## Program Output: {main} ----Total Time Reading: {File-2014-09-04.log}: 2.519s; Read Lines: 690290
######## Program Output: {main} ----Time to close BufferedReader for: {File-2014-09-04.log}: 0.0s
######## Program Output: {main} ----Time Init BufferReader for: {File-2014-09-08.log}: 0.0030s
######## Program Output: {main} ----Time Reading 1st line of: {File-2014-09-08.log}: 0.305s
12.190: [GC [PSYoungGen: 356864K->160K(357184K)] 408052K->101096K(505344K), 0.0080207 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
12.198: [Full GC [PSYoungGen: 160K->0K(357184K)] [PSOldGen: 100936K->49874K(172352K)] 101096K->49874K(529536K) [PSPermGen: 2728K->2728K(21248K)], 0.0108381 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
######## Program Output: {main} ----Total Time Reading: {File-2014-09-08.log}: 1.581s; Read Lines: 665277
######## Program Output: {main} ----Time to close BufferedReader for: {File-2014-09-08.log}: 0.0s
12.979: [GC [PSYoungGen: 346295K->128K(470656K)] 396170K->50002K(643008K), 0.0003402 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
######## Program Output: {main} ----Time Init BufferReader for: {File-2014-09-10.log}: 0.0040s
######## Program Output: {main} ----Time Reading 1st line of: {File-2014-09-10.log}: 0.069s
13.794: [GC [PSYoungGen: 470656K->96K(478144K)] 520530K->96079K(650496K), 0.0074520 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]
######## Program Output: {main} ----Total Time Reading: {File-2014-09-10.log}: 0.829s; Read Lines: 628732
######## Program Output: {main} ----Time to close BufferedReader for: {File-2014-09-10.log}: 0.0010s
######## Program Output: {main} ----Time Init BufferReader for: {File-2014-09-11.log}: 0.0030s
######## Program Output: {main} ----Time Reading 1st line of: {File-2014-09-11.log}: 0.079s
14.597: [GC [PSYoungGen: 477856K->96K(577216K)] 573839K->149576K(749568K), 0.0190215 secs] [Times: user=0.03 sys=0.03, real=0.02 secs]
14.616: [Full GC [PSYoungGen: 96K->0K(577216K)] [PSOldGen: 149480K->53640K(208064K)] 149576K->53640K(785280K) [PSPermGen: 2728K->2728K(21248K)], 0.0114346 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
######## Program Output: {main} ----Total Time Reading: {File-2014-09-11.log}: 0.955s; Read Lines: 900463
######## Program Output: {main} ----Time to close BufferedReader for: {File-2014-09-11.log}: 0.0s
######## Program Output: {main} TOTAL PROCESS TIME:14.634s
Heap
PSYoungGen total 577216K, used 234148K [0x00000007d5f60000, 0x00000007fb250000, 0x0000000800000000)
eden space 576896K, 40% used [0x00000007d5f60000,0x00000007e4409098,0x00000007f92c0000)
from space 320K, 0% used [0x00000007f9310000,0x00000007f9310000,0x00000007f9360000)
to space 320K, 0% used [0x00000007f92c0000,0x00000007f92c0000,0x00000007f9310000)
PSOldGen total 208064K, used 53640K [0x0000000781e00000, 0x000000078e930000, 0x00000007d5f60000)
object space 208064K, 25% used [0x0000000781e00000,0x00000007852622d8,0x000000078e930000)
PSPermGen total 21248K, used 2736K [0x000000077cc00000, 0x000000077e0c0000, 0x0000000781e00000)
object space 21248K, 12% used [0x000000077cc00000,0x000000077ceac088,0x000000077e0c0000)
GC and Program Outputs for the Parallel Run:
######## Program Output: {main} --START REPLAYING {File: File-2014-09-02.log}
######## Program Output: {main} --START REPLAYING {File: File-2014-09-03.log}
######## Program Output: {main} --START REPLAYING {File: File-2014-09-04.log}
######## Program Output: {main} --START REPLAYING {File: File-2014-09-08.log}
######## Program Output: {main} --START REPLAYING {File: File-2014-09-10.log}
######## Program Output: {main} --START REPLAYING {File: File-2014-09-11.log}
######## Program Output: {pool-1-thread-4} ----Time Init BufferReader for: {File-2014-09-08.log}: 0.041s
######## Program Output: {pool-1-thread-2} ----Time Init BufferReader for: {File-2014-09-03.log}: 0.055s
######## Program Output: {pool-1-thread-3} ----Time Init BufferReader for: {File-2014-09-04.log}: 0.054s
######## Program Output: {pool-1-thread-5} ----Time Init BufferReader for: {File-2014-09-10.log}: 0.043s
######## Program Output: {pool-1-thread-6} ----Time Init BufferReader for: {File-2014-09-11.log}: 0.045s
######## Program Output: {pool-1-thread-1} ----Time Init BufferReader for: {File-2014-09-02.log}: 0.068s
######## Program Output: {pool-1-thread-3} ----Time Reading 1st line of: {File-2014-09-04.log}: 7.173s
7.478: [GC [PSYoungGen: 32256K->336K(37632K)] 346588K->314668K(373824K), 0.0011522 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
######## Program Output: {pool-1-thread-6} ----Time Reading 1st line of: {File-2014-09-11.log}: 9.678s
9.947: [GC [PSYoungGen: 32592K->288K(37632K)] 346924K->314620K(373824K), 0.0014428 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
9.980: [GC [PSYoungGen: 32544K->224K(37632K)] 346876K->314556K(373824K), 0.0020556 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
######## Program Output: {pool-1-thread-5} ----Time Reading 1st line of: {File-2014-09-10.log}: 11.273s
11.538: [GC [PSYoungGen: 32480K->240K(69888K)] 346812K->314572K(406080K), 0.0014329 secs] [Times: user=0.05 sys=0.00, real=0.00 secs]
######## Program Output: {pool-1-thread-1} ----Time Reading 1st line of: {File-2014-09-02.log}: 11.821s
12.119: [GC [PSYoungGen: 64752K->240K(69888K)] 379084K->314572K(406080K), 0.0016242 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
18.125: [GC [PSYoungGen: 64752K->224K(62656K)] 379084K->314556K(398848K), 0.0017085 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
18.235: [GC [PSYoungGen: 62624K->64K(60416K)] 376956K->314612K(396608K), 0.0015684 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
20.149: [GC [PSYoungGen: 60416K->32K(58496K)] 374964K->314580K(394688K), 0.0014622 secs] [Times: user=0.01 sys=0.02, real=0.00 secs]
######## Program Output: {pool-1-thread-4} ----Time Reading 1st line of: {File-2014-09-08.log}: 25.276s
25.555: [GC [PSYoungGen: 58464K->32K(57024K)] 373012K->314588K(393216K), 0.0013281 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
26.241: [GC [PSYoungGen: 56608K->32K(54848K)] 371164K->314608K(391040K), 0.0017878 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
######## Program Output: {pool-1-thread-2} ----Time Reading 1st line of: {File-2014-09-03.log}: 27.289s
27.577: [GC [PSYoungGen: 54816K->64K(53568K)] 369392K->314656K(389760K), 0.0015123 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
27.817: [GC [PSYoungGen: 53184K->32K(51584K)] 367776K->314632K(387776K), 0.0008322 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
28.787: [GC [PSYoungGen: 51552K->64K(50432K)] 366152K->314694K(386624K), 0.0013182 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
31.020: [GC [PSYoungGen: 50048K->32K(48576K)] 364678K->314678K(384768K), 0.0010936 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
31.041: [GC [PSYoungGen: 48544K->32K(78080K)] 363190K->314694K(414272K), 0.0034260 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
32.105: [GC [PSYoungGen: 77664K->64K(124288K)] 392326K->314734K(460480K), 0.0010284 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
32.841: [GC [PSYoungGen: 124288K->128K(127296K)] 438958K->314834K(463488K), 0.0010359 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
40.904: [GC [PSYoungGen: 127040K->32K(174336K)] 441746K->314746K(510528K), 0.0020523 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
50.823: [GC [PSYoungGen: 173984K->32K(174336K)] 488698K->314762K(510528K), 0.0015654 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
56.807: [GC [PSYoungGen: 173984K->64K(166720K)] 488714K->314826K(502912K), 0.0016695 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
60.568: [GC [PSYoungGen: 166720K->32K(160000K)] 481482K->314802K(496192K), 0.0014042 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
66.389: [GC [PSYoungGen: 159712K->32K(153152K)] 474482K->314810K(489344K), 0.0013505 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
69.967: [GC [PSYoungGen: 153120K->96K(147136K)] 467898K->314890K(483328K), 0.0010909 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
74.727: [GC [PSYoungGen: 146912K->64K(140864K)] 461706K->314874K(477056K), 0.0016454 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
78.912: [GC [PSYoungGen: 140864K->96K(135360K)] 455674K->314930K(471552K), 0.0013360 secs] [Times: user=0.05 sys=0.01, real=0.00 secs]
######## Program Output: {pool-1-thread-6} ----Total Time Reading: {File-2014-09-11.log}: 69.007s; Read Lines: 900463
######## Program Output: {pool-1-thread-6} ----Time to close BufferedReader for: {File-2014-09-11.log}: 0.0010s
######## Program Output: {pool-1-thread-6} ----processLargeFile(): {File-2014-09-11.log}: 78.745s
83.932: [GC [PSYoungGen: 135200K->64K(129728K)] 450034K->314906K(465920K), 0.0018301 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
84.674: [GC [PSYoungGen: 129728K->32K(124736K)] 444570K->314898K(460928K), 0.0013459 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
92.935: [GC [PSYoungGen: 124512K->64K(119616K)] 439378K->314954K(455808K), 0.0009738 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
97.849: [GC [PSYoungGen: 119616K->32K(115136K)] 434506K->314930K(451328K), 0.0013103 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
106.123: [GC [PSYoungGen: 114912K->64K(110464K)] 429810K->314970K(446656K), 0.0007003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
112.326: [GC [PSYoungGen: 110464K->32K(106432K)] 425370K->314954K(442624K), 0.0015029 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
112.444: [GC [PSYoungGen: 106208K->32K(102208K)] 421130K->314962K(438400K), 0.0009638 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
######## Program Output: {pool-1-thread-4} ----Total Time Reading: {File-2014-09-08.log}: 88.921s; Read Lines: 665277
######## Program Output: {pool-1-thread-4} ----Time to close BufferedReader for: {File-2014-09-08.log}: 0.0010s
######## Program Output: {pool-1-thread-4} ----processLargeFile(): {File-2014-09-08.log}: 114.258s
116.242: [GC [PSYoungGen: 102176K->96K(98496K)] 417106K->315042K(434688K), 0.0018944 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
######## Program Output: {pool-1-thread-5} ----Total Time Reading: {File-2014-09-10.log}: 104.703s; Read Lines: 628732
######## Program Output: {pool-1-thread-5} ----Time to close BufferedReader for: {File-2014-09-10.log}: 0.0010s
######## Program Output: {pool-1-thread-5} ----processLargeFile(): {File-2014-09-10.log}: 116.039s
######## Program Output: {pool-1-thread-2} ----Total Time Reading: {File-2014-09-03.log}: 91.134s; Read Lines: 665049
######## Program Output: {pool-1-thread-2} ----Time to close BufferedReader for: {File-2014-09-03.log}: 0.0010s
######## Program Output: {pool-1-thread-2} ----processLargeFile(): {File-2014-09-03.log}: 118.497s
119.999: [GC [PSYoungGen: 98400K->32K(94720K)] 413346K->314986K(430912K), 0.0008738 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
######## Program Output: {pool-1-thread-3} ----Total Time Reading: {File-2014-09-04.log}: 112.568s; Read Lines: 690290
######## Program Output: {pool-1-thread-3} ----Time to close BufferedReader for: {File-2014-09-04.log}: 0.0s
######## Program Output: {pool-1-thread-3} ----processLargeFile(): {File-2014-09-04.log}: 119.813s
120.410: [GC [PSYoungGen: 94688K->96K(91328K)] 409642K->315066K(427520K), 0.0007063 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
######## Program Output: {pool-1-thread-1} ----Total Time Reading: {File-2014-09-02.log}: 108.343s; Read Lines: 825157
######## Program Output: {pool-1-thread-1} ----Time to close BufferedReader for: {File-2014-09-02.log}: 0.0010s
######## Program Output: {pool-1-thread-1} ----processLargeFile(): {File-2014-09-02.log}: 120.243s
######## Program Output: {main} Gathered Result: --Process {File-2014-09-02.log} took 120.243s
######## Program Output: {main} Gathered Result: --Process {File-2014-09-03.log} took 118.497s
######## Program Output: {main} Gathered Result: --Process {File-2014-09-04.log} took 119.813s
######## Program Output: {main} Gathered Result: --Process {File-2014-09-08.log} took 114.258s
######## Program Output: {main} Gathered Result: --Process {File-2014-09-10.log} took 116.039s
######## Program Output: {main} Gathered Result: --Process {File-2014-09-11.log} took 78.745s
######## Program Output: {main} Right After shutdown()
######## Program Output: {main} Right After awaitTermination()
######## Program Output: {main} TOTAL PROCESS TIME:120.317s
Heap
PSYoungGen total 91328K, used 58978K [0x00000007d5f60000, 0x00000007e4c60000, 0x0000000800000000)
eden space 91136K, 64% used [0x00000007d5f60000,0x00000007d98e0a18,0x00000007db860000)
from space 192K, 50% used [0x00000007e4c00000,0x00000007e4c18000,0x00000007e4c30000)
to space 192K, 0% used [0x00000007e4c30000,0x00000007e4c30000,0x00000007e4c60000)
PSOldGen total 336192K, used 314970K [0x0000000781e00000, 0x0000000796650000, 0x00000007d5f60000)
object space 336192K, 93% used [0x0000000781e00000,0x0000000795196808,0x0000000796650000)
PSPermGen total 21248K, used 2934K [0x000000077cc00000, 0x000000077e0c0000, 0x0000000781e00000)
object space 21248K, 13% used [0x000000077cc00000,0x000000077cedd928,0x000000077e0c0000)
Some default parameters setting for the JVM printed out
uintx InitialHeapSize := 132154176 {product}
uintx MaxGCPauseMillis = 4294967295 {product}
uintx MaxHeapFreeRatio = 70 {product}
uintx MaxHeapSize := 2116026368 {product}
bool UseConcMarkSweepGC = false {product}
bool UseParNewGC = false {product}
bool UseParallelGC := true {product}
bool UseParallelOldGC = false {product}
bool UseParallelOldGCCompacting = true {product}
bool UseParNewGC = false {product}
Computer Details:
64-bit, i7-370 @3.4ghz, 8-core, 8g memo, NTFS with 137gb Free Space
解决方案
The most likely reason for the difference likely has to do with caching in the operating system, rather than in the Java virtual machine.
Specifically, sequential load of the files likely takes full advantage of OS disk controller caching and read ahead. Concurrent loading of multiple files may invalidate the disk cache each time there is a context switch between two threads reading different files, which could be very inefficient depending on the exact parameters involved such as disk cache size, buffer size in the VM, etc.
Note that this result is system dependent; on a different machine with a different disk controller and a different disk configuration or RAID configuration, you might find the opposite result, with concurrent file reading being more efficient.
Finally, I would note that it's probably not a good idea to do performance testing from within Eclipse, unless you are actually going to run your code from within Eclipse in production.
这篇关于JAVA I / O：使用BufferedReader顺序读取文件和并发读取文件之间意想不到的性能差异的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持！