分享程序员开发的那些事...
更新时间：2023-01-18 17:42:24
具体来说，文件的顺序加载可能充分利用操作系统磁盘控制器缓存和预读。每次在读取不同文件的两个线程之间存在上下文切换时，多个文件的并行加载可能会使磁盘缓存无效，这可能是非常低效的，这取决于所涉及的确切参数，例如磁盘高速缓存大小，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:
My Main Question is: What caused such vast difference? I have already tried the following:
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.