-1

我正在开发一个 Java 应用程序来从磁盘读取多个文本文件,修改它们并将修改后的文件写回磁盘。当我使用http://sourceforge.net/projects/filereadtest/files/filereadtest-java-gui/中的“FileReadTestJavaGui-1.05.jar”运行读取测试时,读取速度高达 250 MB/秒。当我运行下面给出的测试应用程序时,我的读取速度低至 11.75 MB/秒。我正在使用 ThreadPoolExecutor 并且无法获得一致的读/写速度。非常欢迎任何有关解决此问题的建议。我在具有 12 GB RAM 的戴尔双四核 2.4 GHz 机器上的 Windows 2008 Server R2 机器上运行了这些测试。

import java.io.File;
import java.io.FileInputStream;
import java.io.FileOutputStream;
import java.io.IOException;
import java.util.concurrent.ArrayBlockingQueue;
import java.util.concurrent.ThreadPoolExecutor;
import java.util.concurrent.TimeUnit;

public class RunTest {
    private static String baseFileName = "C:/logs/input_";
    private static class FileReaderRunnable implements Runnable {
        public FileReaderRunnable(int threadID) {
            super();
            this.threadID = threadID;
        }
        int threadID = -1;
        @Override
        public void run() {
            Thread.currentThread().setName("Thread-" + threadID);
            String writeBaseFileName = "c:/temp/output";
            String[] args = {baseFileName + threadID + ".log", writeBaseFileName + threadID + ".txt"};
            readAndWriteFileInputOutputStream(args);
        }
    }

    public static void main(String[] args) {
        int MAX_THREADS = 20;
        int coreThreadPoolSize = 2;
        int maxThreadPoolSize = 4;
        long threadKeepAliveTime = 12000000;
        int arrayBlockQueueSize = 400;
        ThreadPoolExecutor executor = new ThreadPoolExecutor(
                coreThreadPoolSize,
                maxThreadPoolSize,
                threadKeepAliveTime,
                TimeUnit.MILLISECONDS,
                new ArrayBlockingQueue<Runnable>(arrayBlockQueueSize, true));
        for (int i = 0; i < MAX_THREADS; i++) {
            FileReaderRunnable frr = new FileReaderRunnable(i+1);
            executor.execute(frr);
        }
        executor.shutdown();
        while (!executor.isTerminated()) {
            try {
                Thread.sleep(5000);
                print("********** executor.getPoolSize()=" + executor.getPoolSize());
                print("********** executor.getCorePoolSize()=" + executor.getCorePoolSize());
                print("********** executor.getActiveCount()=" + executor.getActiveCount());
                print("********** executor.getCompletedTaskCount()=" + executor.getCompletedTaskCount());
                print("********** executor.getTaskCount()=" + executor.getTaskCount());
                print("********** executor.isShutdown()=" + executor.isShutdown());
                print("********** executor.isTerminated()=" + executor.isTerminated());
            } catch (InterruptedException e) {
                e.printStackTrace();
            }

        }
    }

    public static void readAndWriteFileInputOutputStream(String[] args) {
        try {
            String routineName = Thread.currentThread().getName();
            String fInp = "c:\\temp\\input.txt";
            String fOut = "c:\\temp\\output.txt";
            if( args.length > 0 ) {
                fInp = args[0];
            }
            if( args.length > 1 ) {
                fOut = args[1];
            }
            FileInputStream fis = null;
            FileOutputStream fos = null;
            // delete the file if it exists
            File fff = new File( fOut );
            if( fff.exists() ) {
                fff.delete();
            }
            fff = null;
            fos = new FileOutputStream(fOut);
            fis = new FileInputStream( fInp );
            long readTime = 0;
            long writeTime = 0;
            final int FILE_CHUNK_SIZE = 16 * 1024;
            byte[] buffer = new byte[ FILE_CHUNK_SIZE ];

            long sTOverall = System.nanoTime();
            final long fileLen = fis.available();
            for ( long restSize = fileLen; restSize > 0; ) {
                final int sizeToProcess = (int) java.lang.Math.min( restSize, FILE_CHUNK_SIZE );
                long sT = System.nanoTime();
                final int actuallyRead = fis.read( buffer, 0, sizeToProcess );
                readTime += System.nanoTime() - sT;
                restSize -= actuallyRead;
                long sT0 = System.nanoTime();
                fos.write(buffer);
                writeTime += System.nanoTime() - sT0;
            }
            sTOverall = System.nanoTime() - sTOverall;
            fff = new File(fOut);
            double size = ((double)fff.length()) / (1024 * 1024);
            double secTaken = ((double)writeTime) / 1000000000;
            print(routineName + ": Took: " + secTaken + " sec to write " + size + " MB which is " + (size/secTaken) + " MB/sec");
            fos.close();
            File fff2 = new File(fInp);
            size = ((double)fff2.length()) / (1024 * 1024);
            secTaken = ((double)readTime) / 1000000000;
            print(routineName + ": Took: " + secTaken + " sec to read " + size + " MB which is " + (size/secTaken) + " MB/sec");
            fis.close();
            print(routineName + ": Took " + sTOverall + " nanosec overall");
        } catch (IOException e) {
            e.printStackTrace();
        }
    }

    public static void print(String string) {
        System.out.println(string);
    }
}

我得到的结果如下:

Thread-1: Took: 0.171561487 sec to write 100.015625 MB which is 582.9724768006936 MB/sec
Thread-2: Took: 0.174120658 sec to write 100.015625 MB which is 574.4041295777781 MB/sec
Thread-1: Took: 0.095193221 sec to read 100.00039100646973 MB which is 1050.4990791988196 MB/sec
Thread-1: Took 273077435 nanosec overall
Thread-2: Took: 0.095017056 sec to read 100.00039100646973 MB which is 1052.4467418404304 MB/sec
Thread-2: Took 273701058 nanosec overall
Thread-4: Took: 0.14674968 sec to write 100.015625 MB which is 681.538964854983 MB/sec
Thread-4: Took: 0.089255036 sec to read 100.00039100646973 MB which is 1120.3893414649424 MB/sec
Thread-4: Took 238318510 nanosec overall
Thread-3: Took: 0.151534826 sec to write 100.015625 MB which is 660.0174206818965 MB/sec
Thread-3: Took: 0.093351422 sec to read 100.00039100646973 MB which is 1071.2251496979845 MB/sec
Thread-3: Took 246756663 nanosec overall
Thread-5: Took: 0.149539881 sec to write 100.015625 MB which is 668.8224193517981 MB/sec
Thread-5: Took: 0.089968802 sec to read 100.00039100646973 MB which is 1111.5007511878364 MB/sec
Thread-5: Took 239927158 nanosec overall
Thread-6: Took: 0.153380444 sec to write 100.015625 MB which is 652.0754692821205 MB/sec
Thread-6: Took: 0.087988256 sec to read 100.00039100646973 MB which is 1136.519753346057 MB/sec
Thread-6: Took 241764966 nanosec overall
Thread-7: Took: 0.142689584 sec to write 100.015625 MB which is 700.9315059745355 MB/sec
Thread-7: Took: 0.088074798 sec to read 100.00039100646973 MB which is 1135.4030128626548 MB/sec
Thread-7: Took 231188741 nanosec overall
Thread-8: Took: 0.140693664 sec to write 100.015625 MB which is 710.8751180152648 MB/sec
Thread-8: Took: 0.085812695 sec to read 100.00039100646973 MB which is 1165.333299536505 MB/sec
Thread-8: Took 226884069 nanosec overall
Thread-9: Took: 0.105057511 sec to write 100.015625 MB which is 952.0083242786895 MB/sec
Thread-9: Took: 0.076369586 sec to read 100.00039100646973 MB which is 1309.4269099019305 MB/sec
Thread-9: Took 181834692 nanosec overall
Thread-10: Took: 0.113160569 sec to write 100.015625 MB which is 883.8381238609713 MB/sec
Thread-10: Took: 0.083640607 sec to read 100.00039100646973 MB which is 1195.5961893780818 MB/sec
Thread-10: Took 197200174 nanosec overall
********** executor.getPoolSize()=2
********** executor.getCorePoolSize()=2
********** executor.getActiveCount()=2
********** executor.getCompletedTaskCount()=10
********** executor.getTaskCount()=20
********** executor.isShutdown()=true
********** executor.isTerminated()=false
Thread-11: Took: 0.154032991 sec to write 100.015625 MB which is 649.3130098343672 MB/sec
Thread-11: Took: 8.420174029 sec to read 100.00039100646973 MB which is 11.876285533061127 MB/sec
Thread-11: Took 8574829737 nanosec overall
********** executor.getPoolSize()=2
********** executor.getCorePoolSize()=2
********** executor.getActiveCount()=2
********** executor.getCompletedTaskCount()=11
********** executor.getTaskCount()=20
********** executor.isShutdown()=true
********** executor.isTerminated()=false
Thread-12: Took: 0.140394781 sec to write 100.015625 MB which is 712.3884825889646 MB/sec
Thread-12: Took: 8.505642503 sec to read 100.00039100646973 MB which is 11.756947340685771 MB/sec
Thread-12: Took 8646511924 nanosec overall
Thread-13: Took: 0.143740254 sec to write 100.015625 MB which is 695.8080441405091 MB/sec
Thread-13: Took: 4.546878135 sec to read 100.00039100646973 MB which is 21.993197978346462 MB/sec
Thread-13: Took 4691105248 nanosec overall
********** executor.getPoolSize()=2
********** executor.getCorePoolSize()=2
********** executor.getActiveCount()=2
********** executor.getCompletedTaskCount()=13
********** executor.getTaskCount()=20
********** executor.isShutdown()=true
********** executor.isTerminated()=false
Thread-14: Took: 0.143977148 sec to write 100.015625 MB which is 694.6631905779936 MB/sec
Thread-14: Took: 5.020245761 sec to read 100.00039100646973 MB which is 19.91942143217911 MB/sec
Thread-14: Took 5164713374 nanosec overall
Thread-15: Took: 0.155099121 sec to write 100.015625 MB which is 644.8497216177002 MB/sec
Thread-15: Took: 3.628340768 sec to read 100.00039100646973 MB which is 27.560914864562612 MB/sec
Thread-15: Took 3783981095 nanosec overall
Thread-16: Took: 0.147386899 sec to write 100.015625 MB which is 678.5923693258518 MB/sec
Thread-16: Took: 3.865473212 sec to read 100.00039100646973 MB which is 25.870154964734425 MB/sec
Thread-16: Took 4013349692 nanosec overall
********** executor.getPoolSize()=2
********** executor.getCorePoolSize()=2
********** executor.getActiveCount()=2
********** executor.getCompletedTaskCount()=16
********** executor.getTaskCount()=20
********** executor.isShutdown()=true
********** executor.isTerminated()=false
Thread-17: Took: 0.145950813 sec to write 100.015625 MB which is 685.2693927782368 MB/sec
Thread-17: Took: 3.594029782 sec to read 100.00039100646973 MB which is 27.824029591324553 MB/sec
Thread-17: Took 3740485565 nanosec overall
Thread-18: Took: 0.143193164 sec to write 100.015625 MB which is 698.4664784696006 MB/sec
Thread-18: Took: 4.387502482 sec to read 100.00039100646973 MB which is 22.792099016861528 MB/sec
Thread-18: Took 4531185662 nanosec overall
********** executor.getPoolSize()=2
********** executor.getCorePoolSize()=2
********** executor.getActiveCount()=2
********** executor.getCompletedTaskCount()=18
********** executor.getTaskCount()=20
********** executor.isShutdown()=true
********** executor.isTerminated()=false
Thread-19: Took: 0.14751012 sec to write 100.015625 MB which is 678.0255144528389 MB/sec
Thread-19: Took: 5.882018447 sec to read 100.00039100646973 MB which is 17.001033218022773 MB/sec
Thread-19: Took 6030072471 nanosec overall
Thread-20: Took: 0.13555387 sec to write 100.015625 MB which is 737.8293589109629 MB/sec
Thread-20: Took: 4.122019495 sec to read 100.00039100646973 MB which is 24.260048048722226 MB/sec
Thread-20: Took 4258033501 nanosec overall
********** executor.getPoolSize()=0
********** executor.getCorePoolSize()=2
********** executor.getActiveCount()=0
********** executor.getCompletedTaskCount()=20
********** executor.getTaskCount()=20
********** executor.isShutdown()=true
********** executor.isTerminated()=true
4

2 回答 2

1

您的所有运行的写入时间都是一致的。您的阅读时间开始时非常快(> 1 GB/s),但最终会触底。我怀疑发生的事情是您超出了系统的磁盘缓存容量。对于前 10 个线程,您正在写入的数据滞留在系统的磁盘缓存中,因此读取速度非常快。在第 10 个线程之后,您已经写入了足够多的数据,系统开始丢弃缓存数据,实际上不得不去磁盘读取数据。它应该一直保留 MRU 块,但也许没有。您没有指定什么操作系统,因此甚至无法推测正在发生的事情。

这是一个警示故事,即微基准测试充满了危险。现代操作系统背后有很多优化,例如 JIT 编译、磁盘缓存(在操作系统中、磁盘控制器和磁盘本身)等,在进行基准测试时必须考虑这些因素,尤其是基础Java 代码执行速度和 I/O 等操作。

我怀疑 FileReadTestJavaGui 没有写入足够的数据来遇到同样的问题。

最重要的是,如果不深入了解代码和“裸机”之间发生的一切,您就无法获得一致的结果,甚至无法确切知道您正在测量的是什么。

于 2013-10-20T04:00:04.073 回答
0

我怀疑您没有使用直接 I/O 来避免在 RAM 中缓存数据(在 Java 中可能吗?)。如果您使用的是 Linux,您可能需要运行 vmstat 来查看发生了什么,如果是 Windows,则可能需要运行 Perfmon。我目前正在 Raspberry Pi 上编写基准测试和压力程序。以下是磁盘(SD 卡)测试的 vmstat 结果,首先是直接 I/O,其中文件缓存保持较小且 CPU 利用率较低。第二个是缓存 I/O,其中缓存可以包含所有使用的文件,并且在 100% 的 CPU 利用率下从 RAM 读取数据。RPi 只有 512 MB 相对较慢的 RAM。对 4 x 164 MB 文件的进一步测试不会缓存它们以供读取,但当操作系统意识到正在重新读取文件时,重复运行可能会有一些缓存。无论文件大小如何,缓存速度都会有很大差异。

vmstat 15 25 > vmstats44.txt
15 second periods, 25 samples
Write 4 files of 82 MB in 46 seconds =   7.1 MB/sec bo
Read 3 x 4 x 82 MB in 62 second       = 15.8 MB/sec bi
Reread 49200 x 64 KB in 167 seconds   = 18.4 MB/sec bi
Rereads 64 KB block for 1 second from 
164 blocks in one file

procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 1  0      0 349476   2772  33484    0    0    51   439 1264  229 15 30 53  2
 0  1      0 347428   2796  33532    0    0     2  6996 3793  914 17 42  0 41
 1  1      0 347172   2904  33592    0    0     6  6851 3736  849 11 41  0 48
 1  1      0 347172   2932  33616    0    0     1  7536 3996  931 11 46  0 43
 2  0      0 347048   2948  33616    0    0 13965  1053 6187 1264 14 18  0 68
 0  1      0 347048   2964  33616    0    0 16188     3 6524 1314 13 14  0 73
 1  0      0 347048   2972  33616    0    0 16427     3 6605 1333 12 14  0 74
 0  1      0 347048   2980  33616    0    0 16439     2 6607 1335 13 14  0 73
 2  0      0 347048   2996  33616    0    0 18253     3 7198 1471  7  9  0 84
 1  1      0 347048   3020  33616    0    0 18842     5 7393 1510  4 10  0 87
 0  1      0 346924   3044  33616    0    0 18833     6 7389 1512  2 10  0 88
 0  1      0 346924   3068  33616    0    0 18842     5 7393 1504  4 10  0 87
 1  0      0 346924   3092  33616    0    0 18859     6 7398 1509  3  8  0 89
 0  1      0 346924   3116  33616    0    0 18854     5 7390 1509  3  9  0 88
 0  1      0 346800   3140  33616    0    0 18859     5 7395 1508  4  9  0 87
 1  1      0 346800   3164  33616    0    0 18820     6 7385 1501  3 10  0 87
 1  1      0 346800   3188  33616    0    0 18842     5 7391 1506  3  8  0 89
 1  1      0 346800   3212  33616    0    0 18829     5 7386 1507  3  9  0 88
 0  1      0 346676   3236  33616    0    0 18816     6 7384 1495  4  9  0 88
 0  0      0 346800   3252  33552    0    0  7428     7 3632  640  4  4 59 32


Cached test  - see cache size details
Write 4 x 82 MB time 2.3, 9.1, 12.3, 2.4 seconds average 12.6 MB/sec bo
Read 19 x 4 x 82 MB in 63 seconds                       =  99 MB/sec cpu us sy
Reread 1158120 x 64 KB in 164 seconds                   = 441 MB/sec cpu us sy

procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
 2  0      0 355484   3692  29308    0    0    60   345 1260  204 14 26 58  2
 0  3      0 124856   3976 254388    0    0    27 13562 1661 1889 16 34  0 50
 1  1      0  11476   4000 365356    0    0     0  8850 1413 2556 10 23  0 67
 1  0      0  11476   4012 365420    0    0     0     2 1750 1118 48 52  0  0
 1  0      0  11344   4020 365420    0    0     0     2 1270  122 50 50  0  0
 1  0      0  11352   4028 365420    0    0     0     4 1271   61 46 54  0  0
 1  1      0  11600   3616 365572    0    0    57     2 1292   77 44 56  0  0
 1  0      0  12320   1940 366340    0    0   254     6 1376  111 14 86  0  0
 1  0      0  11476   1964 367540    0    0    80     4 1304   91 14 86  0  0
 1  0      0  11352   1988 367540    0    0     0     5 1277   82 12 88  0  0
 1  0      0  11352   2012 367540    0    0     0     5 1275   79 13 87  0  0
 1  0      0  11228   2036 367540    0    0     0     5 1276   85 14 86  0  0
 2  0      0  11228   2060 367540    0    0     0     4 1276   80 13 87  0  0
 2  0      0  11228   2084 367540    0    0     0     5 1276   77 13 87  0  0
 1  0      0  11228   2108 367540    0    0     0     4 1276   83 13 87  0  0
 1  0      0  11104   2132 367540    0    0     0     4 1276   78 12 88  0  0
 1  0      0  10980   2300 367552    0    0     9     9 1282   80 11 89  0  0
 0  0      0 352104   2324  31696    0    0     1     5 1273   90 12 81  7  0
于 2013-10-20T13:28:35.577 回答