Made wxLogXXX() functions thread-safe.

They can now be called from any thread and will buffer the messages until the
current log target is flushed from the main thread. This makes earlier code to
do the same thing specifically for wxLogWindow unnecessary and also allows to
use wxLogMessage() in the thread sample instead of using manual logging there.


git-svn-id: https://svn.wxwidgets.org/svn/wx/wxWidgets/trunk@61416 c3d73ce0-8a6f-49c7-b76d-6d57e0e08775

docs/doxygen/overviews/log.h

@@ -258,5 +258,20 @@ automatically switches to using wxLogStderr if it isn't.
 The dialog sample illustrates this approach by defining a custom log target
 customizing the dialog used by wxLogGui for the single messages.
 
+
+@section overview_log_mt Logging in Multi-Threaded Applications
+
+Starting with wxWidgets 2.9.1, logging functions can be safely called from any
+thread. Messages logged from threads other than the main one will be buffered
+until wxLog::Flush() is called in the main thread (which usually happens during
+idle time, i.e. after processing all pending events) and will be really output
+only then. Notice that the default GUI logger already only output the messages
+when it is flushed, so by default messages from the other threads will be shown
+more or less at the same moment as usual. However if you define a custom log
+target, messages may be logged out of order, e.g. messages from the main thread
+with later timestamp may appear before messages with earlier timestamp logged
+from other threads. wxLog does however guarantee that messages logged by each
+thread will appear in order in which they were logged.
+
 */
 

include/wx/log.h

@@ -289,6 +289,26 @@ private:
 
 #define wxLOG_KEY_TRACE_MASK "wx.trace_mask"
 
+// ----------------------------------------------------------------------------
+// log record: a unit of log output
+// ----------------------------------------------------------------------------
+
+struct wxLogRecord
+{
+    wxLogRecord(wxLogLevel level_,
+                const wxString& msg_,
+                const wxLogRecordInfo& info_)
+        : level(level_),
+          msg(msg_),
+          info(info_)
+    {
+    }
+
+    wxLogLevel level;
+    wxString msg;
+    wxLogRecordInfo info;
+};
+
 // ----------------------------------------------------------------------------
 // derive from this class to redirect (or suppress, or ...) log messages
 // normally, only a single instance of this class exists but it's not enforced
@@ -564,6 +584,13 @@ private:
     // caller had already locked GetPreviousLogCS()
     unsigned LogLastRepeatIfNeededUnlocked();
 
+    // called from OnLog() if it's called from the main thread and from Flush()
+    // when it plays back the buffered messages logged from the other threads
+    void OnLogInMainThread(wxLogLevel level,
+                           const wxString& msg,
+                           const wxLogRecordInfo& info);
+
+
     // static variables
     // ----------------
 

interface/wx/log.h

@@ -756,14 +756,22 @@ public:
 
     /**
         Shows all the messages currently in buffer and clears it.
+
         If the buffer is already empty, nothing happens.
+
+        It should only be called from the main application thread.
+
+        If you override this method in a derived class, call the base class
+        version first, before doing anything else, to ensure that any buffered
+        messages from the other threads are logged.
     */
     virtual void Flush();
 
     /**
         Flushes the current log target if any, does nothing if there is none.
 
-        @see Flush()
+        As Flush() itself, this method should only be called from the main
+        application thread.
     */
     static void FlushActive();
 

samples/thread/thread.cpp

@@ -89,28 +89,22 @@ public:
 // the main application frame
 // ----------------------------------------------------------------------------
 
-class MyFrame: public wxFrame
+class MyFrame : public wxFrame,
+                private wxLog
 {
 public:
     // ctor
-    MyFrame(wxFrame *frame, const wxString& title, int x, int y, int w, int h);
+    MyFrame(const wxString& title);
     virtual ~MyFrame();
 
-    // this function is MT-safe, i.e. it can be called from worker threads
-    // safely without any additional locking
-    void LogThreadMessage(const wxString& text)
-    {
-        wxCriticalSectionLocker lock(m_csMessages);
-        m_messages.push_back(text);
-
-        // as we effectively log the messages from the idle event handler,
-        // ensure it's going to be called now that we have some messages to log
-        wxWakeUpIdle();
-    }
-
     // accessors for MyWorkerThread (called in its context!)
     bool Cancelled();
 
+protected:
+    virtual void DoLogRecord(wxLogLevel level,
+                             const wxString& msg,
+                             const wxLogRecordInfo& info);
+
 private:
     // event handlers
     // --------------
@@ -136,6 +130,13 @@ private:
     void OnUpdateWorker(wxUpdateUIEvent& event);
 
 
+    // logging helper
+    void DoLogLine(wxTextCtrl *text,
+                   const wxString& timestr,
+                   const wxString& threadstr,
+                   const wxString& msg);
+
+
     // thread helper functions
     // -----------------------
 
@@ -145,9 +146,6 @@ private:
     // update display in our status bar: called during idle handling
     void UpdateThreadStatus();
 
-    // log the messages queued by LogThreadMessage()
-    void DoLogThreadMessages();
-
 
     // internal variables
     // ------------------
@@ -155,6 +153,10 @@ private:
     // just some place to put our messages in
     wxTextCtrl *m_txtctrl;
 
+    // old log target, we replace it with one using m_txtctrl during this
+    // frame life time
+    wxLog *m_oldLogger;
+
     // the array of pending messages to be displayed and the critical section
     // protecting it
     wxArrayString m_messages;
@@ -208,21 +210,14 @@ enum
 class MyThread : public wxThread
 {
 public:
-    MyThread(MyFrame *frame);
+    MyThread();
     virtual ~MyThread();
 
     // thread execution starts here
     virtual void *Entry();
 
-    // write something to the text control in the main frame
-    void WriteText(const wxString& text)
-    {
-        m_frame->LogThreadMessage(text);
-    }
-
 public:
     unsigned m_count;
-    MyFrame *m_frame;
 };
 
 // ----------------------------------------------------------------------------
@@ -320,12 +315,7 @@ bool MyApp::OnInit()
     wxLog::AddTraceMask("thread");
 
     // Create the main frame window
-    MyFrame *frame = new MyFrame((wxFrame *)NULL, _T("wxWidgets threads sample"),
+    new MyFrame("wxWidgets threads sample");
-                                 50, 50, 450, 340);
-    SetTopWindow(frame);
-
-    // Show the frame
-    frame->Show(true);
 
     return true;
 }
@@ -356,10 +346,11 @@ BEGIN_EVENT_TABLE(MyFrame, wxFrame)
 END_EVENT_TABLE()
 
 // My frame constructor
-MyFrame::MyFrame(wxFrame *frame, const wxString& title,
+MyFrame::MyFrame(const wxString& title)
-                 int x, int y, int w, int h)
+       : wxFrame(NULL, wxID_ANY, title)
-       : wxFrame(frame, wxID_ANY, title, wxPoint(x, y), wxSize(w, h))
 {
+    m_oldLogger = wxLog::GetActiveTarget();
+
     SetIcon(wxIcon(sample_xpm));
 
     // Make a menubar
@@ -394,18 +385,45 @@ MyFrame::MyFrame(wxFrame *frame, const wxString& title,
 
     m_nRunning = m_nCount = 0;
 
-    m_dlgProgress = (wxProgressDialog *)NULL;
+    m_dlgProgress = NULL;
 
 #if wxUSE_STATUSBAR
     CreateStatusBar(2);
 #endif // wxUSE_STATUSBAR
 
-    m_txtctrl = new wxTextCtrl(this, wxID_ANY, _T(""), wxPoint(0, 0), wxSize(0, 0),
+    // create the logging text control and a header showing the meaning of the
+    // different columns
+    wxTextCtrl *header = new wxTextCtrl(this, wxID_ANY, "",
+                                        wxDefaultPosition, wxDefaultSize,
+                                        wxTE_READONLY);
+    DoLogLine(header, "  Time", " Thread", "Message");
+    m_txtctrl = new wxTextCtrl(this, wxID_ANY, "",
+                               wxDefaultPosition, wxDefaultSize,
                                wxTE_MULTILINE | wxTE_READONLY);
+    wxLog::SetActiveTarget(this);
+
+    // use fixed width font to align output in nice columns
+    wxFont font(wxNORMAL_FONT->GetPointSize(), wxFONTFAMILY_TELETYPE,
+                wxFONTSTYLE_NORMAL, wxFONTWEIGHT_NORMAL);
+    header->SetFont(font);
+    m_txtctrl->SetFont(font);
+
+    m_txtctrl->SetFocus();
+
+    // layout and show the frame
+    wxBoxSizer *sizer = new wxBoxSizer(wxVERTICAL);
+    sizer->Add(header, wxSizerFlags().Expand());
+    sizer->Add(m_txtctrl, wxSizerFlags(1).Expand());
+    SetSizer(sizer);
+
+    SetSize(600, 350);
+    Show();
 }
 
 MyFrame::~MyFrame()
 {
+    wxLog::SetActiveTarget(m_oldLogger);
+
     // NB: although the OS will terminate all the threads anyhow when the main
     //     one exits, it's good practice to do it ourselves -- even if it's not
     //     completely trivial in this example
@@ -432,9 +450,43 @@ MyFrame::~MyFrame()
     wxGetApp().m_semAllDone.Wait();
 }
 
+void
+MyFrame::DoLogLine(wxTextCtrl *text,
+                   const wxString& timestr,
+                   const wxString& threadstr,
+                   const wxString& msg)
+{
+    text->AppendText(wxString::Format("%9s %10s %s", timestr, threadstr, msg));
+}
+
+void
+MyFrame::DoLogRecord(wxLogLevel level,
+                     const wxString& msg,
+                     const wxLogRecordInfo& info)
+{
+    // let the default GUI logger treat warnings and errors as they should be
+    // more noticeable than just another line in the log window and also trace
+    // messages as there may be too many of them
+    if ( level <= wxLOG_Warning || level == wxLOG_Trace )
+    {
+        m_oldLogger->LogRecord(level, msg, info);
+        return;
+    }
+
+    DoLogLine
+    (
+        m_txtctrl,
+        wxDateTime(info.timestamp).FormatISOTime(),
+        info.threadId == wxThread::GetMainId()
+            ? wxString("main")
+            : wxString::Format("%x", info.threadId),
+        msg + "\n"
+    );
+}
+
 MyThread *MyFrame::CreateThread()
 {
-    MyThread *thread = new MyThread(this);
+    MyThread *thread = new MyThread;
 
     if ( thread->Create() != wxTHREAD_NO_ERROR )
     {
@@ -447,19 +499,6 @@ MyThread *MyFrame::CreateThread()
     return thread;
 }
 
-void MyFrame::DoLogThreadMessages()
-{
-    wxCriticalSectionLocker lock(m_csMessages);
-
-    const size_t count = m_messages.size();
-    for ( size_t n = 0; n < count; n++ )
-    {
-        m_txtctrl->AppendText(m_messages[n]);
-    }
-
-    m_messages.clear();
-}
-
 void MyFrame::UpdateThreadStatus()
 {
     wxCriticalSectionLocker enter(wxGetApp().m_critsect);
@@ -623,8 +662,6 @@ void MyFrame::OnPauseThread(wxCommandEvent& WXUNUSED(event) )
 
 void MyFrame::OnIdle(wxIdleEvent& event)
 {
-    DoLogThreadMessages();
-
     UpdateThreadStatus();
 
     event.Skip();
@@ -844,11 +881,10 @@ void MyImageDialog::OnPaint(wxPaintEvent& WXUNUSED(evt))
 // MyThread
 // ----------------------------------------------------------------------------
 
-MyThread::MyThread(MyFrame *frame)
+MyThread::MyThread()
         : wxThread()
 {
     m_count = 0;
-    m_frame = frame;
 }
 
 MyThread::~MyThread()
@@ -873,12 +909,7 @@ MyThread::~MyThread()
 
 wxThread::ExitCode MyThread::Entry()
 {
-    wxString text;
+    wxLogMessage("Thread started (priority = %u).", GetPriority());
-
-    text.Printf(wxT("Thread %p started (priority = %u).\n"),
-                GetId(), GetPriority());
-    WriteText(text);
-    // wxLogMessage(text); -- test wxLog thread safeness
 
     for ( m_count = 0; m_count < 10; m_count++ )
     {
@@ -894,16 +925,13 @@ wxThread::ExitCode MyThread::Entry()
         if ( TestDestroy() )
             break;
 
-        text.Printf(wxT("[%u] Thread %p here.\n"), m_count, GetId());
+        wxLogMessage("Thread progress: %u", m_count);
-        WriteText(text);
 
         // wxSleep() can't be called from non-GUI thread!
         wxThread::Sleep(1000);
     }
 
-    text.Printf(wxT("Thread %p finished.\n"), GetId());
+    wxLogMessage("Thread finished.");
-    WriteText(text);
-    // wxLogMessage(text); -- test wxLog thread safeness
 
     return NULL;
 }

src/common/log.cpp

@@ -43,6 +43,7 @@
 #include "wx/textfile.h"
 #include "wx/thread.h"
 #include "wx/crt.h"
+#include "wx/vector.h"
 
 // other standard headers
 #ifndef __WXWINCE__
@@ -68,33 +69,53 @@ const char *wxLOG_COMPONENT = "";
 
 #if wxUSE_THREADS
 
+namespace
+{
+
+// contains messages logged by the other threads and waiting to be shown until
+// Flush() is called in the main one
+typedef wxVector<wxLogRecord> wxLogRecords;
+wxLogRecords gs_bufferedLogRecords;
+
+
 // define static functions providing access to the critical sections we use
 // instead of just using static critical section variables as log functions may
 // be used during static initialization and while this is certainly not
 // advisable it's still better to not crash (as we'd do if we used a yet
 // uninitialized critical section) if it happens
 
-static inline wxCriticalSection& GetTraceMaskCS()
+// this critical section is used for buffering the messages from threads other
+// than main, i.e. it protects all accesses to gs_bufferedLogRecords above
+inline wxCriticalSection& GetBackgroundLogCS()
+{
+    static wxCriticalSection s_csBackground;
+
+    return s_csBackground;
+}
+
+inline wxCriticalSection& GetTraceMaskCS()
 {
     static wxCriticalSection s_csTrace;
 
     return s_csTrace;
 }
 
-static inline wxCriticalSection& GetPreviousLogCS()
+inline wxCriticalSection& GetPreviousLogCS()
 {
     static wxCriticalSection s_csPrev;
 
     return s_csPrev;
 }
 
-static inline wxCriticalSection& GetLevelsCS()
+inline wxCriticalSection& GetLevelsCS()
 {
     static wxCriticalSection s_csLevels;
 
     return s_csLevels;
 }
 
+} // anonymous namespace
+
 #endif // wxUSE_THREADS
 
 // ----------------------------------------------------------------------------
@@ -256,6 +277,28 @@ wxLog::OnLog(wxLogLevel level,
     if ( !pLogger )
         return;
 
+#if wxUSE_THREADS
+    if ( !wxThread::IsMain() )
+    {
+        wxCriticalSectionLocker lock(GetBackgroundLogCS());
+
+        gs_bufferedLogRecords.push_back(wxLogRecord(level, msg, info));
+
+        // ensure that our Flush() will be called soon
+        wxWakeUpIdle();
+
+        return;
+    }
+#endif // wxUSE_THREADS
+
+    pLogger->OnLogInMainThread(level, msg, info);
+}
+
+void
+wxLog::OnLogInMainThread(wxLogLevel level,
+                         const wxString& msg,
+                         const wxLogRecordInfo& info)
+{
     if ( GetRepetitionCounting() )
     {
         wxCRIT_SECT_LOCKER(lock, GetPreviousLogCS());
@@ -269,7 +312,7 @@ wxLog::OnLog(wxLogLevel level,
             return;
         }
 
-        pLogger->LogLastRepeatIfNeededUnlocked();
+        LogLastRepeatIfNeededUnlocked();
 
         // reset repetition counter for a new message
         gs_prevLog.msg = msg;
@@ -297,7 +340,7 @@ wxLog::OnLog(wxLogLevel level,
     }
 #endif // wxUSE_LOG_TRACE
 
-    pLogger->DoLogRecord(level, prefix + msg + suffix, info);
+    DoLogRecord(level, prefix + msg + suffix, info);
 }
 
 void wxLog::DoLogRecord(wxLogLevel level,
@@ -557,6 +600,32 @@ void wxLog::TimeStamp(wxString *str)
 
 void wxLog::Flush()
 {
+#if wxUSE_THREADS
+    wxASSERT_MSG( wxThread::IsMain(),
+                  "should be called from the main thread only" );
+
+    // check if we have queued messages from other threads
+    wxLogRecords bufferedLogRecords;
+
+    {
+        wxCriticalSectionLocker lock(GetBackgroundLogCS());
+        bufferedLogRecords.swap(gs_bufferedLogRecords);
+
+        // release the lock now to not keep it while we are logging the
+        // messages below, allowing background threads to run
+    }
+
+    if ( !bufferedLogRecords.empty() )
+    {
+        for ( wxLogRecords::const_iterator it = bufferedLogRecords.begin();
+              it != bufferedLogRecords.end();
+              ++it )
+        {
+            OnLogInMainThread(it->level, it->msg, it->info);
+        }
+    }
+#endif // wxUSE_THREADS
+
     LogLastRepeatIfNeeded();
 }
 
@@ -566,6 +635,8 @@ void wxLog::Flush()
 
 void wxLogBuffer::Flush()
 {
+    wxLog::Flush();
+
     if ( !m_str.empty() )
     {
         wxMessageOutputBest out;

src/generic/logg.cpp

@@ -53,10 +53,6 @@
 #include "wx/arrstr.h"
 #include "wx/msgout.h"
 
-#if wxUSE_THREADS
-    #include "wx/thread.h"
-#endif // wxUSE_THREADS
-
 #ifdef  __WXMSW__
     // for OutputDebugString()
     #include  "wx/msw/private.h"
@@ -298,6 +294,8 @@ wxLogGui::DoShowMultipleLogMessages(const wxArrayString& messages,
 
 void wxLogGui::Flush()
 {
+    wxLog::Flush();
+
     if ( !m_bHasMessages )
         return;
 
@@ -451,14 +449,11 @@ public:
 #endif // CAN_SAVE_FILES
     void OnClear(wxCommandEvent& event);
 
-    // this function is safe to call from any thread (notice that it should be
+    // do show the message in the text control
-    // also called from the main thread to ensure that the messages logged from
+    void ShowLogMessage(const wxString& message)
-    // it appear in correct order with the messages from the other threads)
+    {
-    void AddLogMessage(const wxString& message);
+        m_pTextCtrl->AppendText(message + wxS('\n'));
-
+    }
-    // actually append the messages logged from secondary threads to the text
-    // control during idle time in the main thread
-    virtual void OnInternalIdle();
 
 private:
     // use standard ids for our commands!
@@ -472,24 +467,9 @@ private:
     // common part of OnClose() and OnCloseWindow()
     void DoClose();
 
-    // do show the message in the text control
-    void DoShowLogMessage(const wxString& message)
-    {
-        m_pTextCtrl->AppendText(message + wxS('\n'));
-    }
-
     wxTextCtrl  *m_pTextCtrl;
     wxLogWindow *m_log;
 
-    // queue of messages logged from other threads which need to be displayed
-    wxArrayString m_pendingMessages;
-
-#if wxUSE_THREADS
-    // critical section to protect access to m_pendingMessages
-    wxCriticalSection m_critSection;
-#endif // wxUSE_THREADS
-
-
     DECLARE_EVENT_TABLE()
     wxDECLARE_NO_COPY_CLASS(wxLogFrame);
 };
@@ -602,43 +582,6 @@ void wxLogFrame::OnClear(wxCommandEvent& WXUNUSED(event))
     m_pTextCtrl->Clear();
 }
 
-void wxLogFrame::OnInternalIdle()
-{
-    {
-        wxCRIT_SECT_LOCKER(locker, m_critSection);
-
-        const size_t count = m_pendingMessages.size();
-        for ( size_t n = 0; n < count; n++ )
-        {
-            DoShowLogMessage(m_pendingMessages[n]);
-        }
-
-        m_pendingMessages.clear();
-    } // release m_critSection
-
-    wxFrame::OnInternalIdle();
-}
-
-void wxLogFrame::AddLogMessage(const wxString& message)
-{
-    wxCRIT_SECT_LOCKER(locker, m_critSection);
-
-#if wxUSE_THREADS
-    if ( !wxThread::IsMain() || !m_pendingMessages.empty() )
-    {
-        // message needs to be queued for later showing
-        m_pendingMessages.Add(message);
-
-        wxWakeUpIdle();
-    }
-    else // we are the main thread and no messages are queued, so we can
-         // log the message directly
-#endif // wxUSE_THREADS
-    {
-        DoShowLogMessage(message);
-    }
-}
-
 wxLogFrame::~wxLogFrame()
 {
     m_log->OnFrameDelete(this);
@@ -681,7 +624,7 @@ void wxLogWindow::DoLogTextAtLevel(wxLogLevel level, const wxString& msg)
     if ( level == wxLOG_Trace )
         return;
 
-    m_pLogFrame->AddLogMessage(msg);
+    m_pLogFrame->ShowLogMessage(msg);
 }
 
 wxFrame *wxLogWindow::GetFrame() const