JDK-8258196 : File operations 3 to 4 times slower in Java 15.1 than in Java 8 on Windows
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.io
  • Affected Version: 11,15
  • Priority: P3
  • Status: Open
  • Resolution: Unresolved
  • OS: windows_10
  • CPU: x86_64
  • Submitted: 2020-11-19
  • Updated: 2023-08-10
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other
tbdUnresolved
Related Reports
Relates :  
Description
ADDITIONAL SYSTEM INFORMATION :
Windows 10

A DESCRIPTION OF THE PROBLEM :
On Windows 10 operations which copy files and read them are 3-4 slower when performed with Java 15.1 than when performed with Java 1.8.
On Mac OSX I cannot reproduce the slow down.
I'm testing the code using the folder which can be downloaded from here: https://github.com/oxygenxml/userguide/tree/master/DITA
The folder contains about 6000 small files (XML files and images).

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
I'm attaching a piece of code which goes through a folder with lots of files (6000), copies each files to the temporary files folder and reads content from it.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
Run with Java 15 the code should take as long as when it's run with Java 1.8
ACTUAL -
With Java 1.8 the code finishes in about 11 seconds. With Java 15 it needs 40 seconds to run.

---------- BEGIN SOURCE ----------
public class ABC {
  static byte[] bytes = new byte[8 * 1024];
  static int cnt = 0;
  
    /**
     * Copies srcFile to dstFile.
     * 
     * @param srcFile             The source File.
     * @param dstFile             The destination File.
     * @param ignoreFileFlags  If <code>true</code> the flags should not be transmitted to
     *        the copied file. (executable, readable, writable).
     * @throws IOException Thrown if file copy fails.
     */
    private static void copyFile(File srcFile, File dstFile, boolean ignoreFileFlags) throws IOException {
      File parentFolder = dstFile.getParentFile();
      if (!parentFolder.exists()) {
        if (!parentFolder.mkdirs()) {
          throw new IOException("Could not create folder: " + parentFolder);
        }
      }
  
      FileInputStream fis = new FileInputStream(srcFile);
      try {
        FileOutputStream fos = new FileOutputStream(dstFile);
        copyInputStreamToOutputStream(fis, fos, true);
      } finally {
        /*
         * Streams are always closed by the "copy" method.
         * But if the output stream cannot not be created, make sure the input stream is closed safely and silently.
         */
        fis.close();
      }
      
      try {
        long srcLastModified = srcFile.lastModified();
        if(srcLastModified > 0) {
          dstFile.setLastModified(srcLastModified);
        }
        if (!ignoreFileFlags) {
          if (!srcFile.canWrite()) {
            //Set the read-only property
            dstFile.setReadOnly();
          }
          dstFile.setExecutable(srcFile.canExecute());
          dstFile.setReadable(srcFile.canRead());
          dstFile.setWritable(srcFile.canWrite());
        }
      } catch (SecurityException e) {
        e.printStackTrace();
      }
    }
  
  private static void read(File file) {
    try {
      File dst = File.createTempFile("test", ".xml");
      dst.deleteOnExit();
      copyFile(file, dst, false);
      System.err.println(file);
      FileInputStream fis = new FileInputStream(dst);
      int len = -1;
      while((len = fis.read(bytes)) != -1) {
        for (int i = 0; i < len; i++) {
          if(bytes[i] == 0) {
            cnt ++;
          }
        }
      };
      fis.close();
      dst.delete();
    } catch (FileNotFoundException e) {
      e.printStackTrace();
    } catch (IOException e) {
      e.printStackTrace();
    }
  }
  
    /**
   * Copies input stream content to output stream.
   * 
   * @param is                The input stream.
   * @param os                The output stream.
   * @param closeOutputStream <code>true</code> to also close the output stream.
   * The input stream is always closed.
   *
   * @throws IOException Thrown if file copy fails.
   */
  public static void copyInputStreamToOutputStream(
      InputStream is, OutputStream os, boolean closeOutputStream) throws IOException {
    BufferedOutputStream bos = new BufferedOutputStream(os, 8000);
    BufferedInputStream bis = new BufferedInputStream(is, 8000);
    try {
      byte[] buff = new byte[8192 * 2];
      int count;
      while ((count = bis.read(buff)) != -1) {
        bos.write(buff, 0, count);
      }
    } finally {
      try {
        bis.close();
      } finally {
        if (closeOutputStream) {
          bos.close();
        } else {
          bos.flush();
        }
      }
    }
  }

  public static void main(String[] args) {
    File start = new File("D:\\git-projects\\userguide-private\\DITA");
    long before = System.currentTimeMillis();
    recurseRead(start);
    long after = System.currentTimeMillis();
    System.err.println("Took: " + (after - before));
    System.err.println(cnt);
  }

  private static void recurseRead(File file) {
    if(file.isDirectory()) {
      File[] files = file.listFiles();
      if(files != null) {
        for (int i = 0; i < files.length; i++) {
          recurseRead(files[i]);
        }
      }
    } else {
      read(file);
    }
  }
}

---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
No workaround so far.

FREQUENCY : always



Comments
I cannot reproduce this on a Windows 10.0.18363 VirtualBox VM running on a macOS host: ---with printing file name --- $ jdk1.8.0_271/bin/java ABC Took: 68032 789186013 $ jdk-15/bin/java ABC Took: 66031 789186013 $ jdk-15/bin/java -Dsun.io.useCanonCaches=true ABC Took: 70251 789186013 ---without printing file name --- $ jdk1.8.0_271/bin/java ABC Took: 54469 789186013 $ jdk-15/bin/java ABC Took: 51344 789186013 $ jdk-15/bin/java -Dsun.io.useCanonCaches=true ABC Took: 50609 789186013
08-01-2021

Reply received from submitter ========================== I'm afraid setting the system property does not help the code run faster. I tested with both java 11 and 15, I get the same run times reported with or without the system property set. But that system property "sun.io.useCanonCaches" is useful for me because I had another separate problem in which one of our clients was having performance problems and they stemmed from using File.getCanonicalFile directly in our code. So thanks for giving links to that other issue, it may help me fix this other issue I had on my side at least.
16-12-2020

File.getCanonicalPath() method is subsequently called from File.createTempFile(String,String). As per Eric's comment : https://bugs.openjdk.java.net/browse/JDK-8258036?focusedCommentId=14388171&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-14388171 the performance is restored on using the suggested -D property. Requesting submitter to use: -Dsun.io.useCanonCaches=true and report the performance
16-12-2020

Compare with the analysis of 8258036 with a similar performance concern.
15-12-2020

[~adev] Do you have cycles to bisect this further? It would be useful to know if it reproduces with JDK 9 for example. The set of Windows calls used has changed since JDK 8.
15-12-2020

This looks like a performance regression: ================================== Java version: 1.8.0_102 (x64) Took: 8128 Java version: 1.8.0_271 (x64) Took: 8522 Java version: 11.0.2 Took: 41311 Java version: 15 (Oracle Open JDK x64) Took: 41745
15-12-2020

Reply received from the submitter =============================== Here are the results with a Java 11.0.2 that I had installed: 11.0.2 Took: 41311 so the problem is also in Java 11.
15-12-2020

Requested the submitter to check if it can be reproduced with JDK 11.
14-12-2020

Requesting the submitter to confirm the above result again and mail the exact results
14-12-2020

After executing the reproducer I did not notice a significant slowdown in the performance in the two versions of JDK. Following are my observations: The statistics are in milliseconds. OS: Win10: JDK 8 u271 =============== 110313 ms 100503 ms 106202 ms 107340 ms OS: Win10: JDK 15 ea b27 =============== 96405 ms 106038 ms 99060 ms 100786 ms
14-12-2020

It would be useful if the submitter could test with other JDK releases (e.g. JDK 11) to see if the anomaly is observed.
14-12-2020

Reply received from submitter ======================================= You seem to have a slow harddrive, I have an SSD harddrive so my run times are much smaller. My Windows version is 10.0.19041 Build 19041. And my CPU details: Intel Core i5-3570 CPU 3.40 GHz Here are the timings I receive on my side (obtained after running the code once to cache disk access, because the first time it's slower): Java version: 1.8.0_102 (x64) Took: 8128 Java version: 1.8.0_271 (x64) Took: 8522 Java version: 15 (Oracle Open JDK x64) Took: 41745 So on my side there is this jump of about 4-5 times between Java 1.8 and Java 15 when running the code.
14-12-2020