为何Java多线程I/O比单线程顺序执行更慢？

问题背景 #

在测试线程创建与并行处理时，遇到多线程代码比单线程顺序执行版本慢得多的异常情况。该代码用于统计文件中的单词数并求和。

单线程代码 #

import java.io.BufferedReader;
import java.io.FileReader;
import java.io.IOException;
import java.util.Arrays;

public class WordCount {

    public static int countWords(String filename) throws IOException {
        long startTime = System.currentTimeMillis();
        try (BufferedReader br = new BufferedReader(new FileReader(filename))) {
            int total = 0;
            for (String line = br.readLine(); line != null; line = br.readLine()) {
                total += line.split("\\s+").length;
            }
            System.out.println("Time for file "+filename+" : "+(System.currentTimeMillis()-startTime) + " ms for "+ total + " words");
            return total;
        }
    }
    
    public static void main(String[] args) {
        long startTime = System.currentTimeMillis();
        int [] wordCount = new int[args.length];
        for (int i = 0; i < args.length; i++) {
            try {
                wordCount[i] = countWords(args[i]);
            } catch (IOException e) {
                System.err.println("Error reading file: " + args[i]);
                e.printStackTrace();
            }
        }
        System.out.println("Word count:" + Arrays.toString(wordCount));
        int total = 0;
        for (int count : wordCount) {
            total += count;
        }
        System.out.println("Total word count:" + total);
        System.out.println("Total time "+(System.currentTimeMillis()-startTime) + " ms");
    }
}

多线程版本代码 #

import java.io.BufferedReader;
import java.io.FileReader;
import java.io.IOException;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.List;

public class WordCountMT {

    public static int countWords(String filename) throws IOException {
        // 与单线程版本实现一致
        long startTime = System.currentTimeMillis();
        try (BufferedReader br = new BufferedReader(new FileReader(filename))) {
            int total = 0;
            for (String line = br.readLine(); line != null; line = br.readLine()) {
                total += line.split("\\s+").length;
            }
            System.out.println("Time for file "+filename+" : "+(System.currentTimeMillis()-startTime) + " ms for "+ total + " words");
            return total;
        }
    }

    private static class CounterWorker implements Runnable {
        private String filename;
        private int index;
        private int[] wordCount;

        public CounterWorker(String filename, int index, int[] wordCount) {
            this.filename = filename;
            this.index = index;
            this.wordCount = wordCount;
        }

        @Override
        public void run() {
            try {
                wordCount[index] = countWords(filename);
            } catch (IOException e) {
                System.err.println("Error reading file: " + filename);
                e.printStackTrace();
            }
        }
    }

    public static void main(String[] args) {
        long startTime = System.currentTimeMillis();
        int[] wordCount = new int[args.length];
        List<Thread> th = new ArrayList<>();

        for (int i = 0; i < args.length; i++) {
            th.add(new Thread(new CounterWorker(args[i], i, wordCount)));
            th.get(i).start();
        }
        try {
            for (Thread t : th) {
                t.join();
            }
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

        System.out.println("Word count:" + Arrays.toString(wordCount));
        int total = 0;
        for (int count : wordCount) {
            total += count;
        }
        System.out.println("Total word count:" + total);
        
        System.out.println("Total time "+(System.currentTimeMillis()-startTime) + " ms");
    }
}

测试结果对比 #

单线程版本输出 #

Time for file /tmp/data/data6-5.txt : 14 ms for 1468 words
Time for file /tmp/data/data5-6.txt : 3 ms for 1468 words
Time for file /tmp/data/data5.txt : 1 ms for 390 words
Time for file /tmp/data/data5-5.txt : 1 ms for 780 words
Time for file /tmp/data/data7.txt : 1 ms for 1078 words
Time for file /tmp/data/data6.txt : 2 ms for 1078 words
Time for file /tmp/data/data6-6.txt : 2 ms for 2156 words
Time for file /tmp/data/data8.txt : 1 ms for 1078 words
Time for file /tmp/data/data3.txt : 0 ms for 390 words
Time for file /tmp/data/data6-7.txt : 1 ms for 2156 words
Time for file /tmp/data/data4.txt : 1 ms for 390 words
Time for file /tmp/data/data5-4.txt : 1 ms for 780 words
Time for file /tmp/data/data1.txt : 0 ms for 390 words
Time for file /tmp/data/data2.txt : 0 ms for 390 words
Time for file /tmp/data/data9.txt : 1 ms for 1078 words
Time for file /tmp/data/data5-7.txt : 0 ms for 1468 words
Time for file /tmp/data/data6-4.txt : 1 ms for 1468 words
Word count:[1468, 1468, 390, 780, 1078, 1078, 2156, 1078, 390, 2156, 390, 780, 390, 390, 1078, 1468, 1468]
Total word count:18006
Total time 54 ms

多线程版本输出 #

Time for file /tmp/data/data3.txt : 46 ms for 390 words
Time for file /tmp/data/data5-4.txt : 54 ms for 780 words
Time for file /tmp/data/data5-5.txt : 58 ms for 780 words
Time for file /tmp/data/data1.txt : 45 ms for 390 words
Time for file /tmp/data/data6-5.txt : 70 ms for 1468 words
Time for file /tmp/data/data5-7.txt : 68 ms for 1468 words
Time for file /tmp/data/data5.txt : 45 ms for 390 words
Time for file /tmp/data/data7.txt : 65 ms for 1078 words
Time for file /tmp/data/data2.txt : 43 ms for 390 words
Time for file /tmp/data/data6.txt : 64 ms for 1078 words
Time for file /tmp/data/data5-6.txt : 70 ms for 1468 words
Time for file /tmp/data/data9.txt : 58 ms for 1078 words
Time for file /tmp/data/data6-7.txt : 71 ms for 2156 words
Time for file /tmp/data/data8.txt : 66 ms for 1078 words
Time for file /tmp/data/data6-6.txt : 72 ms for 2156 words
Time for file /tmp/data/data4.txt : 46 ms for 390 words
Time for file /tmp/data/data6-4.txt : 68 ms for 1468 words
Word count:[1468, 1468, 390, 780, 1078, 1078, 2156, 1078, 390, 2156, 390, 780, 390, 390, 1078, 1468, 1468]
Total word count:18006
Total time 98 ms

可以看到总耗时更长，且单个文件的执行时间也大幅飙升，比如data8文件从1ms增至66ms！

疑问与需求 #

• 如何更好地诊断该问题的原因？
• 是否可以测量CPU时间而非墙钟时间来分析？
• 并行I/O请求本身是否就比串行更慢？
• 需要明确的原因解释，以及可用于精准定位问题的测试/检测方法。

内容的提问来源于stack exchange，提问作者Yann TM