Fix race conditions in Core/Timer

[tberghammer]

Summary

Fix race conditions in Core/Timer

The Timer class already had some support for multi-threaded access
but it still contained several race conditions. This CL fixes them
in preparation of adding multi-threaded dwarf parsing (and other
multi-threaded parts later).

[labath]

lgtm

[clayborg]

"thread_local" isn't well supported and has performance issues. See inlined comments.

include/lldb/Core/Timer.h

89 ↗

(On Diff #38005)

Not sure if all platforms support thread_local correctly. MacOSX might not. I also spoke with some compiler folks on using "thread_local" and they warned that the C++11 spec requires a bunch of other stuff gets initialized when _any_ thread_local variable gets used, so I was told that using the "thread" instead of much better to do. So switch this from thread_local to thread and it should work on most platforms. Not sure if windows will have a problem with this.

So the best fix is probably to make a LLDB_THREAD_LOCAL #define in lldb-defines.h and define it to "__thread" by default. Windows can fix up as needed.

source/Core/Timer.cpp

27 ↗

(On Diff #38005)

Use LLDB_THREAD_LOCAL instead of "thread_local".

[zturner]

include/lldb/Core/Timer.h

89 ↗

(On Diff #38005)

Actually can you use llvm::ThreadLocal instead?

__thread doesn't exist on Windows, and neither does thread_local. ThreadLocal<T> in llvm is the only thing I know that works everywhere.

Once I get the Python 3 stuff finished, we can move to MSVC 2015, which *does* support thread_local. Then we can use the LLDB_THREAD_LOCAL define as you suggest.

Does that work for everyone?

[clayborg]

Yes, please use any llvm system utilities when possible. And scratch the need for LLDB_THREAD_LOCAL at any point in the future and just use llvm::ThreadLocal all the time as thread local variables have already been abstracted by llvm.

[zturner]

Sad as it may seem, I actually think we may *need* this LLDB_THREAD_LOCAL at some point in the future. The reason is that there is at least one place in LLDB (I think it might even be in Timer, but it's been a while since I found this) that relies on thread local destructors. It is possible to make this work on Windows, but the code is absolutely crazy. You have to use pragmas to manually inject magic sections into the binary. Anyway, this actually works using the C++11 thread_local keyword under MSVC 2015, so the fact that we don't have those semantics on Windows is currently a bug, and the only way I know of to get them in a sane manner is to use thread_local.

Anyway, TL;DR - If you need Thread Local destructors, you can't use llvm::ThreadLocal

[tberghammer]

We already used some thread local storage in the same file to store the current Timer stack so I decided to move the depth to the same storage object (it is using the Host::ThreadLocalStorage* methods).

Originally I decided to go with the thread_local keyword because I expected it to be more efficient for integral types then the other methods and based on my understanding it should be supported since MSVC 2010 for integral types.

[clayborg]

Looks good.

lldb/trunk/include/lldb/Core/Timer.h

 //===-- Timer.h -------------------------------------------------*- C++ -*-===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #ifndef liblldb_Timer_h_
 #define liblldb_Timer_h_
 #if defined(__cplusplus)
 
 #include <stdarg.h>
 #include <stdio.h>
 #include <string>
+#include <mutex>
 #include "lldb/lldb-private.h"
 #include "lldb/Host/TimeValue.h"
 
 namespace lldb_private {
 
 //----------------------------------------------------------------------
 /// @class Timer Timer.h "lldb/Core/Timer.h"
 /// @brief A timer class that simplifies common timing metrics.
protected:
     //--------------------------------------------------------------
     /// Member variables
     //--------------------------------------------------------------
     const char *m_category;
     TimeValue m_total_start;
     TimeValue m_timer_start;
     uint64_t m_total_ticks; // Total running time for this timer including when other timers below this are running
     uint64_t m_timer_ticks; // Ticks for this timer that do not include when other timers below this one are running
-    static uint32_t g_depth;
-    static uint32_t g_display_depth;
-    static FILE * g_file;
+
+    static std::atomic_bool g_quiet;
+    static std::atomic_uint g_display_depth;
+    static std::mutex g_file_mutex;
+    static FILE* g_file;
+
 private:
     Timer();
     DISALLOW_COPY_AND_ASSIGN (Timer);
 };
     
 class IntervalTimer
 {
 public:

lldb/trunk/source/Core/Timer.cpp

 #include "lldb/Host/Mutex.h"
 #include "lldb/Host/Host.h"
 
 #include <stdio.h>
 
 using namespace lldb_private;
 
 #define TIMER_INDENT_AMOUNT 2
-static bool g_quiet = true;
-uint32_t Timer::g_depth = 0;
-uint32_t Timer::g_display_depth = 0;
-FILE * Timer::g_file = NULL;
-typedef std::vector<Timer *> TimerStack;
-typedef std::map<const char *, uint64_t> TimerCategoryMap;
+
+namespace
+{
+    typedef std::map<const char*, uint64_t> TimerCategoryMap;
+
+    struct TimerStack
+    {
+        TimerStack() :
+            m_depth(0)
+        {}
+
+        uint32_t m_depth;
+        std::vector<Timer*> m_stack;
+    };
+} // end of anonymous namespace
+
+std::atomic_bool Timer::g_quiet(true);
+std::atomic_uint Timer::g_display_depth(0);
+std::mutex Timer::g_file_mutex;
+FILE* Timer::g_file = nullptr;
+
 static lldb::thread_key_t g_key;
 
 static Mutex &
 GetCategoryMutex()
 {
     static Mutex g_category_mutex(Mutex::eMutexTypeNormal);
     return g_category_mutex;
 }

 
 Timer::Timer (const char *category, const char *format, ...) :
     m_category (category),
     m_total_start (),
     m_timer_start (),
     m_total_ticks (0),
     m_timer_ticks (0)
 {
-    if (g_depth++ < g_display_depth)
+    TimerStack *stack = GetTimerStackForCurrentThread ();
+    if (!stack)
+        return;
+
+    if (stack->m_depth++ < g_display_depth)
     {
         if (g_quiet == false)
         {
+            std::lock_guard<std::mutex> lock(g_file_mutex);
+
             // Indent
-            ::fprintf (g_file, "%*s", g_depth * TIMER_INDENT_AMOUNT, "");
+            ::fprintf (g_file, "%*s", stack->m_depth * TIMER_INDENT_AMOUNT, "");
             // Print formatted string
             va_list args;
             va_start (args, format);
             ::vfprintf (g_file, format, args);
             va_end (args);
 
             // Newline
             ::fprintf (g_file, "\n");
         }
         TimeValue start_time(TimeValue::Now());
         m_total_start = start_time;
         m_timer_start = start_time;
-        TimerStack *stack = GetTimerStackForCurrentThread ();
-        if (stack)
-        {
-            if (stack->empty() == false)
-                stack->back()->ChildStarted (start_time);
-            stack->push_back(this);
-        }
+
+        if (!stack->m_stack.empty())
+            stack->m_stack.back()->ChildStarted (start_time);
+        stack->m_stack.push_back(this);
     }
 }
 
-
 Timer::~Timer()
 {
+    TimerStack *stack = GetTimerStackForCurrentThread ();
+    if (!stack)
+        return;
+
     if (m_total_start.IsValid())
     {
         TimeValue stop_time = TimeValue::Now();
         if (m_total_start.IsValid())
         {
             m_total_ticks += (stop_time - m_total_start);
             m_total_start.Clear();
         }
         if (m_timer_start.IsValid())
         {
             m_timer_ticks += (stop_time - m_timer_start);
             m_timer_start.Clear();
         }
 
-        TimerStack *stack = GetTimerStackForCurrentThread ();
-        if (stack)
-        {
-            assert (stack->back() == this);
-            stack->pop_back();
-            if (stack->empty() == false)
-                stack->back()->ChildStopped(stop_time);
-        }
+        assert (stack->m_stack.back() == this);
+        stack->m_stack.pop_back();
+        if (stack->m_stack.empty() == false)
+            stack->m_stack.back()->ChildStopped(stop_time);
 
         const uint64_t total_nsec_uint = GetTotalElapsedNanoSeconds();
         const uint64_t timer_nsec_uint = GetTimerElapsedNanoSeconds();
         const double total_nsec = total_nsec_uint;
         const double timer_nsec = timer_nsec_uint;
 
         if (g_quiet == false)
         {
-
+            std::lock_guard<std::mutex> lock(g_file_mutex);
             ::fprintf (g_file,
                        "%*s%.9f sec (%.9f sec)\n",
-                       (g_depth - 1) *TIMER_INDENT_AMOUNT, "",
+                       (stack->m_depth - 1) *TIMER_INDENT_AMOUNT, "",
                        total_nsec / 1000000000.0,
                        timer_nsec / 1000000000.0);
         }
 
         // Keep total results for each category so we can dump results.
         Mutex::Locker locker (GetCategoryMutex());
         TimerCategoryMap &category_map = GetCategoryMap();
         category_map[m_category] += timer_nsec_uint;
     }
-    if (g_depth > 0)
-        --g_depth;
+    if (stack->m_depth > 0)
+        --stack->m_depth;
 }
 
 uint64_t
 Timer::GetTotalElapsedNanoSeconds()
 {
     uint64_t total_ticks = m_total_ticks;
 
     // If we are currently running, we need to add the current