boost.log's text_multifile_backend is not performant on windows - perhaps it should be documented?
I recently moved a project to boost.log from a homemade logger. I had something like text_multifile_backend, so finding that as a drop-in replacement was awesome. Unfortunately, the performance when using text_multifile_backend on windows is really bad, because the repeated file close operations (one per log record) are unusually slow on windows. Repeatedly logging a string to the same file via text_multifile_backend results in throughput of about 200 log entries per second. Just to quickly prove it is unique to windows, I made a simple program that just opens, appends a single line, and then closes, an ofstream in a loop. On a high-end windows machine with nvme ssd, 1000 iterations takes 2600ms. On an older linux box with a sata ssd, the same takes 16ms. What do others think about adding a note in the documentation about this performance issue? It's bad enough that I think anyone on windows would want to avoid the backend. It's not the backend's "fault" at all; I could see some options for improving performance of the backend on windows, but they definitely complicate the simplicity of the current approach. (Side note - in googling the issue, other projects have been bitten - notably mercurial on windows - https://gregoryszorc.com/blog/2015/10/22/append-i/o-performance-on-windows/ )
Nicholas Neumann wrote:
Unfortunately, the performance when using text_multifile_backend on windows is really bad, because the repeated file close operations (one per log record) are unusually slow on windows. Repeatedly logging a string to the same file via text_multifile_backend results in throughput of about 200 log entries per second.
That's probably a Windows Defender (or another antivirus) "feature". Not that this helps.
On 3/3/21 11:28 PM, Peter Dimov via Boost wrote:
Nicholas Neumann wrote:
Unfortunately, the performance when using text_multifile_backend on windows is really bad, because the repeated file close operations (one per log record) are unusually slow on windows. Repeatedly logging a string to the same file via text_multifile_backend results in throughput of about 200 log entries per second.
That's probably a Windows Defender (or another antivirus) "feature". Not that this helps.
It does help. Nicholas, could you verify this by adding the directory where log files are written to the excluded ones in the AV software you have? Or by temporarily disabling the software?
On 3/3/21 11:00 PM, Nicholas Neumann via Boost wrote:
I recently moved a project to boost.log from a homemade logger. I had something like text_multifile_backend, so finding that as a drop-in replacement was awesome.
Unfortunately, the performance when using text_multifile_backend on windows is really bad, because the repeated file close operations (one per log record) are unusually slow on windows. Repeatedly logging a string to the same file via text_multifile_backend results in throughput of about 200 log entries per second.
Just to quickly prove it is unique to windows, I made a simple program that just opens, appends a single line, and then closes, an ofstream in a loop. On a high-end windows machine with nvme ssd, 1000 iterations takes 2600ms. On an older linux box with a sata ssd, the same takes 16ms.
What do others think about adding a note in the documentation about this performance issue? It's bad enough that I think anyone on windows would want to avoid the backend. It's not the backend's "fault" at all; I could see some options for improving performance of the backend on windows, but they definitely complicate the simplicity of the current approach.
I'm not sure I feel good about documenting it, as it doesn't really solve the problem. I suppose, I could add a cache of the least recently used files to keep them open, but that cache would be ineffective if exceeded, which can happen in some valid cases (e.g. writing logs pertaining to a given dynamically generated "id" to a separate log). And it would only be useful on Windows.
On 04/03/2021 09:41, Andrey Semashev via Boost wrote:
On 3/3/21 11:00 PM, Nicholas Neumann via Boost wrote:
I recently moved a project to boost.log from a homemade logger. I had something like text_multifile_backend, so finding that as a drop-in replacement was awesome.
Unfortunately, the performance when using text_multifile_backend on windows is really bad, because the repeated file close operations (one per log record) are unusually slow on windows. Repeatedly logging a string to the same file via text_multifile_backend results in throughput of about 200 log entries per second.
Just to quickly prove it is unique to windows, I made a simple program that just opens, appends a single line, and then closes, an ofstream in a loop. On a high-end windows machine with nvme ssd, 1000 iterations takes 2600ms. On an older linux box with a sata ssd, the same takes 16ms.
Opening a file for read/write on Windows using the NT kernel API is approx 76x slower than opening a file on Linux. Using the Win32 API is approx 40% slower again (~106x slower). That's without any antivirus. You're seeing things slower than that again, which is almost certainly due to the file handle close. On Linux this doesn't do work, whereas on Windows it induces a blocking metadata flush plus flush of the containing directory i.e. an fsync of metadata. Windows is competitive to Linux for file i/o, once the file is opened. It is highly uncompetitive for file open/close. This is why compiling a large codebase is always much slower on Windows than elsewhere, because compiling C++ involves opening an awful lot of files for read.
What do others think about adding a note in the documentation about this performance issue? It's bad enough that I think anyone on windows would want to avoid the backend. It's not the backend's "fault" at all; I could see some options for improving performance of the backend on windows, but they definitely complicate the simplicity of the current approach.
I'm not sure I feel good about documenting it, as it doesn't really solve the problem. I suppose, I could add a cache of the least recently used files to keep them open, but that cache would be ineffective if exceeded, which can happen in some valid cases (e.g. writing logs pertaining to a given dynamically generated "id" to a separate log). And it would only be useful on Windows.
Windows, unlike POSIX, has no low soft limit on total open file descriptors such that you need to care about fire and forget HANDLE allocation. You can open at least 16 million files on Windows per process without issue. Just make sure that when opening the HANDLE you do not exclude other programs also opening the file, or deleting or renaming the file. Be aware that so long as the file is open, any directory in the hierarchy above is locked, and cannot be renamed. Be aware if you map the file, other programs will be denied many operations, such as shrinking the file, which does not occur on POSIX. A lot of people coming from POSIX don't realise this, but on Windows opening a file with more permissions than you actually need is expensive. For example, if you only need to atomically append to a file, opening that file for append-only, with no ability to read nor write nor query metadata, is much quicker than opening it with additional privileges. If you don't mind using NtCreateFile() instead of Win32 CreateFile(), that's 40% quicker, as you save on the dynamic memory allocation and Unicode path reencode all the Win32 path APIs do. In our work custom DB in which every new query opens several files on the filesystem, on Windows it is many times slower than on Linux. However, overall benchmarks are within 15% of Linux, because the hideous high cost file open/close gets drowned out by other operations. We also heavily cache open file handles on all platforms (after raising the soft fd limit on POSIX to 1 million), so we avoid file open/close as much as we can, which helps Windows particularly. (All number claims above come from LLFIO which makes the Windows filesystem about twice as fast, and should be considered anecdata) Niall
On 3/4/21 1:27 PM, Niall Douglas via Boost wrote:
Opening a file for read/write on Windows using the NT kernel API is approx 76x slower than opening a file on Linux. Using the Win32 API is approx 40% slower again (~106x slower). That's without any antivirus.
You're seeing things slower than that again, which is almost certainly due to the file handle close. On Linux this doesn't do work, whereas on Windows it induces a blocking metadata flush plus flush of the containing directory i.e. an fsync of metadata.
Windows is competitive to Linux for file i/o, once the file is opened. It is highly uncompetitive for file open/close. This is why compiling a large codebase is always much slower on Windows than elsewhere, because compiling C++ involves opening an awful lot of files for read.
Unfortunately, text_multifile_backend is supposed to open and close file on every log record, as the file name is generated from the log record.
Windows, unlike POSIX, has no low soft limit on total open file descriptors such that you need to care about fire and forget HANDLE allocation. You can open at least 16 million files on Windows per process without issue.
I'm sure there are some resources associated with the file handle in the kernel, so I definitely wouldn't want to have millions of open files in the logging library.
Just make sure that when opening the HANDLE you do not exclude other programs also opening the file, or deleting or renaming the file. Be aware that so long as the file is open, any directory in the hierarchy above is locked, and cannot be renamed. Be aware if you map the file, other programs will be denied many operations, such as shrinking the file, which does not occur on POSIX.
A lot of people coming from POSIX don't realise this, but on Windows opening a file with more permissions than you actually need is expensive. For example, if you only need to atomically append to a file, opening that file for append-only, with no ability to read nor write nor query metadata, is much quicker than opening it with additional privileges.
I see, thanks for the information.
If you don't mind using NtCreateFile() instead of Win32 CreateFile(), that's 40% quicker, as you save on the dynamic memory allocation and Unicode path reencode all the Win32 path APIs do.
I'm currently using C++ ofstream. I suppose, I could use a lower level API if there were compelling benefits, but NtCreateFile in particular seems to be too low level, as it is considered Windows kernel internals and can be changed or removed in the future[1]. Since text_multifile_backend is writing text, I would also have to implement newline character translation, as I believe, WinAPI doesn't do that.
In our work custom DB in which every new query opens several files on the filesystem, on Windows it is many times slower than on Linux. However, overall benchmarks are within 15% of Linux, because the hideous high cost file open/close gets drowned out by other operations. We also heavily cache open file handles on all platforms (after raising the soft fd limit on POSIX to 1 million), so we avoid file open/close as much as we can, which helps Windows particularly.
(All number claims above come from LLFIO which makes the Windows filesystem about twice as fast, and should be considered anecdata)
Thanks for all the information you provided, Niall. In any case, I've created a ticket to consider adding a cache of open files: https://github.com/boostorg/log/issues/142 Also, I've added a note to the docs. [1]: https://docs.microsoft.com/en-us/windows/win32/devnotes/calling-internal-api...
On 3/4/21 10:04 PM, Peter Dimov via Boost wrote:
Andrey Semashev wrote:
Unfortunately, text_multifile_backend is supposed to open and close file on every log record, as the file name is generated from the log record.
If you maintain a small LRU cache, will it help?
That's what I had in mind, but it will have its own problems. One of the main use cases for text_multifile_backend is when you want to maintain a separate log for each of the user's business process entity (e.g. a session or a connection of some sort). There can be any number of such entities, and I can't come up with a reasonable limit for a cache in the sink backend. Naturally, the cache will be ineffective if the number of actively logging entities exceeds its capacity. At the same time I don't want to keep any stale open files in the cache. It seems, I'll have to maintain some sort of a timeout for closing files and cleaning up the cache. But I will only be able to perform the cleanup on log records, which means I'll still have stale open files in cache if there's no logging happening. Keeping open files is not only a concern from resource usage perspective. It may affect user's experience, as e.g. on Windows he won't be able to remove the open files or the containing directory. Deleting an open file on POSIX systems will succeed, but it will also mean some subsequent log records can be lost as they will be written to the deleted file instead of the new one.
Andrey Semashev wrote:
On 3/4/21 10:04 PM, Peter Dimov via Boost wrote:
Andrey Semashev wrote:
Unfortunately, text_multifile_backend is supposed to open and close file on every log record, as the file name is generated from the log record.
If you maintain a small LRU cache, will it help?
That's what I had in mind, but it will have its own problems.
One of the main use cases for text_multifile_backend is when you want to maintain a separate log for each of the user's business process entity (e.g. a session or a connection of some sort). There can be any number of such entities, and I can't come up with a reasonable limit for a cache in the sink backend. Naturally, the cache will be ineffective if the number of actively logging entities exceeds its capacity. At the same time I don't want to keep any stale open files in the cache.
It seems, I'll have to maintain some sort of a timeout for closing files and cleaning up the cache. But I will only be able to perform the cleanup on log records, which means I'll still have stale open files in cache if there's no logging happening.
Keeping open files is not only a concern from resource usage perspective. It may affect user's experience, as e.g. on Windows he won't be able to remove the open files or the containing directory. Deleting an open file on POSIX systems will succeed, but it will also mean some subsequent log records can be lost as they will be written to the deleted file instead of the new one.
It's definitely not trivial. The right thing to do would probably be to implement a deferred close where a file lingers around for a second or so, then is closed by a background thread. If it's used again within this second, it doesn't need to be closed and reopened.
The right thing to do would probably be to implement a deferred close where a file lingers around for a second or so, then is closed by a background
Peter Dimov via Boost wrote: thread. If
it's used again within this second, it doesn't need to be closed and reopened.
I'd also be happy with just an option on the backend that requires
opting-in to use an unbounded cache. It would be off by default but could
be turned on just like flushing on the regular file stream backend. Like
Andrey pointed out, if your use case involves an unbounded number of log
files, using a cache is going to have complications and shortfalls. But if
your use case is like mine - using the multifile backend instead of having
to declare a bunch of regular streams and filters - just keeping all of the
files open until program termination is exactly what you want.
Thinking a little bit differently, the multifile backend could allow for a
client-supplied callback, run after each record consume, which tells the
backend whether to close the file or leave it open in an unbounded cache.
Then cache management is completely customizable but also not the backend's
problem. This probably makes a lot of sense for the different use cases too:
- By default, there is no callback. The file is always closed.
- For my use case, the callback always returns don't close the file.
- For the use case with a log file for each connection/business process
entity/etc, the client probably knows when they are done with the log file
for that entity (e.g., the socket is closed). They are then responsible for
the callback saying it is time to close the file when the last log entry
for it is issued
- For some unimagined use case, the client can customize however they want.
The callback could even provide info about the open files, last time used,
etc, if the client wanted to do something super customized.
Thoughts?
On Thu, Mar 4, 2021 at 1:56 PM Peter Dimov via Boost
On 3/4/21 10:04 PM, Peter Dimov via Boost wrote:
Andrey Semashev wrote:
Unfortunately, text_multifile_backend is supposed to open and close file on every log record, as the file name is generated from the log record.
If you maintain a small LRU cache, will it help?
That's what I had in mind, but it will have its own problems.
One of the main use cases for text_multifile_backend is when you want to maintain a separate log for each of the user's business process entity (e.g. a session or a connection of some sort). There can be any number of such entities, and I can't come up with a reasonable limit for a cache in the sink backend. Naturally, the cache will be ineffective if the number of actively logging entities exceeds its capacity. At the same time I don't want to keep any stale open files in the cache.
It seems, I'll have to maintain some sort of a timeout for closing files and cleaning up the cache. But I will only be able to perform the cleanup on log records, which means I'll still have stale open files in cache if
happening.
Keeping open files is not only a concern from resource usage
Andrey Semashev wrote: there's no logging perspective. It
may affect user's experience, as e.g. on Windows he won't be able to remove the open files or the containing directory. Deleting an open file on POSIX systems will succeed, but it will also mean some subsequent log records can be lost as they will be written to the deleted file instead of the new one.
It's definitely not trivial.
The right thing to do would probably be to implement a deferred close where a file lingers around for a second or so, then is closed by a background thread. If it's used again within this second, it doesn't need to be closed and reopened.
_______________________________________________ Unsubscribe & other changes: http://lists.boost.org/mailman/listinfo.cgi/boost
Nicholas Neumann wrote:
Thinking a little bit differently, the multifile backend could allow for a client- supplied callback, run after each record consume, which tells the backend whether to close the file or leave it open in an unbounded cache.
If you're going to use a client-supplied callback, the most straightforward one would just return a shared_ptr<FILE> (or the appropriate equivalent). Then both opening and closing are under the callback's control. E.g. the simple one would just do shared_ptr<FILE> callback( char const* fn ) { if( FILE* f = std::fopen( fn, "rb" ) ) return shared_ptr<FILE>( f, std::fclose ); else return shared_ptr<FILE>; } whereas a simple caching one would instead do shared_ptr<FILE> callback( char const* fn ) { if( s_cache.count( fn ) ) { return s_cache[ fn ]; } else if( FILE* f = std::fopen( fn, "rb" ) ) { shared_ptr<FILE> sf( f, std::fclose ); s_cache[ fn ] = sf; return sf; } else return shared_ptr<FILE>; } (mutex locks protecting s_cache omitted for brevity) and a more sophisticated cache would have a flush strategy.
Peter Dimov wrote:
If you're going to use a client-supplied callback, the most straightforward one would just return a shared_ptr<FILE> (or the appropriate equivalent). Then both opening and closing are under the callback's control.
That's interesting to think about. A simultaneous pro and con I see is that the callback now has to deal with how to open and close a file, which was an implementation detail of the backend before. If you want or need that level of control, it is useful. But a callback which asks "close the file?" only has to take a path and return a boolean, leaving most of the concerns to the backend. Both allow for any caching strategy. Either one works for me so if the shared_ptr<FILE> approach solves problems for others that the boolean approach does not, I'd be just as happy with it.
On 5/03/2021 5:26 pm, Nicholas Neumann wrote:
Peter Dimov wrote:
If you're going to use a client-supplied callback, the most straightforward one would just return a shared_ptr<FILE> (or the appropriate equivalent). Then both opening and closing are under the callback's control.
That's interesting to think about. A simultaneous pro and con I see is that the callback now has to deal with how to open and close a file, which was an implementation detail of the backend before. If you want or need that level of control, it is useful. But a callback which asks "close the file?" only has to take a path and return a boolean, leaving most of the concerns to the backend. Both allow for any caching strategy. Either one works for me so if the shared_ptr<FILE> approach solves problems for others that the boolean approach does not, I'd be just as happy with it.
To fix that, you could have the callback return void and take the shared_ptr as a parameter instead -- keeping it alive keeps the file open. The callback would only be called when the framework needs to open a new file (or a new pointer to an existing file), not when re-using an existing pointer. The problem is that now both sides have to keep track of this pointer and its context (inside the framework, as a weak_ptr; outside, as a shared_ptr), which has some overhead, especially if the logging system is intended to be multi-thread-safe. Depending on where the callback is attached and how it's used, this may be straightforward or complicated. (Also, using FILE directly ties the implementation to C++ iostreams; it would be better to use an abstraction instead.)
Gavin Lambert wrote:
To fix that, you could have the callback return void and take the shared_ptr as a parameter instead -- keeping it alive keeps the file open. The callback would only be called when the framework needs to open a new file (or a new pointer to an existing file), not when re-using an existing pointer.
That's interesting too, but also more involved to implement afaict. The boolean callback is super simple for the client to use, and for the backend to implement. I feel like there should be a solid use case someone would really like solved to prefer the more complicated approaches (making the client responsible for opening the file, or having the client manage lifetime via shared_ptr). I'll admit I'm biased because my use case doesn't require that, but I don't immediately see what such a use case would be.
Nicholas Neumann wrote:
Peter Dimov wrote:
If you're going to use a client-supplied callback, the most straightforward one would just return a shared_ptr<FILE> (or the appropriate equivalent). Then both opening and closing are under the callback's control.
That's interesting to think about. A simultaneous pro and con I see is that the callback now has to deal with how to open and close a file, which was an implementation detail of the backend before. If you want or need that level of control, it is useful. But a callback which asks "close the file?" only has to take a path and return a boolean, leaving most of the concerns to the backend. Both allow for any caching strategy. Either one works for me so if the shared_ptr<FILE> approach solves problems for others that the boolean approach does not, I'd be just as happy with it.
The boolean callback only allows for "never cache" and "cache forever" strategies, unless I'm missing something. That is, it allows the backend to implement other caching strategies, but not the user writing the callback.
On 5/03/2021 6:23 pm, Peter Dimov wrote:
The boolean callback only allows for "never cache" and "cache forever" strategies, unless I'm missing something. That is, it allows the backend to implement other caching strategies, but not the user writing the callback.
Presumably, to implement other strategies it would have to be called on every log attempt (or at least whenever the framework considers closing the file, which might be after a no-logging timeout or something instead). This is an advantage of the shared_ptr approach, it gives the controller more control (at the disadvantage of more responsibility).
On 04/03/2021 19:34, Andrey Semashev via Boost wrote:
Unfortunately, text_multifile_backend is supposed to open and close file on every log record, as the file name is generated from the log record.
If you maintain a small LRU cache, will it help?
That's what I had in mind, but it will have its own problems.
One of the main use cases for text_multifile_backend is when you want to maintain a separate log for each of the user's business process entity (e.g. a session or a connection of some sort). There can be any number of such entities, and I can't come up with a reasonable limit for a cache in the sink backend. Naturally, the cache will be ineffective if the number of actively logging entities exceeds its capacity. At the same time I don't want to keep any stale open files in the cache.
It seems, I'll have to maintain some sort of a timeout for closing files and cleaning up the cache. But I will only be able to perform the cleanup on log records, which means I'll still have stale open files in cache if there's no logging happening.
You're thinking in terms of POSIX. On Windows, files have an intermediate state of being-deleted. So what you can do is: 1. Have an async thread keep a pool of file handles full. You open these handles to randomly named files, and once opened, you mark them for deletion. 2. When you need to "create" a new file, you unmark a handle for deletion, and rename it to what you need. All this can be done with SetFileInformationByHandle. 3. If there is sudden process exit, or sudden power loss, all files marked for deletion are actually deleted. So no need to clean caches on a timer or anything like that. If you are on a new enough Windows 10, you can make the entire file entry vanish when you mark it for deletion, rather like O_TMPFILE on Linux. You can then make it reappear on an as-needed basis. On older Windows, the file entry will still appear in directory listings, but will be unopenable.
Keeping open files is not only a concern from resource usage perspective. It may affect user's experience, as e.g. on Windows he won't be able to remove the open files or the containing directory.
You can delete or rename open files on Windows just fine. It's just std::ofstream opens files in a way where you can't. Another suggestion is that any decent Windows AV will not scan files incapable of holding executable code for binary viruses. std::ofstream opens files capable of holding executable code, so everything written to them must be scanned deeply. If you instead create a file without executability privileges, the AV should only scan for a small subset of potential malcontent. Niall
On 3/5/21 12:36 PM, Niall Douglas via Boost wrote:
On 04/03/2021 19:34, Andrey Semashev via Boost wrote:
Unfortunately, text_multifile_backend is supposed to open and close file on every log record, as the file name is generated from the log record.
If you maintain a small LRU cache, will it help?
That's what I had in mind, but it will have its own problems.
One of the main use cases for text_multifile_backend is when you want to maintain a separate log for each of the user's business process entity (e.g. a session or a connection of some sort). There can be any number of such entities, and I can't come up with a reasonable limit for a cache in the sink backend. Naturally, the cache will be ineffective if the number of actively logging entities exceeds its capacity. At the same time I don't want to keep any stale open files in the cache.
It seems, I'll have to maintain some sort of a timeout for closing files and cleaning up the cache. But I will only be able to perform the cleanup on log records, which means I'll still have stale open files in cache if there's no logging happening.
You're thinking in terms of POSIX.
Indeed. I'm not using Windows very often, so I might be biased. Frankly, I'm writing code with POSIX in mind by default and add workarounds for Windows, when necessary.
On Windows, files have an intermediate state of being-deleted. So what you can do is:
1. Have an async thread keep a pool of file handles full. You open these handles to randomly named files, and once opened, you mark them for deletion.
2. When you need to "create" a new file, you unmark a handle for deletion, and rename it to what you need. All this can be done with SetFileInformationByHandle.
3. If there is sudden process exit, or sudden power loss, all files marked for deletion are actually deleted. So no need to clean caches on a timer or anything like that.
If you are on a new enough Windows 10, you can make the entire file entry vanish when you mark it for deletion, rather like O_TMPFILE on Linux. You can then make it reappear on an as-needed basis. On older Windows, the file entry will still appear in directory listings, but will be unopenable.
An interesting idea, but I'd prefer if the backend behaved roughly the same on POSIX and Windows. Besides, I'd prefer to avoid spawning threads in the backend, as Boost.Log currently only creates threads for asynchronous logging and never else. Even then the user can provide his own threads.
Keeping open files is not only a concern from resource usage perspective. It may affect user's experience, as e.g. on Windows he won't be able to remove the open files or the containing directory.
You can delete or rename open files on Windows just fine. It's just std::ofstream opens files in a way where you can't.
But the containing directory remains locked, doesn't it?
Another suggestion is that any decent Windows AV will not scan files incapable of holding executable code for binary viruses. std::ofstream opens files capable of holding executable code, so everything written to them must be scanned deeply. If you instead create a file without executability privileges, the AV should only scan for a small subset of potential malcontent.
This might be useful to do. How do you specify that a file is not executable on Windows? There are dwDesiredAccess flags for CreateFile[1], but my understanding is that they describe the access granted through the returned handle and not permissions of the actual file. [1]: https://docs.microsoft.com/en-us/windows/win32/api/fileapi/nf-fileapi-create...
On 05/03/2021 10:45, Andrey Semashev via Boost wrote:
On Windows, files have an intermediate state of being-deleted. So what you can do is:
1. Have an async thread keep a pool of file handles full. You open these handles to randomly named files, and once opened, you mark them for deletion.
2. When you need to "create" a new file, you unmark a handle for deletion, and rename it to what you need. All this can be done with SetFileInformationByHandle.
3. If there is sudden process exit, or sudden power loss, all files marked for deletion are actually deleted. So no need to clean caches on a timer or anything like that.
If you are on a new enough Windows 10, you can make the entire file entry vanish when you mark it for deletion, rather like O_TMPFILE on Linux. You can then make it reappear on an as-needed basis. On older Windows, the file entry will still appear in directory listings, but will be unopenable.
An interesting idea, but I'd prefer if the backend behaved roughly the same on POSIX and Windows. Besides, I'd prefer to avoid spawning threads in the backend, as Boost.Log currently only creates threads for asynchronous logging and never else. Even then the user can provide his own threads.
I appreciate that, but the two systems are very different. Using the same design patterns for both, imposing one design pattern on a platform on which it performs very badly, personally speaking I don't find that a high Quality of Implementation. i.e. When in Rome, do as the Romans do.
Keeping open files is not only a concern from resource usage perspective. It may affect user's experience, as e.g. on Windows he won't be able to remove the open files or the containing directory.
You can delete or rename open files on Windows just fine. It's just std::ofstream opens files in a way where you can't.
But the containing directory remains locked, doesn't it?
Locked in the sense that it cannot be renamed or deleted, yes. The simple workaround is to rename the file out of its directory before you delete it, then the containing directory behaves like on POSIX. Recent Windows 10 implement "POSIX delete" by renaming the file into a magic hidden NTFS folder in the root called \$Extend\$Deleted, and marking it as in-process-of-being-deleted. That same technique works right back to NT 3.5.
Another suggestion is that any decent Windows AV will not scan files incapable of holding executable code for binary viruses. std::ofstream opens files capable of holding executable code, so everything written to them must be scanned deeply. If you instead create a file without executability privileges, the AV should only scan for a small subset of potential malcontent.
This might be useful to do. How do you specify that a file is not executable on Windows? There are dwDesiredAccess flags for CreateFile[1], but my understanding is that they describe the access granted through the returned handle and not permissions of the actual file.
[1]: https://docs.microsoft.com/en-us/windows/win32/api/fileapi/nf-fileapi-create...
A file can be capable of execution according to its ACL. A file handle can be capable of executing code according to its privileges (dwDesiredAccess contains FILE_GENERIC_EXECUTE). You can create a file with an ACL not permitting execution using lpSecurityAttributes, or use hTemplateFile to clone a security descriptor. Or, you can temporarily adjust the current thread's impersonation token such that specifying NULL to CreateFile means files created by that thread aren't executable. The former is best when you can adjust source code, the latter is best when you are calling third party code and you want it to create different permissioned files. Note that I don't actually know if the Windows default AV is clever enough to not deep scan files without Execute ability. I do know it specially skips files signed by a whitelist of Microsoft approved signing authorities, and it was written by Microsoft themselves who suffer the most from it, so your chances are good. (Incidentally, to anyone not aware yet, you can exclude whole directory trees from Microsoft Defender realtime analysis. Just add your MSVC directory, your WSL directory (this makes a HUGE difference to WSL), all your build directories, all tooling and source directories, and so on. Build times approximately halve) Niall
On 3/5/21 3:56 PM, Niall Douglas via Boost wrote:
On 05/03/2021 10:45, Andrey Semashev via Boost wrote:
Keeping open files is not only a concern from resource usage perspective. It may affect user's experience, as e.g. on Windows he won't be able to remove the open files or the containing directory.
You can delete or rename open files on Windows just fine. It's just std::ofstream opens files in a way where you can't.
But the containing directory remains locked, doesn't it?
Locked in the sense that it cannot be renamed or deleted, yes.
The simple workaround is to rename the file out of its directory before you delete it, then the containing directory behaves like on POSIX.
But I'm not the one deleting the file. The hypothetical use case is that the logging backend keeps the file open for possible future writing and the user attempts to delete the file and the containing folder.
Recent Windows 10 implement "POSIX delete" by renaming the file into a magic hidden NTFS folder in the root called \$Extend\$Deleted, and marking it as in-process-of-being-deleted. That same technique works right back to NT 3.5.
Seems like a workaround rather than a fix, which would have been to allow deleting the folder if it only contains files in-process-of-being-deleted. Or just get rid of this weird state entirely.
A file can be capable of execution according to its ACL.
A file handle can be capable of executing code according to its privileges (dwDesiredAccess contains FILE_GENERIC_EXECUTE).
You can create a file with an ACL not permitting execution using lpSecurityAttributes, or use hTemplateFile to clone a security descriptor. Or, you can temporarily adjust the current thread's impersonation token such that specifying NULL to CreateFile means files created by that thread aren't executable. The former is best when you can adjust source code, the latter is best when you are calling third party code and you want it to create different permissioned files.
Note that I don't actually know if the Windows default AV is clever enough to not deep scan files without Execute ability. I do know it specially skips files signed by a whitelist of Microsoft approved signing authorities, and it was written by Microsoft themselves who suffer the most from it, so your chances are good.
I suppose, an argument can be made "what if the user changes permissions later and tries to execute the file?" From that perspective, the antivirus should be scanning everything always.
Niall Douglas wrote: ...
You can delete or rename open files on Windows just fine. It's just std::ofstream opens files in a way where you can't.
Another suggestion is that any decent Windows AV will not scan files incapable of holding executable code for binary viruses. std::ofstream opens files capable of holding executable code, so everything written to them must be scanned deeply. If you instead create a file without executability privileges, the AV should only scan for a small subset of potential malcontent.
Niall, your experience is deeply appreciated and your messages are very informative, but they would be even more useful if you actually say how things you describe are done. How should one open the file correctly so that it can be deleted and renamed while open, and has no executable privileges?
Peter Dimov wrote:
The boolean callback only allows for "never cache" and "cache forever" strategies, unless I'm missing something. That is, it allows the backend to implement other caching strategies, but not the user writing the callback.
So for the boolean callback, I was envisioning the callback being invoked
after every log record consumption. This would allow the client to remove
an item from the cache for a variety of reasons. The callback could track
how big the cache is and remove when a size is exceeded, or could have
client-side knowledge that the last entry to the log file has been written,
etc. Apologies if I'm missing something or it's not clear - I could provide
some sample pseudocode if useful. The backend has an unbounded cache
indexed by path, but removes from the cache whenever the callback returns
false. The callback can then maintain a set of paths being cached and
implement whatever policy it wants to decide when to remove from that set
and return false.
With the shared_ptr approach you outlined, the callback is also per log
record consumption, right? (Just before writing to the file instead of
after.) With the modification Gavin Lambert suggested, I think it is a bit
different, where the shared_ptr lifetime actually is how the cache is
managed, which is definitely more flexible for the client (a cache entry
could be purged at any point, instead of only when a log record is being
consumed) but requires some more care to implement in the backend.
On Fri, Mar 5, 2021 at 10:26 AM Peter Dimov via Boost
Niall Douglas wrote: ...
You can delete or rename open files on Windows just fine. It's just std::ofstream opens files in a way where you can't.
Another suggestion is that any decent Windows AV will not scan files incapable of holding executable code for binary viruses. std::ofstream opens files capable of holding executable code, so everything written to them must be scanned deeply. If you instead create a file without executability privileges, the AV should only scan for a small subset of potential malcontent.
Niall, your experience is deeply appreciated and your messages are very informative, but they would be even more useful if you actually say how things you describe are done. How should one open the file correctly so that it can be deleted and renamed while open, and has no executable privileges?
_______________________________________________ Unsubscribe & other changes: http://lists.boost.org/mailman/listinfo.cgi/boost
On 05/03/2021 16:26, Peter Dimov via Boost wrote:
You can delete or rename open files on Windows just fine. It's just std::ofstream opens files in a way where you can't.
Another suggestion is that any decent Windows AV will not scan files incapable of holding executable code for binary viruses. std::ofstream opens files capable of holding executable code, so everything written to them must be scanned deeply. If you instead create a file without executability privileges, the AV should only scan for a small subset of potential malcontent.
Niall, your experience is deeply appreciated and your messages are very informative, but they would be even more useful if you actually say how things you describe are done. How should one open the file correctly so that it can be deleted and renamed while open, and has no executable privileges?
Everybody was reading the Microsoft API docs already, so I figured you just follow what they tell you. But to summarise those docs: Share mode needs to be FILE_SHARE_READ | FILE_SHARE_WRITE | FILE_SHARE_DELETE and privs need to include DELETE if you want to be able to delete and rename it when open. Use https://docs.microsoft.com/en-us/windows/win32/api/fileapi/nf-fileapi-setfil... to do renames and deletes. For renames, use FILE_RENAME_INFO. For marking and unmarking a file as delete-on-close, use FILE_DISPOSITION_INFORMATION. To create a file without executable in its ACL, probably the least efficient, but easiest, way is using ConvertStringSecurityDescriptorToSecurityDescriptor() to make a SECURITY_DESCRIPTOR. You can create it once and reuse it however. Purely off the top of my head, something like: D:(A;;GRGW;;;AU) ... would grant Access of GenericRead GenericWrite to AuthenticatedUsers. Obviously you'd need more than that, the default ACL within Users on Windows is: SYSTEM: Full Control Administrators: Full Control OWNER: Full control So you'd want OWNER dropped to GRGW, and move OWNER to the top of the ACL list so it gets matched before Administrators. I hope this is more useful to you. Niall
After some more playing with the backend with an unbounded cache, I had a couple interesting findings to share. First, by optimizing stuff on the client side, I was able to get to about 67K log entries per second, with flush after each consume. I profiled this (both in debug and release) and noticed a lot of time spent in path hasing/key compares (cache is just a std::unordered_map from boost::filesystem::path to std::unique_ptrboost::filesystem::ofstream). Changing the cache to be indexed by string (and only forming a boost::filesystem::path when a cached stream doesn't exist) improved throughput to 100K log entries per second, which is pretty substantial. All of that is to say that for my use case too I now see a nice reason to have more than just a boolean callback. I'm not sure that means I'd want or need ability to do the file opening and closing myself, but in some sense, why not? The backend could provide the default functions for the callback to call, making it easy for those that don't want to customize, but customizable for those that do. It also means that rather than having the callback have the path as an input, I'd want it to just give me the log record. Forming the path and working with it can be a lot more expensive than looking at the single entry in the log record that determines the path. I realize now I've gone from "a callback mechanism would be great to make this backend performant on windows" to "it would be great if the callback mechanism allowed me all kinds of options to squeeze even more performance out of the backend". :-) But maybe that starts to make it attractive to linux users as well?
A quick correction. I noticed my performance numbers were not super reliable - my log output directory was on my c drive, which is a bad idea as OS reads/writes will have a greater impact on numbers. I moved the output to a separate, faster drive. There with the cache keyed on path, throughput was 94K, while with cache keyed on the string representation of the path, throughput was 110K. Tweaking further, I could key the cache just on channel name (based on my logging output structure), and that got me to 120K. So while still a good improvement, not quite as dramatic as I first thought.
On 3/3/21 11:28 PM, Peter Dimov via Boost wrote: That's probably a Windows Defender (or another antivirus) "feature". Not
On 3/4/21 03:35 AM, Andrey Semashev via Boost wrote: that
this helps.
It does help. Nicholas, could you verify this by adding the directory where log files are written to the excluded ones in the AV software you have? Or by temporarily disabling the software?
Nice catch Peter. Simply turning off the built in realtime AV takes me from throughput on order of 200-300 messages per second to 5700 messages per second. So better, but still not great. The (imho) sad thing on windows is that disabling A/V has gotten progressively harder with each windows 10 release, especially for the average user. Realistically it's bad enough that developers might as well assume it will always be on for end users, and even fellow developers. On 3/4/21 03:42 AM, Andrey Semashev via Boost wrote:
I'm not sure I feel good about documenting it, as it doesn't really solve the problem. I suppose, I could add a cache of the least recently used files to keep them open, but that cache would be ineffective if exceeded, which can happen in some valid cases (e.g. writing logs pertaining to a given dynamically generated "id" to a separate log). And it would only be useful on Windows.
Just to get a feel for the performance improvement, I quickly implemented caching all of the destination paths with an unordered_map. Every log record consume does a flush. Throughput went to about 53000 log records per second (with or without A/V). Quick performance profiling of that shows obvious bottlenecks gone at this point - removing the flush will get me to 91K log records per second (with or without A/V). Further rate improvements could be made by optimizing my formatter or file_name_composer, which are not the backend's concern. On 3/4/21 10:39 AM, Andrey Semashev via Boost wrote:
Unfortunately, text_multifile_backend is supposed to open and close file on every log record, as the file name is generated from the log record.
That makes sense. For my use case, I'm using text_multifile_backend to write to different files based on the channel in the record, and I've got on the order of 10-20 channels. I could do multiple regular streams with appropriate filters, but that would require declaring the channels I'm going to encounter ahead of time. Not having to do that is really nice. :-) I could see a lot of folks using text_multifile_backend like this (where there is a reasonable limit on how many distinct paths are actually created by the backend), where having a cache (with or even without flush) would be fine. For cases where there is no such limit, it makes less sense. And of course if every log record is going to a different file, no amount of caching is going to help with the windows file open/close slowness. On 3/4/21 10:39 AM, Andrey Semashev via Boost wrote:
In any case, I've created a ticket to consider adding a cache of open files:
https://github.com/boostorg/log/issues/142
Also, I've added a note to the docs.
Thanks so much. The note is excellent. The workarounds you mentioned make a lot of sense... multiple regular streams with filters would work, albeit a bit more awkward for a use case like mine. And I imagine an asynchronous frontend would help, although thinking about the CPU cycles wasted is still a little painful. ;-) I think an unbounded cache would be a good option for use cases like mine. Happy to help with any feedback/benchmarking/contributing if it is useful.
On 3/4/21 10:32 PM, Nicholas Neumann via Boost wrote:
On 3/3/21 11:28 PM, Peter Dimov via Boost wrote: That's probably a Windows Defender (or another antivirus) "feature". Not
On 3/4/21 03:35 AM, Andrey Semashev via Boost wrote: that
this helps.
It does help. Nicholas, could you verify this by adding the directory where log files are written to the excluded ones in the AV software you have? Or by temporarily disabling the software?
Nice catch Peter. Simply turning off the built in realtime AV takes me from throughput on order of 200-300 messages per second to 5700 messages per second. So better, but still not great. The (imho) sad thing on windows is that disabling A/V has gotten progressively harder with each windows 10 release, especially for the average user. Realistically it's bad enough that developers might as well assume it will always be on for end users, and even fellow developers.
On 3/4/21 03:42 AM, Andrey Semashev via Boost wrote:
I'm not sure I feel good about documenting it, as it doesn't really solve the problem. I suppose, I could add a cache of the least recently used files to keep them open, but that cache would be ineffective if exceeded, which can happen in some valid cases (e.g. writing logs pertaining to a given dynamically generated "id" to a separate log). And it would only be useful on Windows.
Just to get a feel for the performance improvement, I quickly implemented caching all of the destination paths with an unordered_map. Every log record consume does a flush. Throughput went to about 53000 log records per second (with or without A/V). Quick performance profiling of that shows obvious bottlenecks gone at this point - removing the flush will get me to 91K log records per second (with or without A/V). Further rate improvements could be made by optimizing my formatter or file_name_composer, which are not the backend's concern.
On 3/4/21 10:39 AM, Andrey Semashev via Boost wrote:
Unfortunately, text_multifile_backend is supposed to open and close file on every log record, as the file name is generated from the log record.
That makes sense. For my use case, I'm using text_multifile_backend to write to different files based on the channel in the record, and I've got on the order of 10-20 channels. I could do multiple regular streams with appropriate filters, but that would require declaring the channels I'm going to encounter ahead of time. Not having to do that is really nice. :-)
I could see a lot of folks using text_multifile_backend like this (where there is a reasonable limit on how many distinct paths are actually created by the backend), where having a cache (with or even without flush) would be fine. For cases where there is no such limit, it makes less sense. And of course if every log record is going to a different file, no amount of caching is going to help with the windows file open/close slowness.
I see. Thanks for sharing your use case and the performance numbers. I'll see about the cache in a future release.
Nicholas Neumann wrote:
Nice catch Peter. Simply turning off the built in realtime AV takes me from throughput on order of 200-300 messages per second to 5700 messages per second. So better, but still not great. The (imho) sad thing on windows is that disabling A/V has gotten progressively harder with each windows 10 release, especially for the average user. Realistically it's bad enough that developers might as well assume it will always be on for end users, and even fellow developers.
It's horrible. Simply running the Boost tests sends multiple samples to "the cloud", which is at least tolerable. But creating an installer package using Inno Setup automatically makes Windows Defender delete it on sight the instant it's downloaded. Apparently, some malware used Inno Setup to package itself, so now nobody can use it. Plus, every new release of Boost is flagged as malware, despite not having any executable files in it. Sorry for the unrelated rant. :-)
participants (5)
-
Andrey Semashev -
Gavin Lambert -
Niall Douglas -
Nicholas Neumann -
Peter Dimov