Skip to main content

 none
KERNEL32's GetFileAttributesExW bizarrely slow based on the content of a file RRS feed

  • Question

  • We have a Java program with a logging mechanism that checks file size before writing and "rolls over" the file to an archive if it gets too big. (The library is called Logback, it's popular in the Java community.)

    We had reports of our application server on Windows slowing to a crawl, and after many hours debugging, discovered that it was the *content of the current log file* that was causing each of LogBack's write operations to take several hundred milliseconds (instead of 5ms or so). Our log output is relatively verbose, so that meant our application was taking minutes to do simple operations if it was under load. It was a very rare occurrence, but when it happened, our application became useless. 

    We could easily reproduce or eliminate the slowness by altering the content at the beginning of the log file. Namely, if we take all the dollar-sign characters ($) out of the first 200 lines, the slowness does not occur. Add them back and the slowness comes back immediately. We were able to do this without restarting our application, just by altering the content on the fly with Notepad++. 

    I know this sounds crazy. So we created a tiny Java project that mimicks the calls that Logback makes. Namely, it retrieves the file length while simultaneously keeping a FileOutputStream object open for writing. It's the File.length() call that becomes slow. 

    The project is posted  here <https://github.com/seeq12/log-slowness>  . 

    You can see the code and read our commentary  here 
    <https://github.com/seeq12/log-slowness/blob/master/src/ShowLogSlowness.java


    It's pretty easy to clone the repo and run the Java command if you want to see this for yourself. This reproduced on 100% of our Windows environments (desktops, laptops, VMs). It does not reproduce on OSX. 

    You can diff the two "seed" log files (fast.log and slow.log) and you'll see how little they differ. 

    It looks like this is a Windows problem, not a Java problem. Java calls GetFileAttributesExW and that's what's slow. I can see the callstack using Windbg:

    Child-SP          RetAddr           Call Site
    00000000`022bee28 00007ffe`bbb80225 ntdll!ZwQueryFullAttributesFile+0x14
    *** ERROR: Symbol file could not be found.  Defaulted to export symbols for C:\Program Files\Seeq Server\jre\files\bin\java.dll - 
    00000000`022bee30 00000000`67c8a3d4 KERNELBASE!GetFileAttributesExW+0x95
    00000000`022bef10 00000000`024d7f74 java_67c80000!Java_java_io_WinNTFileSystem_getLength+0x48
    00000000`022befb0 00000007`404d9328 0x24d7f74
    00000000`022befb8 00000000`2019a1a8 0x7`404d9328
    00000000`022befc0 00000000`00000000 0x2019a1a8


    I don't know what the best forum is to get some feedback on why this is happening, any advice would be appreciated.

    Saturday, October 21, 2017 9:16 PM

Answers

  • >No third party software whatsoever. This repros on a vanilla Azure instance of Windows Server 2016 Datacenter. You can spin it up, download the GitHub project, and see it in action.

    Has it got Windows Defender active?

    Dave

    • Marked as answer by MarkDer Monday, October 23, 2017 3:54 PM
    Monday, October 23, 2017 3:38 PM

All replies

  • We've reproduced the problem using a C application that takes Java out of the picture. It's now committed to the same GitHub project: https://github.com/seeq12/log-slowness

    C code: https://github.com/seeq12/log-slowness/blob/master/SlowLogFile.c

    More findings: It seems this does not reproduce on all hard disks. I have a desktop with both an SSD and a spinning disk, and it repros on the SSD but not the spinning disk. But we observe that it repros more often than not.

    Sunday, October 22, 2017 6:26 PM
  • If this is something that you can reproduce regularly, then you should get information on the hardware and versions of Windows this is affecting and then open a support ticket with Microsoft directly.

    GetFileAttributesExW is basically a thin wrapper around NtQueryFullAttributesFile/ZwQueryFullAttributesFile. All GetFileAttributesExW does is to convert the parameters to what the internal function requires and calls that, and then on return it just takes what the internal function returns, puts it into a format that GetFileAttributesExW itself has been defined to use and then returns that. So any slowness wouldn't be at this level.

    The internal (Nt/Zw)QueryFullAttributesFile basically does a system call into kernel mode and the kernel mode code is what will do the file system look up. This of course would be controlled by the file system driver and hard disk drivers.

    So because this has the potential to be in code controlled by Microsoft themselves, this is something that you will have to contact them directly rather than go through these forums.


    This is a signature. Any samples given are not meant to have error checking or show best practices. They are meant to just illustrate a point. I may also give inefficient code or introduce some problems to discourage copy/paste coding. This is because the major point of my posts is to aid in the learning process.

    Sunday, October 22, 2017 8:15 PM
  • >We could easily reproduce or eliminate the slowness by altering the content at the beginning of the log file. Namely, if we take all the dollar-sign characters ($) out of the first 200 lines, the slowness does not occur. Add them back and the slowness comes back immediately. We were able to do this without restarting our application, just by altering the content on the fly with Notepad++. 

    Do you have an AV product installed?
    If so, does removing it make any difference?

    Sunday, October 22, 2017 10:21 PM
  • No third party software whatsoever. This repros on a vanilla Azure instance of Windows Server 2016 Datacenter. You can spin it up, download the GitHub project, and see it in action.
    • Edited by MarkDer Monday, October 23, 2017 2:12 PM
    Monday, October 23, 2017 1:50 PM
  • >No third party software whatsoever. This repros on a vanilla Azure instance of Windows Server 2016 Datacenter. You can spin it up, download the GitHub project, and see it in action.

    Has it got Windows Defender active?

    Dave

    • Marked as answer by MarkDer Monday, October 23, 2017 3:54 PM
    Monday, October 23, 2017 3:38 PM
  • A wise person once said, "It's always the anti-virus."

    If I turn off Windows Defender, the operations take 0 ms. Turn it on, and it's back to slowness.

    My apologies Dave-- I should have remembered that there is AV built into Windows now.

    Thanks. I see there's a way to add ourselves to an exclusion list for Windows Defender, I'll be exploring that.


    Monday, October 23, 2017 3:54 PM
  • A wise person once said, "It's always the anti-virus."

    That's one I say too :)

    If I turn off Windows Defender, the operations take 0 ms. Turn it on, and it's back to slowness.

    I'm glad you've pinned it down and should have a work around, but I have no idea how to escalate this to MS to have someone look
    into this further with a view to it not being an issue for anyone else in a similar circumstance.

    Monday, October 23, 2017 4:00 PM
  • For some reason I keep forgetting it too. Which is quite daft since it is responsible for scanning files.

    Maybe one day I will remember.


    This is a signature. Any samples given are not meant to have error checking or show best practices. They are meant to just illustrate a point. I may also give inefficient code or introduce some problems to discourage copy/paste coding. This is because the major point of my posts is to aid in the learning process.

    Monday, October 23, 2017 6:10 PM