Add the stop count to "statistics dump" in each target's dictionary.

[clayborg]

Summary

It is great to know how many times the target has stopped over its lifetime as each time the target stops, and possibly resumes without the user seeing it for things like shared library loading and signals that are not notified and auto continued, to help explain why a debug session might be slow. This is now included as "stopCount" inside each target JSON.

[jingham]

The stop id includes all the user expression stops. So the same "drive through code" could produce very different stop counts if you ran a bunch of p-s in one session but not the other. You can't do better than that at present since we only track the natural/vrs. expression stop id for the last stop. But if it mattered you could keep a separate "natural stop" counter and report that instead. You can't quite get back to the natural stops by subtracting the number of expressions, because not all expressions run the target, and some do twice (if the one-thread run times out).

I'm not sure that's terribly important, provided people doing this analysis know that both stops are getting counted, and this is a useful statistic either way.

Anyway, other than that, LGTM.

[clayborg]

In D113810#3128741, @jingham wrote:

The stop id includes all the user expression stops. So the same "drive through code" could produce very different stop counts if you ran a bunch of p-s in one session but not the other. You can't do better than that at present since we only track the natural/vrs. expression stop id for the last stop. But if it mattered you could keep a separate "natural stop" counter and report that instead. You can't quite get back to the natural stops by subtracting the number of expressions, because not all expressions run the target, and some do twice (if the one-thread run times out).

I actually don't care about the number of natural user stops as the user will be aware of these stops. The info I am interested in is when a debug session has thousands of stops that auto resumed a debug session. This can happen if unix signals are used for program flow control or working around things. Android uses SIGSEGV for catching java NULL derefs and many times we will auto resume from these depending on signal settings. If a debug session is taking a long time it is nice to know. Some users might also have some python module that gets loaded and might end up setting a breakpoint with a callback that can auto resume.

The one metric I do want in the future is the time spent in stops that auto resume, like shared library loading stops where it stops, does some work, and auto resumes. The unix signals that cause stops where we auto resume would fit into that category. So one idea for the future it so start a timer each time we stop and then right before we resume stop the timer and report this time as something like "transparentStopTime" or something similar. Expression evaluation could also be counted in the time it took to evaluate expression as a separate stat.

I'm not sure that's terribly important, provided people doing this analysis know that both stops are getting counted, and this is a useful statistic either way.

Anyway, other than that, LGTM.

I was only looking for the total stops for now as it was really easy to add and could give us some insight to slow debug sessions if this number is really high.

[jingham]

In D113810#3132418, @clayborg wrote:

In D113810#3128741, @jingham wrote:

The stop id includes all the user expression stops. So the same "drive through code" could produce very different stop counts if you ran a bunch of p-s in one session but not the other. You can't do better than that at present since we only track the natural/vrs. expression stop id for the last stop. But if it mattered you could keep a separate "natural stop" counter and report that instead. You can't quite get back to the natural stops by subtracting the number of expressions, because not all expressions run the target, and some do twice (if the one-thread run times out).

I actually don't care about the number of natural user stops as the user will be aware of these stops. The info I am interested in is when a debug session has thousands of stops that auto resumed a debug session. This can happen if unix signals are used for program flow control or working around things. Android uses SIGSEGV for catching java NULL derefs and many times we will auto resume from these depending on signal settings. If a debug session is taking a long time it is nice to know. Some users might also have some python module that gets loaded and might end up setting a breakpoint with a callback that can auto resume.

IMO, the real solution for this issue is for lldb to invent (if there isn't already) a "auto-continue signals" packet, so we could tell the stub to restart from those signals w/o even telling lldb about it. Oh, but I guess you can't do that for SIGSEGV...

The one metric I do want in the future is the time spent in stops that auto resume, like shared library loading stops where it stops, does some work, and auto resumes. The unix signals that cause stops where we auto resume would fit into that category. So one idea for the future it so start a timer each time we stop and then right before we resume stop the timer and report this time as something like "transparentStopTime" or something similar. Expression evaluation could also be counted in the time it took to evaluate expression as a separate stat.

Also, ThreadPlans stop a lot without any user-visible stops. So a complicated step can also rack up the stops. Right now, we don't do any accounting for "who is responsible" for auto-continuing, so you'd have to add that in.

I'm not sure that's terribly important, provided people doing this analysis know that both stops are getting counted, and this is a useful statistic either way.

Anyway, other than that, LGTM.

I was only looking for the total stops for now as it was really easy to add and could give us some insight to slow debug sessions if this number is really high.

Sounds fine.

[clayborg]

In D113810#3133655, @jingham wrote:

In D113810#3132418, @clayborg wrote:

In D113810#3128741, @jingham wrote:

The stop id includes all the user expression stops. So the same "drive through code" could produce very different stop counts if you ran a bunch of p-s in one session but not the other. You can't do better than that at present since we only track the natural/vrs. expression stop id for the last stop. But if it mattered you could keep a separate "natural stop" counter and report that instead. You can't quite get back to the natural stops by subtracting the number of expressions, because not all expressions run the target, and some do twice (if the one-thread run times out).

I actually don't care about the number of natural user stops as the user will be aware of these stops. The info I am interested in is when a debug session has thousands of stops that auto resumed a debug session. This can happen if unix signals are used for program flow control or working around things. Android uses SIGSEGV for catching java NULL derefs and many times we will auto resume from these depending on signal settings. If a debug session is taking a long time it is nice to know. Some users might also have some python module that gets loaded and might end up setting a breakpoint with a callback that can auto resume.

IMO, the real solution for this issue is for lldb to invent (if there isn't already) a "auto-continue signals" packet, so we could tell the stub to restart from those signals w/o even telling lldb about it. Oh, but I guess you can't do that for SIGSEGV...

Agreed. It would help speed things up in the lldb-server supports it. Like SIGCHILD and other signals you might want to just ignore.

The one metric I do want in the future is the time spent in stops that auto resume, like shared library loading stops where it stops, does some work, and auto resumes. The unix signals that cause stops where we auto resume would fit into that category. So one idea for the future it so start a timer each time we stop and then right before we resume stop the timer and report this time as something like "transparentStopTime" or something similar. Expression evaluation could also be counted in the time it took to evaluate expression as a separate stat.

Also, ThreadPlans stop a lot without any user-visible stops. So a complicated step can also rack up the stops. Right now, we don't do any accounting for "who is responsible" for auto-continuing, so you'd have to add that in.

Yep, it was more work than I have time for right now.

I'm not sure that's terribly important, provided people doing this analysis know that both stops are getting counted, and this is a useful statistic either way.

Anyway, other than that, LGTM.

I was only looking for the total stops for now as it was really easy to add and could give us some insight to slow debug sessions if this number is really high.

Sounds fine.

Keep an eye out for other stats and things that can help explain things.

One thing I will be doing soon is I want to time how long it takes to create TypeSystem AST instances. I know for Swift this can be really slow when you have many binaries that each have their own Swift AST and if they have a lot of clang modules that might need to be created and cached. I am sure that the Clang AST type system instances can take a while if there is any clang module caching they want to do. The first time can take a while and it would be good to measure.

lldb/source/Target/Statistics.cpp

json::Value TargetStats::ToJSON(Target &target) {
   }
 
   ProcessSP process_sp = target.GetProcessSP();
   if (process_sp) {
     UnixSignalsSP unix_signals_sp = process_sp->GetUnixSignals();
     if (unix_signals_sp)
       target_metrics_json.try_emplace("signals",
                                       unix_signals_sp->GetHitCountStatistics());
+    uint32_t stop_id = process_sp->GetStopID();
+    target_metrics_json.try_emplace("stopCount", stop_id);
   }
   target_metrics_json.try_emplace("breakpoints", std::move(breakpoints_array));
   target_metrics_json.try_emplace("totalBreakpointResolveTime",
                                   totalBreakpointResolveTime);
 
   return target_metrics_json;
 }
 

lldb/test/API/commands/statistics/basic/TestStats.py

def test_expressions_frame_var_counts(self):
         self.verify_success_fail_count(stats, 'expressionEvaluation', 2, 2)
 
         self.expect("statistics enable")
         # 'frame var' with enabled statistics will change stats.
         self.expect("frame var", substrs=['27'])
         stats = self.get_target_stats(self.get_stats())
         self.verify_success_fail_count(stats, 'frameVariable', 1, 0)
 
+        # Test that "stopCount" is available when the process has run
+        self.assertEqual('stopCount' in stats, True,
+                         'ensure "stopCount" is in target JSON')
+        self.assertGreater(stats['stopCount'], 0,
+                           'make sure "stopCount" is greater than zero')
+
     def test_default_no_run(self):
         """Test "statistics dump" without running the target.
 
         When we don't run the target, we expect to not see any 'firstStopTime'
         or 'launchOrAttachTime' top level keys that measure the launch or
         attach of the target.
 
         Output expected to be something like:
def test_default_no_run(self):
           "totalDebugInfoParseTime": 8.2121400240000071,
           "totalSymbolTableParseTime": 0.123,
           "totalSymbolTableIndexTime": 0.234,
         }
         """
         target = self.createTestTarget()
         debug_stats = self.get_stats()
         debug_stat_keys = [
-            'modules', 
+            'modules',
             'targets',
             'totalSymbolTableParseTime',
             'totalSymbolTableIndexTime',
             'totalDebugInfoByteSize',
             'totalDebugInfoIndexTime',
             'totalDebugInfoParseTime',
         ]
         self.verify_keys(debug_stats, '"debug_stats"', debug_stat_keys, None)
def test_default_with_run(self):
         }
 
         """
         target = self.createTestTarget()
         lldbutil.run_to_source_breakpoint(self, "// break here",
                                           lldb.SBFileSpec("main.c"))
         debug_stats = self.get_stats()
         debug_stat_keys = [
-            'modules', 
+            'modules',
             'targets',
             'totalSymbolTableParseTime',
             'totalSymbolTableIndexTime',
             'totalDebugInfoByteSize',
             'totalDebugInfoIndexTime',
             'totalDebugInfoParseTime',
         ]
         self.verify_keys(debug_stats, '"debug_stats"', debug_stat_keys, None)
class TestCase(TestBase):
     def test_modules(self):
         """
             Test "statistics dump" and the module information.
         """
         exe = self.getBuildArtifact("a.out")
         target = self.createTestTarget(file_path=exe)
         debug_stats = self.get_stats()
         debug_stat_keys = [
-            'modules', 
+            'modules',
             'targets',
             'totalSymbolTableParseTime',
             'totalSymbolTableIndexTime',
             'totalDebugInfoParseTime',
             'totalDebugInfoIndexTime',
             'totalDebugInfoByteSize'
         ]
         self.verify_keys(debug_stats, '"debug_stats"', debug_stat_keys, None)
def test_breakpoints(self):
                             "details": {...},
                             "id": 1,
                             "resolveTime": 2.65438675
                         },
                         {
                             "details": {...},
                             "id": 2,
                             "resolveTime": 4.3632581669999997
-                        }                        
+                        }
                     ]
                 }
             ],
             "totalDebugInfoByteSize": 182522234,
             "totalDebugInfoIndexTime": 2.33343,
             "totalDebugInfoParseTime": 8.2121400240000071,
             "totalSymbolTableParseTime": 0.123,
             "totalSymbolTableIndexTime": 0.234,
             "totalBreakpointResolveTime": 7.0176449170000001
         }
 
         """
         target = self.createTestTarget()
         self.runCmd("b main.cpp:7")
         self.runCmd("b a_function")
         debug_stats = self.get_stats()
         debug_stat_keys = [
-            'modules', 
+            'modules',
             'targets',
             'totalSymbolTableParseTime',
             'totalSymbolTableIndexTime',
             'totalDebugInfoParseTime',
             'totalDebugInfoIndexTime',
             'totalDebugInfoByteSize',
         ]
         self.verify_keys(debug_stats, '"debug_stats"', debug_stat_keys, None)
def test_breakpoints(self):
             'details',
             'id',
             'internal',
             'numLocations',
             'numResolvedLocations',
             'resolveTime'
         ]
         for breakpoint in breakpoints:
-            self.verify_keys(breakpoint, 'target_stats["breakpoints"]', 
+            self.verify_keys(breakpoint, 'target_stats["breakpoints"]',
                              bp_keys_exist, None)