locked
WinRT: intensive file writing (C++)

    Question

  • Hi

    My application (Windows Store App, C++) needs to perform quite intensive write-to-file operations. 

    It's about logging functionality, so it is quite important not  to buffer the data since if the application crashes the last logs (which could be critical to understand the crash) are lost.

    I've tried two methods:

    1. FileIO::AppendTextAsync
    2. OpenTransactedWriteAsync, DataWrite, StoreAsync, CommitAsync

    Both methods work but: the first works very slowly. It takes 4-5 milliseconds (on quite strong desktop PC) to complete single write operation which is too much (by far).

    The second work fast but it is buffered operation, that is the data is flushed to the file only when the CommitAsync is called and it is not what I need.

    Do I miss something, is there are any other method that works better?

    Thanks,

    Rafi


    Wednesday, May 8, 2013 10:11 AM

Answers

  • Where are you writing this? If you are writing to the app data folders you can use the Win32 API directly. If you are writing elsewhere you need to go through the broker as you are doing.

    --Rob

    Wednesday, May 8, 2013 2:44 PM
    Owner
  • As Rob Caplan noted, if you're writing your log to your app's local data directory then you can use the Win32 file APIs. They're two orders of magnitude faster than the WinRT file APIs. To create the appropriate filename for your log, do something like this:

    void MakeLocalFileName( wchar_t *wzFileName, wchar_t *wzFilePart )
     {
      // get the LocalFolder path
      wcscpy_s( wzFileName, MAX_PATH, ApplicationData::Current->LocalFolder->Path->Data() );
    
      // Append file part
      wcscat_s( wzFileName, MAX_PATH, wzFilePart );
    
     }
    
    You can use the resulting full filename to open with CreateFile or _wfopen_s().

    MSFT folks consistently blame the FileBroker for the slow WinRT file API performance. I'm not sure that the FB is the entire problem (unless is it completely unoptimized) and suspect the Async threading overhead is equally to blame (or maybe the majority of the poor perf). For example, enumerating 2000 files in the Local Data directory takes basically zero time using the standard FindFirst/FindNext Win32 APIs. Doing the equivalent enumeration in the WinRT APIs (GetFilesAsync plus GetBasicPropertiesAsync) takes a whopping 7700ms. Now, the FB implementation of GetFilesAsync must be, under the covers, doing the equivalent to FindFirst/FindNext and we know that's fast. And transmitting the results back to the app should be done in bulk, so that should be fast as well. The GetBasicPropertiesAsync call on each returned file should be fast because I assume it's simply querying the cached bulk results from GetFilesAsync. Here's the breakdown of the 7700ms for those operations:

    GetFilesAsync(): 2500 ms

    GetBasicPropertiesAsync() loop: 5200 ms

    The GetFilesAsync() time is bad enough (remember that actually enumerating 2000 files takes basically zero time in Win32) but it includes the IPC overhead to the FileBroker. The GetBasicPropertiesAsync() loop time is simply inexcusable. I already have the StorageFile vector at that point so the results should be cached locally in my process. Stepping through them should take almost zero time. The only explanations I could come up with for this horrendous performance are:

    1. The FileBroker is completely unoptimized and there is no caching in it at all. I find this hard to believe but ... given the poor design/implementation of WinRT in general, I can't rule it out.

    2. The WinRT file APIs are completely unoptimized and have to do an IPC with the FileBroker for every op. Again, hard to believe ...

    3. COM object creation overhead. Building up and taking down all those file objects must take time, but 5500ms? Of course, the huge amount of time spent in GetFilesAsync() can't be attributed completely to FB IPC overhead. There are 2000 StorageFile objects being created.

    4. Async threading overhead. This is my main suspect. However, it doesn't explain the poor GetFilesAsync() performance.

    I refuse to believe that MSFT would hire SDEs, in the Windows Team no less, that would not have implemented simple caching to solve items 1-2 above. That's Programming 101 stuff.

    Wednesday, May 8, 2013 4:58 PM

All replies

  • This is a C# forum and I think there not many people here that can help you.

    To try to ask this question on this forum:
    http://social.msdn.microsoft.com/Forums/en-US/winappswithnativecode/threads

    Wednesday, May 8, 2013 11:01 AM
  • thanks
    Wednesday, May 8, 2013 11:25 AM
  • Where are you writing this? If you are writing to the app data folders you can use the Win32 API directly. If you are writing elsewhere you need to go through the broker as you are doing.

    --Rob

    Wednesday, May 8, 2013 2:44 PM
    Owner
  • As Rob Caplan noted, if you're writing your log to your app's local data directory then you can use the Win32 file APIs. They're two orders of magnitude faster than the WinRT file APIs. To create the appropriate filename for your log, do something like this:

    void MakeLocalFileName( wchar_t *wzFileName, wchar_t *wzFilePart )
     {
      // get the LocalFolder path
      wcscpy_s( wzFileName, MAX_PATH, ApplicationData::Current->LocalFolder->Path->Data() );
    
      // Append file part
      wcscat_s( wzFileName, MAX_PATH, wzFilePart );
    
     }
    
    You can use the resulting full filename to open with CreateFile or _wfopen_s().

    MSFT folks consistently blame the FileBroker for the slow WinRT file API performance. I'm not sure that the FB is the entire problem (unless is it completely unoptimized) and suspect the Async threading overhead is equally to blame (or maybe the majority of the poor perf). For example, enumerating 2000 files in the Local Data directory takes basically zero time using the standard FindFirst/FindNext Win32 APIs. Doing the equivalent enumeration in the WinRT APIs (GetFilesAsync plus GetBasicPropertiesAsync) takes a whopping 7700ms. Now, the FB implementation of GetFilesAsync must be, under the covers, doing the equivalent to FindFirst/FindNext and we know that's fast. And transmitting the results back to the app should be done in bulk, so that should be fast as well. The GetBasicPropertiesAsync call on each returned file should be fast because I assume it's simply querying the cached bulk results from GetFilesAsync. Here's the breakdown of the 7700ms for those operations:

    GetFilesAsync(): 2500 ms

    GetBasicPropertiesAsync() loop: 5200 ms

    The GetFilesAsync() time is bad enough (remember that actually enumerating 2000 files takes basically zero time in Win32) but it includes the IPC overhead to the FileBroker. The GetBasicPropertiesAsync() loop time is simply inexcusable. I already have the StorageFile vector at that point so the results should be cached locally in my process. Stepping through them should take almost zero time. The only explanations I could come up with for this horrendous performance are:

    1. The FileBroker is completely unoptimized and there is no caching in it at all. I find this hard to believe but ... given the poor design/implementation of WinRT in general, I can't rule it out.

    2. The WinRT file APIs are completely unoptimized and have to do an IPC with the FileBroker for every op. Again, hard to believe ...

    3. COM object creation overhead. Building up and taking down all those file objects must take time, but 5500ms? Of course, the huge amount of time spent in GetFilesAsync() can't be attributed completely to FB IPC overhead. There are 2000 StorageFile objects being created.

    4. Async threading overhead. This is my main suspect. However, it doesn't explain the poor GetFilesAsync() performance.

    I refuse to believe that MSFT would hire SDEs, in the Windows Team no less, that would not have implemented simple caching to solve items 1-2 above. That's Programming 101 stuff.

    Wednesday, May 8, 2013 4:58 PM
  • Thanks. I don't care where to write, I just want the logs messages to be saved.

    I've tried  the _wfopen_s option. I'll probably use it.

    Thursday, May 9, 2013 11:10 AM
  • I do believe the FB is one to blame.

    If I'm using the OpenTransactedWriteAsync, DataWriter, StoreAsync, CommitAsync option it works rather fast. And it does perform Async stuff (StoryAsync) on every write operation. With this approach the actual file writing is performed only when CommitAsync is called, that is just once.

    There is another kinda proof: I can use UDP send operation (DatagramSocket) as another logging option and it takes 6 milliseconds to perform 5000 send operations, all of them are WriteAsync which I'm serializing:

    		auto t = create_task(str->WriteAsync(b));
    		try {
    			t.get();
    		}
    		catch (Exception^ e)
    		{
    
    		}


    • Edited by RafiKiel Thursday, May 9, 2013 11:18 AM
    Thursday, May 9, 2013 11:17 AM
  • I do believe the FB is one to blame.

    If I'm using the OpenTransactedWriteAsync, DataWriter, StoreAsync, CommitAsync option it works rather fast. And it does perform Async stuff (StoryAsync) on every write operation. With this approach the actual file writing is performed only when CommitAsync is called, that is just once.

    There is another kinda proof: I can use UDP send operation (DatagramSocket) as another logging option and it takes 6 milliseconds to perform 5000 send operations, all of them are WriteAsync which I'm serializing:

    		auto t = create_task(str->WriteAsync(b));
    		try {
    			t.get();
    		}
    		catch (Exception^ e)
    		{
    
    		}


    How are you getting the timing of that 5000 op UDP loop? Before doing the loop, call GetTickCount64() and in your try{}, after t.get(), increment a counter. When that counter hits your loop count, snap the time again with GetTickCount64().

    Edit:

    As a follow up, I implemented a simple version of StorageFile, MyStorageFile, that used the results from FindFirst/FindNext. All it contained was a String^ for cFileName, an int for the file size, and a GetBasicPropertiesAsync() function. I created a Vector<> of them during the enumeration. This barely changed the execution time of the enumeration (around 16 ms) so, at least in this simple attempt, the COM object creation time was negligible.

    Then I used the same Async call pattern in a for loop on the Vector of MyStorageFile entries as I did on the results of StorageFolder->GetFilesAsync. The total execution time jumped up to 281 ms. Note that all my GetBasicPropertiesAsync call was doing was to return a ref class containing a single int. 

    So, it looks like the Async pattern is responsible for one order of magnitude of the slowdown in file enumeration. That's bad enough ... but there's still another full order of magnitude slowdown needed (the really big chunks of time per file) to equal the poor performance of the actual GetFilesAsync/GetBasicPropertiesAsync method.

    It would be as fast or faster to put those 2000 files on an internet server and do a simple http directory listing than it is to query the local file system using GetFilesAsync/GetBasicPropertiesAsync. Wow.


    • Edited by henador Thursday, May 9, 2013 9:48 PM added test results
    Thursday, May 9, 2013 1:48 PM