[Enhancement] Option to log thread name

[nuertey]

Awesome logging library. Thanks. I added a little code to it in order to be able to log thread names for a personal project. I am sharing so if others find it useful it can make it into the library. I tested the Linux portion and it works. I don't have access to a Windows machine so could not test that part.

Requirement

Introduce a new flag (%q) in pattern formatter to represent thread name. To use, try something like this:
spdlog::set_pattern("%H:%M:%S %z - %^%l%$ - %^[thread %t = %q]%$ -> %v");

Solution

Leverage the prctl() system call on Unix-like OSes and the new GetThreadDescription() function on Windows to retrieve the thread name.

Example

spdlog::set_pattern("%H:%M:%S %z - %^%l%$ - %^[thread %t = %q]%$ -> %v");
....

Files Changed

include/spdlog/details/log_msg.h 
include/spdlog/details/os.h 
include/spdlog/details/pattern_formatter_impl.h

Code located at : https://github.com/nuertey/spdlog

[gabime]

Thanks. Looks useful.

Few suggestions:

• This won't work in async mode (async_log_msg need to updated)

• Calling os::thread_name(theThreadName, sizeof(theThreadName)) on each log_msg creation seems slow. It should be only called by the formatter when really needed (using the msg.thread_id variable, and hence, no need to store the thread_name in the log_ms)

[nuertey]

I think I understand what you mean. I have made those changes (as I understood them) in my codebase. It is tested in Linux again and pushed to my copy of your repo https://github.com/nuertey/spdlog.

If my understanding of your suggestions are accurate, consequences of these changes are :

1) No speed degradation of the original implementation as os::thread_name() does not have to be called on each log_msg creation. 

2) A further side-effect of 1) is the point you brought up about not needing to store the thread_name in the log_msg struct. Further, with this new scheme, async_msg does not have to be updated.

3) The new '%q' flag becomes superfluous then as we are now tieing the thread_name to the presence of the msg.thread_id variable. This implies that the new q_formatter class is not needed and can be deleted. A benefit of this is, no need to update the Wiki to account for this new flag.

4) The meaning of the '%t' flag now changes then to ALWAYS imply "<thread_id> = <thread_name>" in the formatter.

Let me know if I misunderstood or missed anything.
Thanks
Nuertey

[gabime]

I wouldn't change the %t flag meaning. We should maintain backward compatible. I would add a %q flag.

Also, maybe bench to see if storing once the thread name in thread local storage improves performance instead of querying the thread name for each call.

[nuertey]

Definitely, it makes sense that the thread local storage of the thread name would be faster than making the call on each log. I haven't had time to benchmark both options but because it makes obvious sense what you suggest, I have made that change.
Nuertey

https://github.com/nuertey/spdlog

[arthur-tacca]

I notice that suggested change uses GetThreadDescription on Windows. That only works on Windows 10, but I think there are a lot of people still using older versions of Windows.

My suggestion would be to create a spdlog-specific call to set the thread name, which just stores the passed-in value in a thread-local string. This would have a few benefits:

• Better cross platform support (old versions of Windows and maybe other platforms)
• Useful if you don't want the thread name in the log to exactly match its OS name (e.g. 15 character restriction on Linux, don't want internal name to show up on top/ps).
• People could use (/abuse) the spdlog thread name to store some other information that they want to be included in log messages but not all log clients have direct access to e.g. what network request the thread is currently handling
• Simpler implementation in spdlog (no platform-specific code)

[nuertey]

Arthur-tacca,
Definitely, I could implement your suggestion to "create a spdlog-specific call to set the thread name, which just stores the passed-in value in a thread-local string." This is doable and then the fallback case on that string being empty is to query as I have already provided for Windows 10 and POSIX. This way it does not become an absolute requirement that it must be set.

I think the bigger issue as you probably sensed yourself is this begins to lead to issue #617 and whether we really should generalize these potential extra diagnostic info.

What issue #617 seems to be proposing is rather like log4cxx's Mapped Diagnostic Context. It is a per-thread scheme used to distinguish interleaved log output from different sources. See their documentation here : https://svn.apache.org/repos/asf/logging/site/trunk/docs/log4cxx/apidocs/classlog4cxx_1_1_m_d_c.html and accompanying format specifiers (aka conversion characters) here : https://svn.apache.org/repos/asf/logging/site/trunk/docs/log4cxx/apidocs/classlog4cxx_1_1_pattern_layout.html

I think we have to be very careful to not introduce a correct but unwieldy solution that might affect the performance bottom-line of spdlog. It would be interesting to assess how many folks out there do really need such a generic solution and if not, what performance costs they are willing to incur for having that general solution.

Having said that, certainly what you do suggest is doable. And in fact before finding spdlog and its awesomeness, when I used to use log4cxx, I would use their MDC feature to achieve your exact aims in such a way :

// In a unique user's thread context :
// ...
log4cxx::MDC::put("threadName", "My_Unique_ThreadName"); // Could also be an std::string retrieved from the OS-specific thread name of course.


// And then in the log4cxx XML configuration file, I would do something like this :
// ...
<layout class="org.apache.log4j.PatternLayout">
    <param name="ConversionPattern" value="%d %-5p [%X{threadName}] %C{2} (%F:%L) - %m%n" />
</layout>

I never delved into the MDC's implementation of log4cxx to assess its true costs though so take my comment with a caveat.

[mattgodbolt]

+1 on this one -- being able to name the threads (via thread_local, or access to Linux-style prctl in the message, or ... anything), would be fabulous.

[gabime]

FYI, spdlog now have an option to customize pattern flags. This makes it possible to customize the %t flag to display thread name.

[nuertey]

Good to know. Excellent work.

[swimmingmachine]

@nuertey I am on Windows OS. When I replaced the original .h files with the three changed .h files, there was an error saying sys/prctl.h not found in my Qt Creator IDE. I know that file is for Unix-like OSes, but there were more errors after I commented out that include. Please advise how to solve this problem. Thank you.

[nuertey]

@swimmingmachine :) gosh it has been 3 years since that my thread naming enhancement to spdlog. I am not even sure I have access to my original workspace still. And note that @gabime may have modified the APIs and enhanced things further since then. So reach out to @gabime and let him suggest how best to accomplish your aims with his latest code. Due to being severely entrenched in other projects, I am out of touch with spdlog.

Thanks for reaching out though. So let us wait till @gabime comments. He is the original author of excellent spdlog... so he will have better info for you than me.
Regards
Nuertey

[tt4g]

@swimmingmachine Please see the Wiki for how to create a custom formatter.
Extending spdlog with your own flags: https://github.com/gabime/spdlog/wiki/3.-Custom-formatting

If you need the thread name, get it in your custom formatter.
Note that spdlog messages only have thread ID.

spdlog/include/spdlog/details/log_msg-inl.h

Lines 15 to 25 in 0ca574a

	SPDLOG_INLINE log_msg::log_msg(spdlog::log_clock::time_point log_time, spdlog::source_loc loc, string_view_t a_logger_name,
	spdlog::level::level_enum lvl, spdlog::string_view_t msg)
	: logger_name(a_logger_name)
	, level(lvl)
	, time(log_time)
	#ifndef SPDLOG_NO_THREAD_ID
	, thread_id(os::thread_id())
	#endif
	, source(loc)
	, payload(msg)
	{}

spdlog/include/spdlog/details/os-inl.h

Lines 365 to 374 in 0ca574a

	// Return current thread id as size_t (from thread local storage)
	SPDLOG_INLINE size_t thread_id() SPDLOG_NOEXCEPT
	{
	#if defined(SPDLOG_NO_TLS)
	return _thread_id();
	#else // cache thread id in tls
	static thread_local const size_t tid = _thread_id();
	return tid;
	#endif
	}

The easiest way is to save the thread name in the thread_local variable.
See also: https://stackoverflow.com/questions/10121560/stdthread-naming-your-thread

Another way.
On Windows, you can get the thread name with the GetThreadDescription() function, but this function requires a native-handle as its argument.
If you are not using an asynchronous logger, you can get the current thread handle with GetCurrentThread().
This API should be available in Windows 10.
See also: https://stackoverflow.com/questions/9366722/how-to-get-the-name-of-a-win32-thread

Tip
In C++11, you can get a native-handle from std::thread::native_handle(), but you need a std::thread object to call this function.

[nuertey]

Hi @swimmingmachine,
Adding to the excellent info that @tt4g has provided you, attached is an excerpt from one of my personal project files where threading prominently featured.

From that excerpt, you can see that you can use many different APIs to set and retrieve thread names; this goes to @tt4g tip about C++11 even.

You can set and retrieve thread names via C++11, or even via any POSIX-supporting OS calls such as pthread_setname_np() or via prctl() or via GetThreadDescription() Windows-like API calls as pointed out by @tt4g.

Here is the reference to C++11 'std::thread' :

https://en.cppreference.com/w/cpp/thread/thread/native_handle

Note that in my attached excerpt of those thread set and get implementations, I have omitted other implementations that are extraneous to your actual question; Implementations such as NonInterspersedLog<>, which I simply implemented like this below, in case you are curious:

// Log colored output to the console but in a truly thread-safe and 
// non-interleaved character way:

// Due to a more involved syntax when invoking template lambdas, 
// rather prefer template function to a C++20 template lambda.
template <typename T, typename... Args>
inline void NonInterspersedLog(const std::string_view& logMessage,
                               const Args&... args)
{
    static_assert((std::is_same_v<T, DebugLog_t>
                || std::is_same_v<T, TraceLog_t>
                || std::is_same_v<T, InfoLog_t>
                || std::is_same_v<T, ErrorLog_t>
                || std::is_same_v<T, WarnLog_t>
                || std::is_same_v<T, CriticalLog_t>),
    "Hey! Logging category MUST be one of the following:\n\tDebugLog_t \
                \n\tTraceLog_t \n\tInfoLog_t \n\tErrorLog_t \
                \n\tWarnLog_t \n\tFatalLog_t");
    
    char myThreadName[RECOMMENDED_BUFFER_SIZE];
    GetThreadName(myThreadName, sizeof(myThreadName));
                
    if constexpr (std::is_same_v<T, DebugLog_t>)
    {
        std::ostringstream oss;            
        oss << Color::FG_LIGHT_BLUE << "[" << myThreadName << "] " 
            << Color::FG_LIGHT_CYAN << "{" << TypeName<T>() << "}: " 
            << Color::FG_DEFAULT << "\"" << logMessage << "\"";
        
        ((oss << ' ' << args), ...);
            
        // Ensure that even the newlines are properly output without
        // being incorrectly interspersed.
        std::string logString = oss.str() + "\n";
        std::cout << logString;
    }
    else if constexpr (std::is_same_v<T, TraceLog_t>)
    {
        std::ostringstream oss;            
        oss << Color::FG_LIGHT_BLUE << "[" << myThreadName << "] " 
            << Color::FG_MAGENTA << "{" << TypeName<T>() << "}: " 
            << Color::FG_DEFAULT << "\"" << logMessage << "\"";
        
        ((oss << ' ' << args), ...);
            
        // Ensure that even the newlines are properly output without
        // being incorrectly interspersed.
        std::string logString = oss.str() + "\n";
        std::cout << logString;
    }
    else if constexpr (std::is_same_v<T, InfoLog_t>)
    {
        std::ostringstream oss;            
        oss << Color::FG_LIGHT_BLUE << "[" << myThreadName << "] " 
            << Color::FG_GREEN << "{" << TypeName<T>() << "}: " 
            << Color::FG_DEFAULT << "\"" << logMessage << "\"";
        
        ((oss << ' ' << args), ...);
            
        // Ensure that even the newlines are properly output without
        // being incorrectly interspersed.
        std::string logString = oss.str() + "\n";
        std::cout << logString;
    }
    else if constexpr (std::is_same_v<T, ErrorLog_t>)
    {
        std::ostringstream oss;            
        oss << Color::FG_LIGHT_BLUE << "[" << myThreadName << "] " 
            << Color::FG_LIGHT_RED << "{" << TypeName<T>() << "}: " 
            << Color::FG_DEFAULT << "\"" << logMessage << "\"";
        
        ((oss << ' ' << args), ...);
            
        // Ensure that even the newlines are properly output without
        // being incorrectly interspersed.
        std::string logString = oss.str() + "\n";
        std::cerr << logString;
    }
    else if constexpr (std::is_same_v<T, WarnLog_t>)
    {
        std::ostringstream oss;            
        oss << Color::FG_LIGHT_BLUE << "[" << myThreadName << "] " 
            << Color::FG_YELLOW << Color::FT_BOLD << "{" << TypeName<T>() << "}: " 
            << Color::FG_DEFAULT << "\"" << logMessage << "\"";
        
        ((oss << ' ' << args), ...);
            
        // Ensure that even the newlines are properly output without
        // being incorrectly interspersed.
        std::string logString = oss.str() + "\n";
        std::cerr << logString;
    }
    else if constexpr (std::is_same_v<T, CriticalLog_t>)
    {
        std::ostringstream oss;            
        oss << Color::FG_LIGHT_BLUE << "[" << myThreadName << "] " 
            << Color::FG_RED << Color::FT_BOLD << "{" << TypeName<T>() << "}: " 
            << Color::FG_DEFAULT << "\"" << logMessage << "\"";
        
        ((oss << ' ' << args), ...);
            
        // Ensure that even the newlines are properly output without
        // being incorrectly interspersed.
        std::string logString = oss.str() + "\n";
        std::cerr << logString;
    }
}

Hope all these informations help. Enjoy.
Nuertey

Here is the link to my several implementations of thread name sets and gets:

https://github.com/nuertey/RandomArtifacts/blob/master/thread_name_answer.cpp

[nuertey]

And @swimmingmachine,
These additional defines might be helpful too in navigating my code excerpt:

inline constexpr size_t THREAD_NAME_LENGTH      = 16;  // Length is restricted by the OS. Includes null-termination.
inline constexpr size_t RECOMMENDED_BUFFER_SIZE = 20;  // For retrievals; must be at least 16; OS will null-terminate.

Regards
Nuertey

[swimmingmachine]

Thank you both! I will give it a try.