[boost] boost.log's text_multifile_backend is not performant on windows - perhaps it should be documented?

[Nicholas Neumann via Boost]

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/
)

_______________________________________________
Unsubscribe & other changes: http://lists.boost.org/mailman/listinfo.cgi/boost

[Peter Dimov via Boost]

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.

[Andrey Semashev via Boost]

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?

[Andrey Semashev via Boost]

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.

[Niall Douglas via Boost]

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

[Andrey Semashev via Boost]

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-apis

[Peter Dimov via Boost]

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?

[Nicholas Neumann via Boost]

On 3/4/21 03:35 AM, Andrey Semashev 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
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.

[Andrey Semashev 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 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 via Boost]

I see. Thanks for sharing your use case and the performance numbers.
I'll see about the cache in a future release.

[Peter Dimov via Boost]

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. :-)

[Peter Dimov via Boost]

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.

[Nicholas Neumann via Boost]

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 <bo...@lists.boost.org>
wrote:

[Peter Dimov via 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.

[Nicholas Neumann via Boost]

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.

[Gavin Lambert via Boost]

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.)

[Nicholas Neumann via Boost]

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.

[Peter Dimov via Boost]

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.

[Niall Douglas via Boost]

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

[Andrey Semashev via Boost]

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-createfilea

[Niall Douglas via Boost]

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-createfilea

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

[Andrey Semashev via Boost]

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.

[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?

[Nicholas Neumann via Boost]

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 <bo...@lists.boost.org>
wrote:

[Niall Douglas via 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-setfileinformationbyhandle
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

[Nicholas Neumann via Boost]

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_ptr<boost::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?

[Nicholas Neumann via Boost]

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.

[Gavin Lambert via Boost]

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).