diff --git a/docs/doxygen/overviews/log.h b/docs/doxygen/overviews/log.h index 4042ec2955..f0d979b73e 100644 --- a/docs/doxygen/overviews/log.h +++ b/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. + */ diff --git a/include/wx/log.h b/include/wx/log.h index 73a8e60559..e3626ad634 100644 --- a/include/wx/log.h +++ b/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 // ---------------- diff --git a/interface/wx/log.h b/interface/wx/log.h index 49a9f10d76..428f9fb660 100644 --- a/interface/wx/log.h +++ b/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(); diff --git a/samples/thread/thread.cpp b/samples/thread/thread.cpp index c6e7d0d2de..74afcec5a6 100644 --- a/samples/thread/thread.cpp +++ b/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"), - 50, 50, 450, 340); - SetTopWindow(frame); - - // Show the frame - frame->Show(true); + new MyFrame("wxWidgets threads sample"); return true; } @@ -356,10 +346,11 @@ BEGIN_EVENT_TABLE(MyFrame, wxFrame) END_EVENT_TABLE() // My frame constructor -MyFrame::MyFrame(wxFrame *frame, const wxString& title, - int x, int y, int w, int h) - : wxFrame(frame, wxID_ANY, title, wxPoint(x, y), wxSize(w, h)) +MyFrame::MyFrame(const wxString& title) + : wxFrame(NULL, wxID_ANY, title) { + 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; - - text.Printf(wxT("Thread %p started (priority = %u).\n"), - GetId(), GetPriority()); - WriteText(text); - // wxLogMessage(text); -- test wxLog thread safeness + wxLogMessage("Thread started (priority = %u).", GetPriority()); 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()); - WriteText(text); + wxLogMessage("Thread progress: %u", m_count); // wxSleep() can't be called from non-GUI thread! wxThread::Sleep(1000); } - text.Printf(wxT("Thread %p finished.\n"), GetId()); - WriteText(text); - // wxLogMessage(text); -- test wxLog thread safeness + wxLogMessage("Thread finished."); return NULL; } diff --git a/src/common/log.cpp b/src/common/log.cpp index 1b599cc8f8..05f4cd676c 100644 --- a/src/common/log.cpp +++ b/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 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; diff --git a/src/generic/logg.cpp b/src/generic/logg.cpp index ae690ab5ff..88a17cd700 100644 --- a/src/generic/logg.cpp +++ b/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 - // also called from the main thread to ensure that the messages logged from - // it appear in correct order with the messages from the other threads) - void AddLogMessage(const wxString& message); - - // actually append the messages logged from secondary threads to the text - // control during idle time in the main thread - virtual void OnInternalIdle(); + // do show the message in the text control + void ShowLogMessage(const wxString& message) + { + m_pTextCtrl->AppendText(message + wxS('\n')); + } 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