0

I suspected a method in my code to be very slow when listing files in a directory containing thousands of files (more than 60s). So I put some logs in my code and it confirmed me that this part was slow. It then used JFR to see if it was correctly reporting this hugely slow method.

The associated thread dump is :

"EJB default - 5 : Task-XML_MON" #522 prio=5 os_prio=0 cpu=8362437.50ms elapsed=86380.31s tid=0x000001c5d122c000 nid=0x594c runnable  [0x0000001cb04fd000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.fs.WindowsNativeDispatcher.CreateFile0(java.base@11.0.2/Native Method)
    at sun.nio.fs.WindowsNativeDispatcher.CreateFile(java.base@11.0.2/WindowsNativeDispatcher.java:71)
    at sun.nio.fs.WindowsChannelFactory.open(java.base@11.0.2/WindowsChannelFactory.java:308)
    at sun.nio.fs.WindowsChannelFactory.newFileChannel(java.base@11.0.2/WindowsChannelFactory.java:168)
    at sun.nio.fs.WindowsFileSystemProvider.checkReadAccess(java.base@11.0.2/WindowsFileSystemProvider.java:326)
    at sun.nio.fs.WindowsFileSystemProvider.checkAccess(java.base@11.0.2/WindowsFileSystemProvider.java:363)
    at sun.nio.fs.AbstractFileSystemProvider.exists(java.base@11.0.2/AbstractFileSystemProvider.java:151)
    at java.nio.file.Files.exists(java.base@11.0.2/Files.java:2434)
    at org.apache.commons.io.file.CountingPathVisitor.visitFile(CountingPathVisitor.java:151)
    at org.apache.commons.io.file.CountingPathVisitor.visitFile(CountingPathVisitor.java:35)
    at java.nio.file.Files.walkFileTree(java.base@11.0.2/Files.java:2724)
    at org.apache.commons.io.FileUtils.listAccumulate(FileUtils.java:2076)
    at org.apache.commons.io.FileUtils.listFiles(FileUtils.java:2132)

This thread dump comes from a JFR recording (in 'profile' mode) that I started when I knew for sure that my application was running my slow method (listing the files of a directory through the call of FileUtils.listFiles() which calls java.nio.file.Files.walkFileTree()).

I stopped the recording after about 60s and opened it in JMC.

I was then very surprised to see absolutely no warning from the automatic analysis and futhermore surprised to not see my method listed in the "Method profiling" section. All I saw was this :

enter image description here

Why is FileUtils.listFiles not present in the "Method profiling" knowing it was running for the whole time of the recording ?

Does it mean that the java.nio methods (here java.nio.file.Files.walkFileTree in particular) are not sampled by JFR ?

It is really hard to detect this type of bottleneck if JFR or JMC cannot provide this kind of information.

Olivier Masseau
  • 778
  • 7
  • 23
  • Select `File I/O` node on the left pane (I believe you are currently on `Method Profiling`) – Andrey B. Panfilov Aug 15 '22 at 11:24
  • @AndreyB.Panfilov File I/O node shows nothing, which seems normal to me. It is a node that shows only reads/writes on files, which is not the case here. I'm just calling Files.walkFileTree to list the files in a directory. – Olivier Masseau Aug 16 '22 at 07:53
  • 1
    The Method Profiler event ("jdk.ExecutionSample") samples Java code that is executing. What makes your application slow is likely at a lower layer, i.e the operating system or the hardware. JFR has a native samples event ("jdk. NativeMethodSample") that can provide information on threads that are in native, executing or waiting. – Kire Haglin Aug 16 '22 at 12:15

0 Answers0