Add more information to the log timer dump

[aadsm]

Summary

The log timer dump is showing the time of the function itself minus any function that is called from this one that also happens to be timed. However, this is really not obvious and it also makes it hard to understand the time spent in total and also which children are actually taking the time.
To get a better reading of the timer dump I added the total, children (which I named child) and also the hit count. I used these timers to figure out a performance issue and only after adding this things were more clear to me.

It looks like this:

(lldb) log timer dump
35.447713617 sec (total: 35.449s; child: 0.001s; count: 1374) for void SymbolFileDWARF::Index()
29.717921481 sec (total: 29.718s; child: 0.000s; count: 8230500) for const lldb_private::ConstString &lldb_private::Mangled::GetDemangledName(lldb::LanguageType) const
21.049508865 sec (total: 24.683s; child: 3.633s; count: 1399) for void lldb_private::Symtab::InitNameIndexes()
...

[teemperor]

Could you provide a test? There are some existing tests for Timer in lldb/unittests/Utility/TimerTest.cpp which you can extend. You can run/compile these tests via LIT_FILTER="TimerTest" make check-lldb.

(I also believe this patch breaks TimerTest as it checks the output of DumpCategoryTimes)

lldb/source/Utility/Timer.cpp

111 ↗

(On Diff #197002)

Can you move struct this into an anonymous namespace?

[aadsm]

Fix and add unit test

[aadsm]

Move struct to anonymous namespace

[davide]

lldb/unittests/Utility/TimerTest.cpp

100–101 ↗

(On Diff #197049)

this seems ... very fragile.

[aadsm]

lldb/unittests/Utility/TimerTest.cpp

100–101 ↗

(On Diff #197049)

that's a good point. I'm not that familiar with the ieee754 to know what's a safe interval here, do you know?

[labath]

lldb/source/Utility/Timer.cpp

98–101 ↗

(On Diff #197049)

IIUC, one of these is redundant, as it can be recomputed from the other two, so we should remove it.

110–123 ↗

(On Diff #197049)

You can just move the const char * into the Stats struct and get rid of the std::pair. Then the CategoryMapIteratorSortCriterion thingy can also become a regular operator<.

lldb/unittests/Utility/TimerTest.cpp

89 ↗

(On Diff #197049)

I'm not sure this second line is really helpful here. Looking at this output, I would have never guessed that these numbers mean we were running two recursive timers belonging to the same category, and the entire thing finished in 20ms.

Maybe this isn't a real usage problem, as normally we don't have recursive timers (I believe), but in that case, we probably shouldn't have them in this test either (as right now it is the only documentation about how these times are supposed to work).

What's the reason for using recursive timers here? If you just wanted to check that the invocation count is 2, then you can wrap the two timers in {} blocks, so that they execute "sequentially" instead of recursively. (Which I guess would match the typical scenario where a timer-enabled function calls another timer-enabled function two times in a loop.)

96–97 ↗

(On Diff #197049)

Could you help clang-format split this string more reasonably (e.g., by manually splitting the string after the ])?

100–101 ↗

(On Diff #197049)

I think you want to use EXPECT_DOUBLE_EQ here.

[aadsm]

lldb/source/Utility/Timer.cpp

110–123 ↗

(On Diff #197049)

ah yeah, that will be much better.

lldb/unittests/Utility/TimerTest.cpp

89 ↗

(On Diff #197049)

you're totally right, I actually didn't think much about it when I wrote the test but this should definitely be sequential not recursive.

[aadsm]

lldb/unittests/Utility/TimerTest.cpp

100–101 ↗

(On Diff #197049)

It still doesn't help me :(

Expected: total1 - child1
      Which is: 0.099999999999999992
To be equal to: seconds1
      Which is: 0.10011115499999999

[aadsm]

Only store needed data for dumping and put everything in the struct. Also fix tests to do sequential calls instead of recursive.

[labath]

lldb/unittests/Utility/TimerTest.cpp

100–101 ↗

(On Diff #197049)

Ah, ok I see now.. You need smaller precision because two of the numbers are only printed with three decimal spaces. In that case, you can do EXPECT_NEAR(a-b, c, 0.002). ( I chose 0.002 instead of 0.001 just in case it's possible for rounding errors to add up to over 0.001 --- cca. 0.0005 for a, ~0.0005 for b and ~0.0...05 for c).

[aadsm]

Use EXPECT_NEAR for tests

[aadsm]

• Renamed CompareFileAndLine to FileAndLineEqual and made it return a bool
• Made include_inlined_functions a mandatory parameter in GetSameLineContiguousAddressRange
• Fix documentation
• Refactored the object file creation from YAML
• Got rid of a bunch of macros
• Improved the test case

[aadsm]

Undo the previous changes because I updated to the wrong diff.

[aadsm]

Rebase and fixed an issue with one of the asserts.

lldb/trunk/include/lldb/Utility/Timer.h

public:
   class Category {
   public:
     explicit Category(const char *category_name);
 
   private:
     friend class Timer;
     const char *m_name;
     std::atomic<uint64_t> m_nanos;
+    std::atomic<uint64_t> m_nanos_total;
+    std::atomic<uint64_t> m_count;
     std::atomic<Category *> m_next;
 
     DISALLOW_COPY_AND_ASSIGN(Category);
   };
 
   /// Default constructor.
   Timer(Category &category, const char *format, ...)
       __attribute__((format(printf, 3, 4)));

lldb/trunk/source/Utility/Timer.cpp

 
 static TimerStack &GetTimerStackForCurrentThread() {
   static thread_local TimerStack g_stack;
   return g_stack;
 }
 
 Timer::Category::Category(const char *cat) : m_name(cat) {
   m_nanos.store(0, std::memory_order_release);
+  m_nanos_total.store(0, std::memory_order_release);
+  m_count.store(0, std::memory_order_release);
   Category *expected = g_categories;
   do {
     m_next = expected;
   } while (!g_categories.compare_exchange_weak(expected, this));
 }
 
 void Timer::SetQuiet(bool value) { g_quiet = value; }
 
Timer::~Timer() {
 
   assert(stack.back() == this);
   stack.pop_back();
   if (!stack.empty())
     stack.back()->ChildDuration(total_dur);
 
   // Keep total results for each category so we can dump results.
   m_category.m_nanos += std::chrono::nanoseconds(timer_dur).count();
+  m_category.m_nanos_total += std::chrono::nanoseconds(total_dur).count();
+  m_category.m_count++;
 }
 
 void Timer::SetDisplayDepth(uint32_t depth) { g_display_depth = depth; }
 
 /* binary function predicate:
  * - returns whether a person is less than another person
  */
-
-typedef std::pair<const char *, uint64_t> TimerEntry;
-
-static bool CategoryMapIteratorSortCriterion(const TimerEntry &lhs,
-                                             const TimerEntry &rhs) {
-  return lhs.second > rhs.second;
+namespace {
+struct Stats {
+  const char *name;
+  uint64_t nanos;
+  uint64_t nanos_total;
+  uint64_t count;
+};
+} // namespace
+
+static bool CategoryMapIteratorSortCriterion(const Stats &lhs,
+                                             const Stats &rhs) {
+  return lhs.nanos > rhs.nanos;
 }
 
 void Timer::ResetCategoryTimes() {
-  for (Category *i = g_categories; i; i = i->m_next)
+  for (Category *i = g_categories; i; i = i->m_next) {
     i->m_nanos.store(0, std::memory_order_release);
+    i->m_nanos_total.store(0, std::memory_order_release);
+    i->m_count.store(0, std::memory_order_release);
+  }
 }
 
 void Timer::DumpCategoryTimes(Stream *s) {
-  std::vector<TimerEntry> sorted;
+  std::vector<Stats> sorted;
   for (Category *i = g_categories; i; i = i->m_next) {
     uint64_t nanos = i->m_nanos.load(std::memory_order_acquire);
-    if (nanos)
-      sorted.push_back(std::make_pair(i->m_name, nanos));
+    if (nanos) {
+      uint64_t nanos_total = i->m_nanos_total.load(std::memory_order_acquire);
+      uint64_t count = i->m_count.load(std::memory_order_acquire);
+      Stats stats{i->m_name, nanos, nanos_total, count};
+      sorted.push_back(stats);
+    }
   }
   if (sorted.empty())
     return; // Later code will break without any elements.
 
   // Sort by time
   llvm::sort(sorted.begin(), sorted.end(), CategoryMapIteratorSortCriterion);
 
-  for (const auto &timer : sorted)
-    s->Printf("%.9f sec for %s\n", timer.second / 1000000000., timer.first);
+  for (const auto &stats : sorted)
+    s->Printf("%.9f sec (total: %.3fs; child: %.3fs; count: %llu) for %s\n",
+              stats.nanos / 1000000000., stats.nanos_total / 1000000000.,
+              (stats.nanos_total - stats.nanos) / 1000000000., stats.count,
+              stats.name);
 }

lldb/trunk/unittests/Utility/TimerTest.cpp

Timer::ResetCategoryTimes();
     std::this_thread::sleep_for(std::chrono::milliseconds(100));
     static Timer::Category tcat2("CAT2");
     Timer t2(tcat2, ".");
     std::this_thread::sleep_for(std::chrono::milliseconds(10));
   }
   StreamString ss;
   Timer::DumpCategoryTimes(&ss);
   double seconds1, seconds2;
-  ASSERT_EQ(2, sscanf(ss.GetData(), "%lf sec for CAT1%*[\n ]%lf sec for CAT2",
+  ASSERT_EQ(2, sscanf(ss.GetData(),
+                      "%lf sec (total: %*lfs; child: %*lfs; count: %*d) for "
+                      "CAT1%*[\n ]%lf sec for CAT2",
                       &seconds1, &seconds2))
       << "String: " << ss.GetData();
   EXPECT_LT(0.01, seconds1);
   EXPECT_GT(1, seconds1);
   EXPECT_LT(0.001, seconds2);
   EXPECT_GT(0.1, seconds2);
 }
+
+TEST(TimerTest, CategoryTimesStats) {
+  Timer::ResetCategoryTimes();
+  {
+    static Timer::Category tcat1("CAT1");
+    Timer t1(tcat1, ".");
+    std::this_thread::sleep_for(std::chrono::milliseconds(100));
+    static Timer::Category tcat2("CAT2");
+    {
+      Timer t2(tcat2, ".");
+      std::this_thread::sleep_for(std::chrono::milliseconds(10));
+    }
+    {
+      Timer t3(tcat2, ".");
+      std::this_thread::sleep_for(std::chrono::milliseconds(10));
+    }
+  }
+  // Example output:
+  // 0.105202764 sec (total: 0.132s; child: 0.027s; count: 1) for CAT1
+  // 0.026772798 sec (total: 0.027s; child: 0.000s; count: 2) for CAT2
+  StreamString ss;
+  Timer::DumpCategoryTimes(&ss);
+  double seconds1, total1, child1, seconds2;
+  int count1, count2;
+  ASSERT_EQ(
+      6, sscanf(ss.GetData(),
+                "%lf sec (total: %lfs; child: %lfs; count: %d) for CAT1%*[\n ]"
+                "%lf sec (total: %*lfs; child: %*lfs; count: %d) for CAT2",
+                &seconds1, &total1, &child1, &count1, &seconds2, &count2))
+      << "String: " << ss.GetData();
+  EXPECT_NEAR(total1 - child1, seconds1, 0.002);
+  EXPECT_EQ(1, count1);
+  EXPECT_NEAR(child1, seconds2, 0.002);
+  EXPECT_EQ(2, count2);
+}