Check IsDebuggerPresent in msvc_sink before doing work

[DominikGrabiec]

I'm not sure if everybody will want to do this, so this is just a suggestion and something up for discussion. I've included some code below.

The OutputDebugString function can be relatively slow at times since it has to lock a global mutex before copying your message to a listener. With many applications trying to use this in parallel you can hit contention and slow down your program. One way to mitigate this is to check if a debugger is attached first using IsDebuggerPresent before doing any processing work and calling OutputDebugString.

The IsDebuggerPresent function itself just checks a global flag in your process address space, so it doesn't need to lock or go into the kernel, so it is quite fast and can be checked before each call.

I've seen people call it once at program startup when setting up logging, so if a debugger is not attached you skip initialising that sink. In this case you do end up missing all logging output when you later attach a debugger to the running process.

The one down side I see of checking if a debugger is attached before sinking every log message is that you won't see your debug output in something like Sysinternals DebugView tool. But realistically you should be able to hook up a different logging sink if you want a live feed.

The code changes required are adding this forward declare:

extern "C" __declspec(dllimport) int __stdcall IsDebuggerPresent();

Then changing the body of msvc_sink.h to something like:

        if (IsDebuggerPresent()) // Check if debugger is attached before sinking
        {
            memory_buf_t formatted;
            base_sink<Mutex>::formatter_->format(msg, formatted);
            formatted.push_back('\0'); // add a null terminator for OutputDebugStringA
            OutputDebugStringA(formatted.data());
        }

[gabime]

Seems like good idea. How fast is IsDebuggerPresent ? If we going to call it for each log we must be sure.

[DominikGrabiec]

The IsDebuggerPresent function checks the PEB structure in the process if the flag is set. This is pretty much the same as checking a global variable in your own code before logging something.

I made this change - from checking once at startup and adding the OutputDebugString logger to checking before each log message sink - in a large AAA game engine and did not notice any degradation of performance in both the game while it was being debugged nor in the data processing pipeline.

[gabime]

Well in this case this seems fine.
I am not sure whether to provide an option to use old behavior (or perhaps vise versa to maintain backward compatibility - turn on new behavior only if enable_debugger_presence_check() is called)

[DominikGrabiec]

• The simplest way to implement this for someone using the library would be to create a new class deriving from the existing msvc_sink and put the check in that. For a library author it might not be the best idea because then you'll have two msvc classes which could lead to confusion.
• If instead you put in an #ifdef or if consteval or something around the debugger check, then you give a configuration point and complicate the library and code. You also wouldn't be able to switch it at runtime.
• The third option is to add another runtime check so you'd first check if we want to check then check if it's enabled, which is adding a bit more runtime overhead to what is otherwise a lean system.

This is the hard part of library design.

The strongest argument I have for not adding the IsDebuggerPresent check is that it will change the timings of when the code is running with and without the debugger attached. This could affect timings and show/hide issues with threads.

Maybe the answer is for me to implement my own msvc_sink class in my own code with this behaviour and be done with it, so the library version can remain simple and more deterministic.

[gabime]

If there is a big performance gain (any numbers?) It is certainly worth while to add to spdlog as an option.

[sylveon]

FWIW I already have such an implementation in my code:

class debug_sink final : public spdlog::sinks::base_sink<spdlog::details::null_mutex> {
protected:
	void sink_it_(const spdlog::details::log_msg &msg) override
	{
		if (IsDebuggerPresent())
		{
			spdlog::memory_buf_t formatted;
			this->formatter_->format(msg, formatted);
			formatted.push_back('\0');

			OutputDebugStringA(formatted.data());
		}
	}

	void flush_() noexcept override
	{ }
};

I am not opposed to making this part of the built-in MSVC sink

[DominikGrabiec]

Sorry for the delayed response, I don't really have any real numbers to show regarding performance.
I just recall when others have tested the impact of always logging to OutputDebugString, and when I tested the impact of putting the if check in the code.

In my current (non-game) project I figured it would be easiest to just implement it myself and so wrote this:

template <typename Mutex>
class vs_debugger_sink : public spdlog::sinks::msvc_sink<Mutex>
{
public:
	vs_debugger_sink() = default;

protected:
	void sink_it_(const spdlog::details::log_msg& msg) override
	{
		if (IsDebuggerPresent())
		{
			spdlog::sinks::msvc_sink<Mutex>::sink_it_(msg);
		}
	}
};

using vs_debugger_sink_mt = vs_debugger_sink<std::mutex>;

[Benichou34]

Please note that "OutputDebugString" doesn't necessarily need a debugger. Applications like DebugView can receive these messages.
If we consider this case, IsDebuggerPresent() should not be used in the sink_it method.

[gabime]

Exactly. Thats why I am hesitating adding this. On the other hand seems like with debugger is the common use and IsDebuggerPresent() probably improves performance significantly.

[gabime]

Changed default behavior to check for debugger using IsDebuggerPresent() . To use old behavior pass false to the msvc_sink constructor.