Feature/thread safe logging #139

mcakircali · 2024-09-10T13:40:00Z

No description provided.

optional to use enables safely handling lifetime of log channel objects

refactored Channel as interface (abstract class) OutputChannel works as usual EmptyChannel has no buffer and is no-op fixes segfaults in multi-threaded bonus: improves performance

don't call virtual methods in dtor

handle any log calls from dtors of static objects

codecov-commenter · 2024-09-10T13:46:46Z

Codecov Report

Attention: Patch coverage is 72.72727% with 30 lines in your changes missing coverage. Please review.

Project coverage is 63.70%. Comparing base (a8f0983) to head (19507a3).

Files with missing lines	Patch %	Lines
src/eckit/log/Log.cc	48.57%	18 Missing ⚠️
src/eckit/log/ChannelBuffer.cc	61.90%	8 Missing ⚠️
src/eckit/system/Library.cc	50.00%	3 Missing ⚠️
src/eckit/log/Channel.h	50.00%	1 Missing ⚠️

Additional details and impacted files

@@             Coverage Diff             @@
##           develop     #139      +/-   ##
===========================================
+ Coverage    63.69%   63.70%   +0.01%     
===========================================
  Files         1065     1066       +1     
  Lines        55140    55188      +48     
  Branches      4085     4100      +15     
===========================================
+ Hits         35122    35159      +37     
- Misses       20018    20029      +11

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

geier1993 · 2024-09-10T14:09:30Z

src/eckit/log/Log.cc

-    virtual Channel* createChannel() { return new Channel(Main::instance().createWarningLogTarget()); }
-};
+    if (Main::finalised()) {
+        thread_local Channel postMainError(new PrefixTarget("POST-MAIN-ERROR", new OStreamTarget(std::cout)));


Put in a comment:

This may still cause a segfault due to detruction order in library shutdown -
We may have to return an emptychannel that won't cause any harm when it has been destructed officially

I am hesitant about this comment (not clear to me) because it can be very misleading if we haven't seen a case before

which type of library, runtime or system ?

for example, calling Log::info/debug/error in a system::~Library will fail but nothing to do with what Main::finalised does.

github-actions · 2024-09-11T09:23:03Z

Private downstream CI failed.
Workflow name: private-downstream-ci-hpc
View the logs at https://github.com/ecmwf-actions/private-downstream-ci/actions/runs/10808625792.

github-actions · 2024-09-11T09:35:09Z

Private downstream CI succeeded.
Workflow name: private-downstream-ci
View the logs at https://github.com/ecmwf-actions/private-downstream-ci/actions/runs/10808794710.

and include fixes

github-actions · 2024-09-11T20:59:40Z

Private downstream CI failed.
Workflow name: private-downstream-ci-hpc
View the logs at https://github.com/ecmwf-actions/private-downstream-ci/actions/runs/10819467342.

github-actions · 2024-09-11T21:02:18Z

Private downstream CI succeeded.
Workflow name: private-downstream-ci
View the logs at https://github.com/ecmwf-actions/private-downstream-ci/actions/runs/10819456484.

github-actions · 2024-09-11T21:02:19Z

Private downstream CI succeeded.
Workflow name: private-downstream-ci
View the logs at https://github.com/ecmwf-actions/private-downstream-ci/actions/runs/10819456484.

Ozaq

@mcakircali I am not sure if all my comments are relevant to you but I had to guess a bit what the intent of this PR is, i.e. what is the underlying bug to solve.

Ozaq · 2024-10-15T11:34:22Z

src/eckit/log/Log.h

@@ -29,8 +30,7 @@ typedef void (*channel_callback_t)(void* data, const char* msg);
 /// Singleton holding global streams for logging
 ///

-class Log {
-
+class Log: private NonCopyable {


You updated the Log struct to be non-copyable and non-instanciable. I.e. the struct Log is essentially a namespace, why not make it a namespace in the first place? Right now there are only function templates used which also removes this reason to use a struct. This change should also be transparent to the user as the sythax for invocation will be unchanged.

Struct Log is essentially a namespace. If you look at the history of this code, it predates namespaces in C++...

I'm not sure if there would be knock-on impacts of changing it to be a namespace. There is a lot of code which makes use of the log functionality. And (in any case) it would leave us out of our general conventions, in that we would have to have a namespace called "Log" rather than "log" or we would really break a lot of stuff.

This PR already does far too much changing things (mostly for the better) at the same time as trying to fix an underlying issue. Makes it much harder to see if/where it actually fixes the issue. I'm generally inclined towards separating 'cleanup' PRs and and functional PRs for the ease of correctness reviewing. So if we want to play with this, it should be in a separate PR.

Ozaq · 2024-10-15T12:45:38Z

src/eckit/log/Channel.h

+public:  // methods
+    EmptyChannel();
+
+    ~EmptyChannel() = default;


this needs to be made virtual with virtual or override

Ozaq · 2024-10-15T13:05:59Z

src/eckit/log/Channel.h

    ~AutoIndent() { channel_.unindent(); }
 };

 //----------------------------------------------------------------------------------------------------------------------

+class EmptyChannel: public Channel {


Two remarks:

1.) This should be named VoidChannel or NullChannel (as in > /dev/null), because it is more interesting that the messages disappear into the void than it is important that the channel is empty.

2.) Is this type actually needed? A VoidChannel could equally be constructed by a factory function, e.g. createVoidChannel.

Ozaq · 2024-10-15T13:07:52Z

src/eckit/log/Channel.h

-
-    ChannelBuffer* buffer_;
+private:  // members
+    ChannelBuffer* buffer_ {nullptr};


I think this should be a std::unique_ptr<ChannelBuffer>

This is currently explicitly deleted in the constructor. Please change to unique_ptr. Is a good change.

Ozaq · 2024-10-15T13:16:29Z

src/eckit/log/Channel.h

@@ -39,7 +39,7 @@ class Channel : public std::ostream, private NonCopyable {
    bool operator!() const;
    operator bool() const;

-    void indent(const char* prefix = "");
+    void indent(const char* space = "");


From a first glance I disagree with the renaming because It looks like I can use an arbitrary character sequence here while I interpret indentation either as <space> vs <tab> or a numerical value e.g. 5 spaces.

I also disagree with this renaming. Although, that said, it is plausible to use non-space indents (e.g. ">>>" or "...")

Ozaq · 2024-10-15T14:29:15Z

src/eckit/log/Log.cc


 Channel& Log::info() {
    if (!Main::ready()) {
-        static Channel empty(new PrefixTarget("PRE-MAIN-INFO", new OStreamTarget(std::cout)));
-        return empty;
+        thread_local Channel preMainInfo(new PrefixTarget("PRE-MAIN-INFO", new OStreamTarget(std::cout)));


Are there really pre-main threads running? I.e. does this need to be thread_local?

I don't think that there are ever pre-main threads running. Good point.

Ozaq · 2024-10-15T14:47:44Z

src/eckit/log/Log.cc

+    if (Main::finalised()) {
+        // This may still cause a SEGFAULT due to missing destruction order at the end of library life time 
+        // - only solution is then to use an empty channel which is harmless in a destructed state
+        thread_local Channel postMainError(new PrefixTarget("POST-MAIN-ERROR", new OStreamTarget(std::cout)));


Static objects are destructed in reverse order of construction. Function statics are constructed on first use, i.e. the Channel object will be destroyed before all objects that write log messages are destructed.

Ideally we do not rely on static initialization order at all and explicitly call all initialization code in main, then it is straight forward to start logging as one of the first systems.

For the shutdown scenario we could opt to leak memory and simply heap allocate all Channels and never destruct them.

Ozaq · 2024-10-15T14:52:09Z

tests/log/test_log_threads_hammer.cc

+
+//----------------------------------------------------------------------------------------------------------------------
+
+CASE("Log: output " + std::to_string(logSize) + " logs by " + std::to_string(numThreads) + " threads") {


I think this needs to be extended with any additional log targets as they use multiple write calls if I understand the code correctly to produce a single log message

Ozaq · 2024-10-15T14:54:38Z

tests/log/CMakeLists.txt

+ecbuild_add_test( TARGET      eckit_test_log_threads_hammer
+                  SOURCES     test_log_threads_hammer.cc
+                  ENVIRONMENT _TEST_ECKIT_HOME=/tmp/$ENV{USER}
+                  LIBS        eckit )
+


I am a bit torn about adding this to the default test set because this test may pass (or most likely will) even if there is a bug as it is about trying to trigger a race condition. I don't know what the current testing strategy is for test that do not reliably produce a clear good/bad distinction

Ozaq · 2024-10-15T15:01:07Z

src/eckit/runtime/Main.cc

 static StaticMutex local_mutex;
 static Main* instance_ = nullptr;

 //----------------------------------------------------------------------------------------------------------------------

 Main::Main(int argc, char** argv, const char* homeenv) :
    taskID_(-1), argc_(argc), argv_(argv), home_("/"), debug_(false) {
+
+    std::atexit(finalise);


Be aware that this may still interleave with static object destruction, see https://en.cppreference.com/w/cpp/utility/program/exit

mcakircali added 27 commits June 20, 2024 17:31

feat(Main): added finalise and finalised

c7f0675

optional to use enables safely handling lifetime of log channel objects

feat(Channel): introduce EmptyChannel

0407bb1

refactored Channel as interface (abstract class) OutputChannel works as usual EmptyChannel has no buffer and is no-op fixes segfaults in multi-threaded bonus: improves performance

fix(ChannelBuffer): rename OutputChannel

d9c9862

fix(ChannelBuffer): sync() in Channel not in dtor here

d4825ae

don't call virtual methods in dtor

fix(Log): set missing private ctor/dtor = default

2d73e73

fix(Log): thread and lifetime safe Channels

82a17f5

fix(Library): renamed Channel => OutputChannel

60c5399

fix(Library): log channels are thread (and lifetime) safe

225e43a

handle any log calls from dtors of static objects

fix(Test): finalise the Main object

88e5eed

fix(Test): renamed Channel to OutputChannel

0faf773

feat(Test): added multi-threaded log testing

4e59bf0

fix(Library): revert unintended changes

ae98034

fix(Channel): revert inheritance and restore interface

346a23c

feat(ChannelBuffer): added VoidBuffer for EmptyChannel

0519c53

refactor(Channel): rename OutputChannel to Channel

5dd813f

fix(Main): set finished to false on initialise

3459dde

chore(Test): relocated global tester object

1e89c86

fix(Channel): rather override, and add missing stream operator overload

7c3c1bc

fix(Log): make sure no copy nor default ctor

6ddfc94

fix(Main): typo UK

c948b30

refactor(VoidBuffer): moved detail to source

bfdce18

fix(Log): includes

8444660

fix(Library): debug channel as member, empty channel as thread_local

25fac98

fix(Log): cleanup

2bf8c5e

fix(Main): finalise Main (any child) via std::atexit

0d49f7a

test(Log): cleanup

3f8b957

test(Log): add worse case

0ba7337

mcakircali requested review from geier1993 and simondsmart September 10, 2024 13:40

geier1993 reviewed Sep 10, 2024

View reviewed changes

mcakircali and others added 3 commits September 10, 2024 16:26

test(Log): comment out the worse case

1968f5d

Merge branch 'develop' into feature/thread-safe-logging

86ec904

Add comments to note about possible problems

8caa48e

refactor(logging): emptyChannel name

19507a3

and include fixes

Ozaq reviewed Oct 15, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Feature/thread safe logging #139

Feature/thread safe logging #139

mcakircali commented Sep 10, 2024

codecov-commenter commented Sep 10, 2024 •

edited

Loading

geier1993 Sep 10, 2024

mcakircali Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

Ozaq left a comment

Ozaq Oct 15, 2024

simondsmart Oct 17, 2024

Ozaq Oct 15, 2024

Ozaq Oct 15, 2024

Ozaq Oct 15, 2024

simondsmart Oct 17, 2024

Ozaq Oct 15, 2024

simondsmart Oct 17, 2024

Ozaq Oct 15, 2024

simondsmart Oct 17, 2024

Ozaq Oct 15, 2024

Ozaq Oct 15, 2024

Ozaq Oct 15, 2024

Ozaq Oct 15, 2024


		//----------------------------------------------------------------------------------------------------------------------

		CASE("Log: output " + std::to_string(logSize) + " logs by " + std::to_string(numThreads) + " threads") {

Feature/thread safe logging #139

Are you sure you want to change the base?

Feature/thread safe logging #139

Conversation

mcakircali commented Sep 10, 2024

codecov-commenter commented Sep 10, 2024 • edited Loading

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

github-actions bot commented Sep 11, 2024

Ozaq left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov-commenter commented Sep 10, 2024 •

edited

Loading