[Command] Implement `stats`

[davide]

Summary

This allows us to collect useful metrics about lldb debugging sessions.

I thought that an example would be better than a thousand words:

Process 19705 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = step in
    frame #0: 0x0000000100000fb4 blah`main at blah.c:3
   1    int main(void) {
   2      int a = 6;
-> 3      return 0;
   4    }
(lldb) stats enable
(lldb) frame var a
(int) a = 6
(lldb) expr a
(int) $1 = 6
(lldb) stats disable
### Start STATISTICS dump ###
Number of expr evaluation successes : 1
Number of expr evaluation failures : 0
Number of frame var successes : 1
Number of frame var failures : 0
### End STATISTICS dump ###

Future improvements might include:

1. Passing a file, or implementing categories. The way this patch has been implements is generic enough to allow this to be extended easily without breaking the grammar
2. Adding an SBAPI and Python API for use in scripts.

Thanks to Jim Ingham for discussing the design with me.

[jasonmolenda]

My two cents,

Why print the '# Start STATISTICS dump #' header/footer when printing the results? I don't think we demarcate result output like that anywhere else in lldb. I don't think it adds anything for the user.

I would probably name the command statistics and have a built in "stats" alias.

Should statistics disable print the results, or should there be a 'statistics status' or 'statistics show' or 'statistics dump' command to show the statistics results accumulated so far?

[jasonmolenda]

Ah, no you couldn't set up a command alias like that. Still, if the full name was statistics, you could type 'stat' and it would match. 'stats' wouldn't, though.

I do think decoupling the disabling action from the dumping action would be an improvement. You may want to dump the current statistics multiple times during a sequence of commands, without disabling / re-enabling every time. And dropping the header/footer from the results.

[davide]

In D45547#1065054, @jasonmolenda wrote:

Ah, no you couldn't set up a command alias like that. Still, if the full name was statistics, you could type 'stat' and it would match. 'stats' wouldn't, though.

I do think decoupling the disabling action from the dumping action would be an improvement. You may want to dump the current statistics multiple times during a sequence of commands, without disabling / re-enabling every time. And dropping the header/footer from the results.

OK! I don't mind adding another dump subcommand. I think it makes sense.
I can also disable the footer/header, I largely got that format from opt -time-passes. I don't feel strongly about it, so I'll let everybody else decide :)

[labath]

I don't see myself using this command personally, but I agree that splitting the "disable stats collection" and "dump accumulated stats" into two actions seems a better choice (maybe disable could do a final auto-dump though). I also think the header/footer is not needed for a primarily interactive tool. If we have a command that dumps so much data that the user cannot tell where the output starts and ends then we're doing something wrong (PS: I wish we had automatic pagination for the backtrace command).

I am also wondering whether statistics should be a top-level command, or should we put it under "log". We already have "log timers enable/disable/...", which are doing something similar to this, so it seems like a good idea to move these two things closer together.

lldb/packages/Python/lldbsuite/test/functionalities/stats/main.c

13

Maybe test for failure as well (I guess trying to print an non-existing variable should do the trick)?

lldb/source/Commands/CommandObjectStats.cpp

31–35

I think we have some way (should involve eCommandRequiresTarget) to avoid the need for checking this.

43–46

Are you planning to have some kind of decentralized method of registering statistics?
If not, then I don't see a need for explicitly registering the statistic kinds here, since the single source of truth about the available kinds can be StatisticKind enum, and Target can just get the list from there automatically when need (when stats are enabled?)

This way we could even simplify the code by avoiding the "statistic is not registered but someone still called IncrementStats" state altogether) and the stats map could be a simple array with NumStatistics elements.

[davide]

I prefer having it as a top level command rather than part of log. If you think about it LLVM does the same distinction and it worked quite well in practice.
We plan to collect more metrics to the command so I'd very much like to have this living as a separate entity.

lldb/packages/Python/lldbsuite/test/functionalities/stats/main.c

13

Testing for failure here is a little tricky because the expression parser reports a failure only when it fails internally (and not when succeeds but returns an error because clangAST can't find the variable). Eventually we could make it more fine grained but for now I just would like to get the number of failures resolving variable due to expression parsing logic failing (and not because typos).

lldb/source/Commands/CommandObjectStats.cpp

31–35

I'll check this out, thanks!

43–46

No. I originally thought to make it that way but I have to say that maybe it's easier to have a centralized mechanism. I'm still unsure whether this should be a vector or a map, I'll think about it more.

[labath]

In D45547#1065661, @davide wrote:

I prefer having it as a top level command rather than part of log. If you think about it LLVM does the same distinction and it worked quite well in practice.
We plan to collect more metrics to the command so I'd very much like to have this living as a separate entity.

I agree that "logging" and "statistics" sound like two different entities. Though in that case, maybe it's the "log timers" command that is misplaced. "performance timers" sound more like "statistics" than "logging" to me. Maybe eventually these two things should be merged even? I don't know what's the right solution here, and I don't care much about it even, though I would be sad if the choice we make now prevents some future unification due to backwards compatibility issues.

lldb/packages/Python/lldbsuite/test/functionalities/stats/main.c

13

Makes sense, thanks for the explanation.

lldb/source/Commands/CommandObjectStats.cpp

43–46

llvm manual recommends http://llvm.org/docs/ProgrammersManual.html#map-like-containers-std-map-densemap-etc vector as a first choice data structure for a map. :P

[davide]

I'm under the impression that we should either merge log timers with stats or just remove log timers altogether and start from scratch.
From what I hear from Jim, it was really useful for a few people, so maybe a fresh start would be a better way of handling things. Thanks!

lldb/source/Commands/CommandObjectStats.cpp

43–46

Allright, you convinced me :)

[xiaobai]

I really like this idea! It will be very helpful for @sas and I. I'd like to +1 creating a separate stats dump subcommand instead of dumping stats on stats disable.

lldb/source/Commands/CommandObjectStats.cpp

37

nit: You can drop the == true

77

nit:

if (!target->GetCollectingStats()) {

[jingham]

Timers seemed like they would be really useful for collection of data about operations in lldb, but for most things I think they end up being hard to use because actual wall-clock time is so variable from run to run, and especially for disk and inter-process heavy operations, which lldb tends to be. I'm not sure we should give up on timers, sometimes you want to know "how many times did I do X" and other times "how long did X take" and the Timers are more useful for this than just a sample or wall-clock times because you can find out how long it took "in the Dwarf parser", etc.

But in many cases our performance is more driven by unnecessary lookups, and that sort of error. For that sort of error it will be much more useful to say "given program A and expression B, how many DWARF DIE lookups did I do" than "how long did I spent wall-clock in the DWARF parser..." When the former goes from 20 to 2000, that will be a much clearer symbol that we probably introduced a performance regression.

[davide]

In D45547#1066348, @jingham wrote:

Timers seemed like they would be really useful for collection of data about operations in lldb, but for most things I think they end up being hard to use because actual wall-clock time is so variable from run to run, and especially for disk and inter-process heavy operations, which lldb tends to be. I'm not sure we should give up on timers, sometimes you want to know "how many times did I do X" and other times "how long did X take" and the Timers are more useful for this than just a sample or wall-clock times because you can find out how long it took "in the Dwarf parser", etc.

But in many cases our performance is more driven by unnecessary lookups, and that sort of error. For that sort of error it will be much more useful to say "given program A and expression B, how many DWARF DIE lookups did I do" than "how long did I spent wall-clock in the DWARF parser..." When the former goes from 20 to 2000, that will be a much clearer symbol that we probably introduced a performance regression.

Yes, I agree. I addressed all the comments.
Jim, can you please take a look? Thanks!

[davide]

lldb/source/Commands/CommandObjectStats.cpp

37

Thanks, I'll fix these!

[jingham]

I made a few comments all to the same effect, you can use CommandObject::GetSelectedOrDummyTarget to get the target that the command is operating on, or you can get is straight from m_exe_ctx if you want to make sure that you are getting a real target. In the case of stats, I think running with the dummy target is fine, since for instance you can run expressions in the dummy target...

Other than that I think this is a good place to start from.

lldb/source/Commands/CommandObjectExpression.cpp

626

This is what CommandObject::GetSelectedOrDummy target is for.

lldb/source/Commands/CommandObjectStats.cpp

30–31

By the time the DoExecute is run, m_exe_ctx has the execution context, so you can get the target from there, or use GetSelectedOrDummyTarget. You can run expressions in the dummy target so there's no reason not to collect stats from it.

[davide]

lldb/source/Commands/CommandObjectExpression.cpp

626

I just moved existing code, but I agree it's better using this API.

[davide]

In D45547#1066044, @xiaobai wrote:

I really like this idea! It will be very helpful for @sas and I. I'd like to +1 creating a separate stats dump subcommand instead of dumping stats on stats disable.

Thanks! If you has ideas or want to add stuffs, don't hesitate to start a discussion and/or submit a review!

lldb/include/lldb/Target/Target.h

 #include "lldb/Target/ProcessLaunchInfo.h"
 #include "lldb/Target/SectionLoadHistory.h"
 #include "lldb/Utility/ArchSpec.h"
+#include "lldb/Utility/LLDBAssert.h"
 #include "lldb/Utility/Timeout.h"
 #include "lldb/lldb-public.h"
 

   static void ImageSearchPathsChanged(const PathMappingList &path_list,
                                       void *baton);
 
+  //------------------------------------------------------------------
+  // Utilities for `stats` command.
+  //------------------------------------------------------------------
+private:
+  std::vector<uint32_t> m_stats_storage;
+  bool m_collecting_stats = false;
+
+public:
+  void SetCollectingStats(bool v) { m_collecting_stats = v; }
+
+  bool GetCollectingStats() { return m_collecting_stats; }
+
+  void IncrementStats(lldb_private::StatisticKind key) {
+    if (!GetCollectingStats())
+      return;
+    lldbassert(key < lldb_private::StatisticKind::StatisticMax &&
+               "invalid statistics!");
+    m_stats_storage[key] += 1;
+  }
+
+  std::vector<uint32_t> GetStatistics() { return m_stats_storage; }
+
 private:
   //------------------------------------------------------------------
   /// Construct with optional file and arch.

lldb/include/lldb/lldb-private-enumerations.h

   Typedef
 };
 
+//----------------------------------------------------------------------
+// Enumerations that can be used to specify the kind of metric we're
+// looking at when collecting stats.
+//----------------------------------------------------------------------
+enum StatisticKind {
+  ExpressionSuccessful = 0,
+  ExpressionFailure = 1,
+  FrameVarSuccess = 2,
+  FrameVarFailure = 3,
+  StatisticMax = 4
+};
+
 } // namespace lldb_private
 
 namespace llvm {

lldb/packages/Python/lldbsuite/test/functionalities/stats/Makefile

+LEVEL = ../../make
+C_SOURCES := main.c
+include $(LEVEL)/Makefile.rules

lldb/packages/Python/lldbsuite/test/functionalities/stats/TestStats.py

+from lldbsuite.test import lldbinline
+from lldbsuite.test import decorators
+
+lldbinline.MakeInlineTest(
+    __file__, globals(), [])

lldb/packages/Python/lldbsuite/test/functionalities/stats/main.c

+// Test that the lldb command `stats` works.
+
+int main(void) {
+  int patatino = 27;
+  //%self.expect("statistics disable", substrs=['need to enable statistics before disabling'], error=True)
+  //%self.expect("statistics enable")
+  //%self.expect("statistics enable", substrs=['already enabled'], error=True)
+  //%self.expect("expr patatino", substrs=['27'])
+  //%self.expect("statistics disable")
+  //%self.expect("statistics dump", substrs=['expr evaluation successes : 1', 'expr evaluation failures : 0'])
+  //%self.expect("frame var", substrs=['27'])
+  //%self.expect("statistics enable")
+  //%self.expect("frame var", substrs=['27'])
+  //%self.expect("statistics disable")
+  //%self.expect("statistics dump", substrs=['frame var successes : 1', 'frame var failures : 0'])
+
+  return 0;
+}

lldb/source/Commands/CommandObjectExpression.cpp

   if (expr == nullptr)
     expr = command;
 
+  Target *target = m_interpreter.GetExecutionContext().GetTargetPtr();
+  if (!target)
+    target = GetDummyTarget();
+
   if (EvaluateExpression(expr, &(result.GetOutputStream()),
                          &(result.GetErrorStream()), &result)) {
-    Target *target = m_interpreter.GetExecutionContext().GetTargetPtr();
-    if (!target)
-        target = GetDummyTarget();
 
     if (!m_fixed_expression.empty() && target->GetEnableNotifyAboutFixIts()) {
       CommandHistory &history = m_interpreter.GetCommandHistory();

       }
       history.AppendString(fixed_command);
     }
+    // Increment statistics to record this expression evaluation
+    // success.
+    target->IncrementStats(StatisticKind::ExpressionSuccessful);
     return true;
   }
 
+  // Increment statistics to record this expression evaluation
+  // failure.
+  target->IncrementStats(StatisticKind::ExpressionFailure);
   result.SetStatus(eReturnStatusFailed);
   return false;
 }

lldb/source/Commands/CommandObjectFrame.cpp

       m_interpreter.TruncationWarningGiven();
     }
 
-    return result.Succeeded();
+    // Increment statistics.
+    bool res = result.Succeeded();
+    Target *target = m_exe_ctx.GetTargetPtr();
+    if (!target)
+      target = GetDummyTarget();
+    if (res)
+      target->IncrementStats(StatisticKind::FrameVarSuccess);
+    else
+      target->IncrementStats(StatisticKind::FrameVarFailure);
+    return res;
   }
 
 protected:

lldb/source/Commands/CommandObjectStats.h

 #define liblldb_CommandObjectStats_h_
 
 #include "lldb/Interpreter/CommandObject.h"
+#include "lldb/Interpreter/CommandObjectMultiword.h"
 
 namespace lldb_private {
-class CommandObjectStats : public CommandObjectParsed {
+class CommandObjectStats : public CommandObjectMultiword {
 public:
   CommandObjectStats(CommandInterpreter &interpreter);
 
   ~CommandObjectStats() override;
-
-protected:
-  bool DoExecute(Args &command, CommandReturnObject &result) override;
 };
 } // namespace lldb_private
 

lldb/source/Commands/CommandObjectStats.cpp

 #include "lldb/Host/Host.h"
 #include "lldb/Interpreter/CommandInterpreter.h"
 #include "lldb/Interpreter/CommandReturnObject.h"
+#include "lldb/Target/Target.h"
 
 using namespace lldb;
 using namespace lldb_private;
 
-CommandObjectStats::CommandObjectStats(CommandInterpreter &interpreter)
-    : CommandObjectParsed(
-          interpreter, "stats", "Print statistics about a debugging session",
-          nullptr) {
-}
+class CommandObjectStatsEnable : public CommandObjectParsed {
+public:
+  CommandObjectStatsEnable(CommandInterpreter &interpreter)
+      : CommandObjectParsed(
+            interpreter, "enable", "Enable statistics collection", nullptr,
+            eCommandRequiresTarget | eCommandProcessMustBePaused) {}
+
+  ~CommandObjectStatsEnable() override = default;
+
+protected:
+  bool DoExecute(Args &command, CommandReturnObject &result) override {
+    auto exe_ctx = m_interpreter.GetExecutionContext();
+    Target *target = exe_ctx.GetTargetPtr();
+
+    if (target->GetCollectingStats() == true) {
+      result.AppendError("statistics already enabled");
+      result.SetStatus(eReturnStatusFailed);
+      return false;
+    }
+
+    target->SetCollectingStats(true);
+    result.SetStatus(eReturnStatusSuccessFinishResult);
+    return true;
+  }
+};
+
+class CommandObjectStatsDisable : public CommandObjectParsed {
+public:
+  CommandObjectStatsDisable(CommandInterpreter &interpreter)
+      : CommandObjectParsed(
+            interpreter, "disable", "Disable statistics collection", nullptr,
+            eCommandRequiresTarget | eCommandProcessMustBePaused) {}
+
+  ~CommandObjectStatsDisable() override = default;
+
+protected:
+  bool DoExecute(Args &command, CommandReturnObject &result) override {
+    auto exe_ctx = m_interpreter.GetExecutionContext();
+    Target *target = exe_ctx.GetTargetPtr();
 
-bool CommandObjectStats::DoExecute(Args &command, CommandReturnObject &result) {
-  return true;
+    if (target->GetCollectingStats() == false) {
+      result.AppendError("need to enable statistics before disabling them");
+      result.SetStatus(eReturnStatusFailed);
+      return false;
+    }
+
+    target->SetCollectingStats(false);
+    result.SetStatus(eReturnStatusSuccessFinishResult);
+    return true;
+  }
+};
+
+class CommandObjectStatsDump : public CommandObjectParsed {
+private:
+  std::string GetStatDescription(lldb_private::StatisticKind K) {
+    switch (K) {
+    case StatisticKind::ExpressionSuccessful:
+      return "Number of expr evaluation successes";
+    case StatisticKind::ExpressionFailure:
+      return "Number of expr evaluation failures";
+    case StatisticKind::FrameVarSuccess:
+      return "Number of frame var successes";
+    case StatisticKind::FrameVarFailure:
+      return "Number of frame var failures";
+    case StatisticKind::StatisticMax:
+      return "";
+    }
+    llvm_unreachable("Statistic not registered!");
+  }
+
+public:
+  CommandObjectStatsDump(CommandInterpreter &interpreter)
+      : CommandObjectParsed(
+            interpreter, "dump", "Dump statistics results", nullptr,
+            eCommandRequiresTarget | eCommandProcessMustBePaused) {}
+
+  ~CommandObjectStatsDump() override = default;
+
+protected:
+  bool DoExecute(Args &command, CommandReturnObject &result) override {
+    auto exe_ctx = m_interpreter.GetExecutionContext();
+    Target *target = exe_ctx.GetTargetPtr();
+
+    uint32_t i = 0;
+    for (auto &stat : target->GetStatistics()) {
+      result.AppendMessageWithFormat(
+          "%s : %u\n",
+          GetStatDescription(static_cast<lldb_private::StatisticKind>(i))
+              .c_str(),
+          stat);
+      i += 1;
+    }
+    result.SetStatus(eReturnStatusSuccessFinishResult);
+    return true;
+  }
+};
+
+CommandObjectStats::CommandObjectStats(CommandInterpreter &interpreter)
+    : CommandObjectMultiword(interpreter, "statistics",
+                             "Print statistics about a debugging session",
+                             "statistics <subcommand> [<subcommand-options>]") {
+  LoadSubCommand("enable",
+                 CommandObjectSP(new CommandObjectStatsEnable(interpreter)));
+  LoadSubCommand("disable",
+                 CommandObjectSP(new CommandObjectStatsDisable(interpreter)));
+  LoadSubCommand("dump",
+                 CommandObjectSP(new CommandObjectStatsDump(interpreter)));
 }
 
-CommandObjectStats::~CommandObjectStats() {}
+CommandObjectStats::~CommandObjectStats() = default;

lldb/source/Interpreter/CommandInterpreter.cpp

       CommandObjectSP(new CommandObjectMultiwordSettings(*this));
   m_command_dict["source"] =
       CommandObjectSP(new CommandObjectMultiwordSource(*this));
-  m_command_dict["stats"] = CommandObjectSP(new CommandObjectStats(*this));
+  m_command_dict["statistics"] = CommandObjectSP(new CommandObjectStats(*this));
   m_command_dict["target"] =
       CommandObjectSP(new CommandObjectMultiwordTarget(*this));
   m_command_dict["thread"] =

lldb/source/Target/Target.cpp

       Broadcaster(debugger.GetBroadcasterManager(),
                   Target::GetStaticBroadcasterClass().AsCString()),
       ExecutionContextScope(), m_debugger(debugger), m_platform_sp(platform_sp),
-      m_mutex(), m_arch(target_arch),
-      m_images(this), m_section_load_history(), m_breakpoint_list(false),
-      m_internal_breakpoint_list(true), m_watchpoint_list(), m_process_sp(),
-      m_search_filter_sp(), m_image_search_paths(ImageSearchPathsChanged, this),
-      m_ast_importer_sp(), m_source_manager_ap(), m_stop_hooks(),
-      m_stop_hook_next_id(0), m_valid(true), m_suppress_stop_hooks(false),
-      m_is_dummy_target(is_dummy_target)
+      m_mutex(), m_arch(target_arch), m_images(this), m_section_load_history(),
+      m_breakpoint_list(false), m_internal_breakpoint_list(true),
+      m_watchpoint_list(), m_process_sp(), m_search_filter_sp(),
+      m_image_search_paths(ImageSearchPathsChanged, this), m_ast_importer_sp(),
+      m_source_manager_ap(), m_stop_hooks(), m_stop_hook_next_id(0),
+      m_valid(true), m_suppress_stop_hooks(false),
+      m_is_dummy_target(is_dummy_target),
+      m_stats_storage(static_cast<int>(StatisticKind::StatisticMax))
 
 {
   SetEventName(eBroadcastBitBreakpointChanged, "breakpoint-changed");