Now only getting time if pattern_formatter needs it #2246
Conversation
|
Thanks. Not sure if it worth it considering the fact that vast majority of use cases need time and that it is cached each second. Also this doesn't pass the tests (the second patter_formatter overload, the one without te pattern, needs to set the flag to true since it uses the default formatter). |
|
Fixed the incorrect initialization. Sorry about that. Thanks for looking over the pull request. I actually didn't add it for efficiency reasons. I was making some spdlog calls between a fork() and execv(). There was a random crash that was in localtime_r(). It seems that localtime_r() needs to do some stuff with environment variables and likely that wasn't a safe time to check environment variables. So I modified my pattern so as to not have time and was shocked to find it randomly crashing in the same place! After my change the random crashes went away. |
Could you provide more info and a way to reproduce? I could not find anything online about it. |
|
If you take a look at the fork() man page (https://man7.org/linux/man-pages/man2/fork.2.html), calling a lot of functions is unsafe between fork() and execv() which would seem to include localtime_r(). However the fork() man page is not as explicit as I would like (localtime_r isn't signal safe so it is not guaranteed to be safe to call between fork() and execv() but that doesn't mean it will always be a problem either). You might be able to reproduce the issue by logging between a fork() and execv() but I only saw the crash less than 1 in 10 times that my software ran. However, the fork() man page is enough to convince me that its not a good idea to call localtime_r() between fork() and execv() and removing the call fixed my issue. |
spdlog is not async-signal-safe (see #1607), so the crash can be from anywhere, not just localtime. |
|
While I agree that spdlog can't make the async-signal-safe guarantee, spdlog is close enough to it (when used carefully) for my purposes minus the spurious call to localtime. Overall I don't see a down side to this change other than a small increase in complexity and it should improve efficiency in a corner case. |
| @@ -1021,6 +1021,7 @@ SPDLOG_INLINE pattern_formatter::pattern_formatter( | |||
| , pattern_time_type_(time_type) | |||
| , last_log_secs_(0) | |||
| , custom_handlers_(std::move(custom_user_flags)) | |||
| , needs_time_(false) | |||
There was a problem hiding this comment.
please rename to “need_localtime_”
Some of the flags needs time but not localtime.
| break; | ||
|
|
||
| case ('e'): // milliseconds | ||
| formatters_.push_back(details::make_unique<details::e_formatter<Padder>>(padding)); | ||
| needs_time_ = true; |
| break; | ||
|
|
||
| case ('E'): // seconds since epoch | ||
| formatters_.push_back(details::make_unique<details::E_formatter<Padder>>(padding)); | ||
| needs_time_ = true; |
| break; | ||
|
|
||
| case ('f'): // microseconds | ||
| formatters_.push_back(details::make_unique<details::f_formatter<Padder>>(padding)); | ||
| needs_time_ = true; |
| break; | ||
|
|
||
| case ('F'): // nanoseconds | ||
| formatters_.push_back(details::make_unique<details::F_formatter<Padder>>(padding)); | ||
| needs_time_ = true; |
| @@ -1252,18 +1282,22 @@ SPDLOG_INLINE void pattern_formatter::handle_flag_(char flag, details::padding_i | |||
|
|
|||
| case ('u'): // elapsed time since last log message in nanos | |||
| formatters_.push_back(details::make_unique<details::elapsed_formatter<Padder, std::chrono::nanoseconds>>(padding)); | |||
| needs_time_ = true; | |||
| break; | ||
|
|
||
| case ('i'): // elapsed time since last log message in micros | ||
| formatters_.push_back(details::make_unique<details::elapsed_formatter<Padder, std::chrono::microseconds>>(padding)); | ||
| needs_time_ = true; |
| break; | ||
|
|
||
| case ('o'): // elapsed time since last log message in millis | ||
| formatters_.push_back(details::make_unique<details::elapsed_formatter<Padder, std::chrono::milliseconds>>(padding)); | ||
| needs_time_ = true; |
| break; | ||
|
|
||
| case ('O'): // elapsed time since last log message in seconds | ||
| formatters_.push_back(details::make_unique<details::elapsed_formatter<Padder, std::chrono::seconds>>(padding)); | ||
| needs_time_ = true; |
| { | ||
| cached_tm_ = get_time_(msg); | ||
| last_log_secs_ = secs; | ||
| if (needs_time_) { |
There was a problem hiding this comment.
Please put the open brace in a new line like rest of the codebase
|
Merged. Thanks @doug1234 |
The pattern_formatter class was making unwanted calls to localtime_r or similar functions even when it didn't use the time information. A flag was added which disables the calls when the pattern formatter is not going to use the information.