Record duration of calls to external programs at debug level

The old profiling report was removed in favour of using external
profilers like cProfile. This is useful for overall profiling and
identifying code hotspots but is less helpful for drilling down
to the collection of individual items.

Since running programs is the dominant cost on typical hosts log
the time taken to run each call and tag it with the binary name.

This allows looking at the per-call and per-command cost across a
run of sosreport.

Signed-off-by: Bryn M. Reeves <bmr@redhat.com>

1 files changed, 2 insertions, 0 deletions

diff --git a/sos/plugins/__init__.py b/sos/plugins/__init__.py
index 7eff4e65..7758fa99 100644
--- a/sos/plugins/__init__.py
+++ b/sos/plugins/__init__.py
@@ -525,10 +525,12 @@ class Plugin(object):
         """Execute a command and save the output to a file for inclusion in the
         report.
         """
+        start = time()
         # pylint: disable-msg = W0612
         result = self.get_command_output(exe, timeout=timeout, runat=runat)
         if (result['status'] == 127):
             return None
+        self.log_debug("collected output of '%s' in %s" % (exe.split()[0], time() - start))
 
         if suggest_filename:
             outfn = self.make_command_filename(suggest_filename)