Add timing to the verbose logs of abidw
authorDodji Seketeli <dodji@redhat.com>
Fri, 19 Jul 2019 08:14:40 +0000 (10:14 +0200)
committerDodji Seketeli <dodji@redhat.com>
Fri, 19 Jul 2019 08:46:42 +0000 (10:46 +0200)
While doing my recent optimization work, it became useful to have an
idea of the time different parts of the processing pipeline are
taking.

This patch introduces an abigail::tools_utils::timer type that is easy
to use to time a given part of the code and emit the elapsed time to
an output stream.

This abigail::tools_utils::timer type is thus used to time various
parts of the processing pipeline involved in abidw.  Just using the
existing --verbose option now yields timing information.

* include/abg-tools-utils.h (class timer): Declare new type.
(operator<<(ostream&, const timer&)): Declare new streaming
operator for the new timer type.
* src/abg-tools-utils.cc (struct timer::priv): Define new type.
(timer::{timer, start, stop, value_in_seconds, value,
value_as_string, ~timer}): Define member functions.
(operator<<(ostream& o, const timer& t)): Define streaming
operator.
(build_corpus_group_from_kernel_dist_under): Add timing logs to
the linux kernel reading process.
* src/abg-dwarf-reader.cc
(read_context::canonicalize_types_scheduled): Add timing logs to
type canonicalization.
(read_debug_info_into_corpus): Add timing logs for the whole debug
info loading and internal representation building process.
* tools/abidw.cc (load_corpus_and_write_abixml): Add timing logs
for the binary loading and serizalization process.
(load_kernel_corpus_group_and_write_abixml): Add timing logs the
Linux Kernel binary loading and writing process.

Signed-off-by: Dodji Seketeli <dodji@redhat.com>
include/abg-tools-utils.h
src/abg-dwarf-reader.cc
src/abg-tools-utils.cc
tools/abidw.cc

index 4d35d53a15603bf111d0da4f6bac72d5be73b10d..a153af689740236ad444778c46f3ea9cc5b6f473 100644 (file)
@@ -254,6 +254,37 @@ abidiff_status_has_abi_change(abidiff_status s);
 bool
 abidiff_status_has_incompatible_abi_change(abidiff_status s);
 
+/// A type used to time various part of the libabigail system.
+class timer
+{
+  struct priv;
+  typedef shared_ptr<priv> priv_sptr;
+
+  priv_sptr priv_;
+
+public:
+  enum kind
+  {
+    /// Default timer kind.
+    DEFAULT_TIMER_KIND = 0,
+    /// This kind of timer starts upon instantiation.
+    START_ON_INSTANTIATION_TIMER_KIND = 1,
+  };
+
+  timer (kind k = DEFAULT_TIMER_KIND);
+  bool start();
+  bool stop();
+  time_t value_in_seconds() const;
+  bool value(time_t& hours,
+            time_t& minutes,
+            time_t& seconds,
+            time_t& milliseconds) const;
+  string value_as_string() const;
+  ~timer();
+}; //end class timer
+
+ostream& operator<<(ostream&, const timer&);
+
 ostream&
 operator<<(ostream& output, file_type r);
 
index f64ab9bdfd701262f8b736bb5a7d0df5a8963c12..47af7e3516d33ead549d0a6fb7f024e1ec534242 100644 (file)
@@ -5588,6 +5588,7 @@ public:
   void
   canonicalize_types_scheduled(die_source source)
   {
+    tools_utils::timer cn_timer;
     if (do_log())
       {
        cerr << "going to canonicalize types";
@@ -5595,10 +5596,12 @@ public:
        if (c)
          cerr << " of corpus " << current_corpus()->get_path();
        cerr << " (DIEs source: " << source << ")\n";
+       cn_timer.start();
       }
 
     if (!types_to_canonicalize(source).empty())
       {
+       tools_utils::timer single_type_cn_timer;
        size_t total = types_to_canonicalize(source).size();
        if (do_log())
          cerr << total << " types to canonicalize\n";
@@ -5616,16 +5619,22 @@ public:
                if (corpus_sptr c = current_corpus())
                  cerr << "@" << c->get_path();
                cerr << " ...";
+               single_type_cn_timer.start();
              }
            canonicalize(t);
            if (do_log())
-             cerr << " DONE\n";
+             {
+               cerr << " DONE";
+               single_type_cn_timer.stop();
+               cerr << ":" <<single_type_cn_timer << "\n";
+             }
          }
 
        // Now canonicalize types that were created but not tied to
        // any DIE.
        if (!extra_types_to_canonicalize().empty())
          {
+           tools_utils::timer single_type_cn_timer;
            size_t total = extra_types_to_canonicalize().size();
            if (do_log())
              cerr << total << " extra types to canonicalize\n";
@@ -5643,14 +5652,32 @@ public:
                    if (corpus_sptr c = current_corpus())
                      cerr << "@" << c->get_path();
                    cerr << " ...";
+                   single_type_cn_timer.start();
                  }
                canonicalize(*it);
+               if (do_log())
+                 {
+                   single_type_cn_timer.stop();
+                   cerr << "DONE:"
+                        << single_type_cn_timer
+                        << "\n";
+                 }
              }
          }
       }
+
     if (do_log())
-      cerr << "finished canonicalizing types.  (source: "
-          << source << ")\n";
+      {
+       cn_timer.stop();
+       cerr << "finished canonicalizing types";
+       corpus_sptr c = current_corpus();
+       if (c)
+         cerr << " of corpus " << current_corpus()->get_path();
+       cerr << " (DIEs source: "
+            << source << "):"
+            << cn_timer
+            << "\n";
+      }
   }
 
   /// Compute the number of canonicalized and missed types in the late
@@ -16449,57 +16476,105 @@ read_debug_info_into_corpus(read_context& ctxt)
 
   // Walk all the DIEs of the debug info to build a DIE -> parent map
   // useful for get_die_parent() to work.
-  if (ctxt.do_log())
-    cerr << "building die -> parent maps ...";
+  {
+    tools_utils::timer t;
+    if (ctxt.do_log())
+      {
+       cerr << "building die -> parent maps ...";
+       t.start();
+      }
 
-  ctxt.build_die_parent_maps();
+    ctxt.build_die_parent_maps();
 
-  if (ctxt.do_log())
-    cerr << " DONE@" << ctxt.current_corpus()->get_path() << "\n";
+    if (ctxt.do_log())
+      {
+       t.stop();
+       cerr << " DONE@" << ctxt.current_corpus()->get_path()
+            << ":"
+            << t
+            << "\n";
+      }
+  }
 
   ctxt.env()->canonicalization_is_done(false);
 
-  if (ctxt.do_log())
-    cerr << "building the libabigail internal representation ...";
-  // And now walk all the DIEs again to build the libabigail IR.
-  Dwarf_Half dwarf_version = 0;
-  for (Dwarf_Off offset = 0, next_offset = 0;
-       (dwarf_next_unit(ctxt.dwarf(), offset, &next_offset, &header_size,
-                       &dwarf_version, NULL, &address_size, NULL,
-                       NULL, NULL) == 0);
-       offset = next_offset)
-    {
-      Dwarf_Off die_offset = offset + header_size;
-      Dwarf_Die unit;
-      if (!dwarf_offdie(ctxt.dwarf(), die_offset, &unit)
-         || dwarf_tag(&unit) != DW_TAG_compile_unit)
-       continue;
+  {
+    tools_utils::timer t;
+    if (ctxt.do_log())
+      {
+       cerr << "building the libabigail internal representation ...";
+       t.start();
+      }
+    // And now walk all the DIEs again to build the libabigail IR.
+    Dwarf_Half dwarf_version = 0;
+    for (Dwarf_Off offset = 0, next_offset = 0;
+        (dwarf_next_unit(ctxt.dwarf(), offset, &next_offset, &header_size,
+                         &dwarf_version, NULL, &address_size, NULL,
+                         NULL, NULL) == 0);
+        offset = next_offset)
+      {
+       Dwarf_Off die_offset = offset + header_size;
+       Dwarf_Die unit;
+       if (!dwarf_offdie(ctxt.dwarf(), die_offset, &unit)
+           || dwarf_tag(&unit) != DW_TAG_compile_unit)
+         continue;
 
-      ctxt.dwarf_version(dwarf_version);
+       ctxt.dwarf_version(dwarf_version);
 
-      address_size *= 8;
+       address_size *= 8;
 
-      // Build a translation_unit IR node from cu; note that cu must
-      // be a DW_TAG_compile_unit die.
-      translation_unit_sptr ir_node =
-       build_translation_unit_and_add_to_ir(ctxt, &unit, address_size);
-      ABG_ASSERT(ir_node);
-    }
-  if (ctxt.do_log())
-    cerr << " DONE@" << ctxt.current_corpus()->get_path() << "\n";
-
-  if (ctxt.do_log())
-    cerr << "resolving declaration only classes ...";
-  ctxt.resolve_declaration_only_classes();
-  if (ctxt.do_log())
-    cerr << " DONE@" << ctxt.current_corpus()->get_path() <<"\n";
-
-  if (ctxt.do_log())
-    cerr << "fixing up functions with linkage name but "
-        << "no advertised underlying symbols ....";
-  ctxt.fixup_functions_with_no_symbols();
-  if (ctxt.do_log())
-    cerr << " DONE@" << ctxt.current_corpus()->get_path() <<"\n";
+       // Build a translation_unit IR node from cu; note that cu must
+       // be a DW_TAG_compile_unit die.
+       translation_unit_sptr ir_node =
+         build_translation_unit_and_add_to_ir(ctxt, &unit, address_size);
+       ABG_ASSERT(ir_node);
+      }
+    if (ctxt.do_log())
+      {
+       t.stop();
+       cerr << " DONE@" << ctxt.current_corpus()->get_path()
+            << ":"
+            << t
+            << "\n";
+      }
+  }
+
+  {
+    tools_utils::timer t;
+    if (ctxt.do_log())
+      {
+       cerr << "resolving declaration only classes ...";
+       t.start();
+      }
+    ctxt.resolve_declaration_only_classes();
+    if (ctxt.do_log())
+      {
+       t.stop();
+       cerr << " DONE@" << ctxt.current_corpus()->get_path()
+            << ":"
+            << t
+            <<"\n";
+      }
+  }
+
+  {
+    tools_utils::timer t;
+    if (ctxt.do_log())
+      {
+       cerr << "fixing up functions with linkage name but "
+            << "no advertised underlying symbols ....";
+       t.start();
+      }
+    ctxt.fixup_functions_with_no_symbols();
+    if (ctxt.do_log())
+      {
+       t.stop();
+       cerr << " DONE@" << ctxt.current_corpus()->get_path()
+            <<":"
+            << t
+            <<"\n";
+      }
+  }
 
   /// Now, look at the types that needs to be canonicalized after the
   /// translation has been constructed (which is just now) and
@@ -16512,22 +16587,46 @@ read_debug_info_into_corpus(read_context& ctxt)
   /// even for some static data members.  We need to do that for types
   /// are in the alternate debug info section and for types that in
   /// the main debug info section.
-  if (ctxt.do_log())
-    cerr << "perform late type canonicalizing ...\n";
-  ctxt.perform_late_type_canonicalizing();
-  if (ctxt.do_log())
-    cerr << "late type canonicalizing DONE@"
-        << ctxt.current_corpus()->get_path()
-        << "\n";
+  {
+    tools_utils::timer t;
+    if (ctxt.do_log())
+      {
+       cerr << "perform late type canonicalizing ...\n";
+       t.start();
+      }
+
+    ctxt.perform_late_type_canonicalizing();
+    if (ctxt.do_log())
+      {
+       t.stop();
+       cerr << "late type canonicalizing DONE@"
+            << ctxt.current_corpus()->get_path()
+            << ":"
+            << t
+            << "\n";
+      }
+  }
 
   ctxt.env()->canonicalization_is_done(true);
 
-  if (ctxt.do_log())
-    cerr << "sort functions and variables ...";
-  ctxt.current_corpus()->sort_functions();
-  ctxt.current_corpus()->sort_variables();
-  if (ctxt.do_log())
-    cerr << " DONE@" << ctxt.current_corpus()->get_path() <<" \n";
+  {
+    tools_utils::timer t;
+    if (ctxt.do_log())
+      {
+       cerr << "sort functions and variables ...";
+       t.start();
+      }
+    ctxt.current_corpus()->sort_functions();
+    ctxt.current_corpus()->sort_variables();
+    if (ctxt.do_log())
+      {
+       t.stop();
+       cerr << " DONE@" << ctxt.current_corpus()->get_path()
+            << ":"
+            << t
+            <<" \n";
+      }
+  }
 
   return ctxt.current_corpus();
 }
index 9300bebe7446b1ba8cdf3780381f755192930677..f7349ec82b7e10aa1bc5876515ae0522c28c2861 100644 (file)
@@ -35,6 +35,7 @@
 #include <unistd.h>
 #include <sys/types.h>
 #include <sys/stat.h>
+#include <sys/time.h>
 #include <dirent.h>
 #include <time.h>
 #include <cstdlib>
@@ -187,6 +188,154 @@ abidiff_status_has_incompatible_abi_change(abidiff_status s)
   struct stat st; \
   memset(&st, 0, sizeof(st))
 
+// <class timer stuff>
+
+/// The private data type of the @ref timer class.
+struct timer::priv
+{
+  timer::kind timer_kind;
+  struct timeval begin_timeval;
+  struct timeval end_timeval;
+
+  priv(timer::kind k)
+    : timer_kind(k),
+      begin_timeval(),
+      end_timeval()
+  {}
+}; // end struct timer::priv
+
+/// Constructor of the @ref timer type.
+///
+/// @param k the kind of timer to instantiate.
+timer::timer(timer::kind k)
+  : priv_(new timer::priv(k))
+{
+  if (priv_->timer_kind == START_ON_INSTANTIATION_TIMER_KIND)
+    start();
+}
+
+/// Start the timer.
+///
+/// To stop the timer (and record the time elapsed since the timer was
+/// started), call the timer::stop member function.
+///
+/// @return true upon successful completion.
+bool
+timer::start()
+{
+  if (gettimeofday(&priv_->begin_timeval, 0))
+    return false;
+  return true;
+}
+
+/// Stop the timer.
+///
+/// This records the time elapsed since the timer was started using
+/// the timer::start member function.
+///
+/// @return true upon successful completion.
+bool
+timer::stop()
+{
+  if (gettimeofday(&priv_->end_timeval, 0))
+    return false;
+  return true;
+}
+
+/// Get the elapsed time in seconds.
+///
+/// @return the time elapsed between the invocation of the methods
+/// timer::start() and timer::stop, in seconds.
+time_t
+timer::value_in_seconds() const
+{return priv_->end_timeval.tv_sec - priv_->begin_timeval.tv_sec;}
+
+/// Get the elapsed time in hour:minutes:seconds:milliseconds.
+///
+/// @param hours out parameter. This is set to the number of hours elapsed.
+///
+/// @param minutes out parameter.  This is set to the number of minutes
+/// (passed the number of hours) elapsed.
+///
+/// @param seconds out parameter.  This is se to the number of
+/// seconds (passed the number of hours and minutes) elapsed.
+///
+/// @param milliseconds.  This is set ot the number of milliseconds
+/// (passed the number of hours, minutes and seconds) elapsed.
+///
+/// @return true upon successful completion.
+bool
+timer::value(time_t&           hours,
+            time_t&            minutes,
+            time_t&            seconds,
+            time_t&    milliseconds) const
+{
+  time_t elapsed_seconds =
+    priv_->end_timeval.tv_sec - priv_->begin_timeval.tv_sec;
+  suseconds_t elapsed_usecs =
+    ((priv_->end_timeval.tv_sec * 1000000) + priv_->end_timeval.tv_usec)
+    - ((priv_->begin_timeval.tv_sec * 1000000) + priv_->begin_timeval.tv_usec);
+
+  milliseconds = 0;
+
+  hours = elapsed_seconds / 3600;
+  minutes = (elapsed_seconds % 3600) / 60;
+  seconds = (elapsed_seconds % 3600) % 60;
+  if (elapsed_seconds == 0)
+    milliseconds = elapsed_usecs / 1000;
+
+  return true;
+}
+
+/// Get the elapsed time as a human-readable string.
+///
+/// @return the elapsed time as a human-readable string.
+string
+timer::value_as_string() const
+{
+  time_t hours = 0, minutes = 0, seconds = 0;
+  time_t msecs = 0;
+
+  value(hours, minutes, seconds, msecs);
+
+  std::ostringstream o;
+
+  if (hours)
+    o << hours << "h";
+
+  if (minutes)
+    o << minutes << "m";
+
+  o << seconds << "s";
+
+  if (msecs)
+    o <<msecs <<"ms";
+
+  return o.str();
+}
+
+/// Destructor of the @ref timer type.
+timer::~timer()
+{
+}
+
+/// Streaming operator for the @ref timer type.
+///
+/// Emit a string representing the elapsed time (in a human-readable
+/// manner) to an output stream.
+///
+/// @param o the output stream to emit the elapsed time string to.
+///
+/// @param t the timer to consider.
+///
+/// @return the output stream considered.
+ostream&
+operator<<(ostream& o, const timer& t)
+{
+  o << t.value_as_string();
+  return o;
+}
+
 /// Get the stat struct (as returned by the lstat() function of the C
 /// library) of a file.  Note that the function uses lstat, so that
 /// callers can detect symbolic links.
@@ -2305,14 +2454,18 @@ build_corpus_group_from_kernel_dist_under(const string& root,
   vector<string> modules;
 
   if (verbose)
-    std::cout << "Analysing kernel dist root '"
+    std::cerr << "Analysing kernel dist root '"
              << root << "' ... " << std::flush;
 
+  timer t;
+
+  t.start();
   bool got_binary_paths =
     get_binary_paths_from_kernel_dist(root, debug_info_root, vmlinux, modules);
+  t.stop();
 
   if (verbose)
-    std::cout << "DONE\n";
+    std::cerr << "DONE: " << t << "\n";
 
   dwarf_reader::read_context_sptr ctxt;
   if (got_binary_paths)
@@ -2330,9 +2483,17 @@ build_corpus_group_from_kernel_dist_under(const string&  root,
            dwarf_reader::create_read_context(vmlinux, di_roots ,env.get(),
                                              /*read_all_types=*/false,
                                              /*linux_kernel_mode=*/true);
+         dwarf_reader::set_do_log(*ctxt, verbose);
 
+         t.start();
          load_generate_apply_suppressions(*ctxt, suppr_paths,
                                           kabi_wl_paths, supprs);
+         t.stop();
+
+         if (verbose)
+           std::cerr << "loaded white list and generated suppr spec in: "
+                     << t
+                     << "\n";
 
          // If we have been given a whitelist of functions and
          // variable symbols to look at, then we can avoid loading
@@ -2345,14 +2506,18 @@ build_corpus_group_from_kernel_dist_under(const string& root,
          set_read_context_corpus_group(*ctxt, group);
 
          if (verbose)
-           std::cout << "reading kernel binary '"
-                     << vmlinux << "' ... " << std::flush;
+           std::cerr << "reading kernel binary '"
+                     << vmlinux << "' ...\n" << std::flush;
 
          // Read the vmlinux corpus and add it to the group.
+         t.start();
          read_and_add_corpus_to_group_from_elf(*ctxt, *group, status);
+         t.stop();
 
-           if (verbose)
-             std::cout << " DONE\n";
+         if (verbose)
+           std::cerr << vmlinux
+                     << " reading DONE:"
+                     << t << "\n";
        }
 
       if (!group->is_empty())
@@ -2365,7 +2530,7 @@ build_corpus_group_from_kernel_dist_under(const string&   root,
               ++m, ++cur_module_index)
            {
              if (verbose)
-               std::cout << "reading module '"
+               std::cerr << "reading module '"
                          << *m << "' ("
                          << cur_module_index
                          << "/" << total_nb_modules
@@ -2387,10 +2552,15 @@ build_corpus_group_from_kernel_dist_under(const string& root,
 
              set_read_context_corpus_group(*ctxt, group);
 
+             t.start();
              read_and_add_corpus_to_group_from_elf(*ctxt,
                                                    *group, status);
+             t.stop();
              if (verbose)
-               std::cout << " DONE\n";
+               std::cerr << "module '"
+                         << *m
+                         << "' reading DONE: "
+                         << t << "\n";
            }
 
          result = group;
index 111ceb2278a0165557bbb033a0106dd159b10749..d520fc3d03a5e14fc9ca966095d13384b8801fb1 100644 (file)
@@ -56,6 +56,7 @@ using abigail::tools_utils::temp_file;
 using abigail::tools_utils::temp_file_sptr;
 using abigail::tools_utils::check_file;
 using abigail::tools_utils::build_corpus_group_from_kernel_dist_under;
+using abigail::tools_utils::timer;
 using abigail::ir::environment_sptr;
 using abigail::ir::environment;
 using abigail::corpus;
@@ -405,12 +406,26 @@ load_corpus_and_write_abixml(char* argv[],
                             const options& opts)
 {
   int exit_code = 0;
+  timer t;
 
   read_context& ctxt = *context;
   corpus_sptr corp;
   dwarf_reader::status s = dwarf_reader::STATUS_UNKNOWN;
+  t.start();
   corp = read_corpus_from_elf(ctxt, s);
+  t.stop();
+  if (opts.do_log)
+    emit_prefix(argv[0], cerr)
+      << "read corpus from elf file in: " << t << "\n";
+
+  t.start();
   context.reset();
+  t.stop();
+
+  if (opts.do_log)
+    emit_prefix(argv[0], cerr)
+      << "reset read context in: " << t << "\n";
+
   if (!corp)
     {
       if (s == dwarf_reader::STATUS_DEBUG_INFO_NOT_FOUND)
@@ -452,9 +467,16 @@ load_corpus_and_write_abixml(char* argv[],
     }
   else
     {
+      t.start();
       const write_context_sptr& write_ctxt
          = create_write_context(corp->get_environment(), cout);
       set_common_options(*write_ctxt, opts);
+      t.stop();
+
+      if (opts.do_log)
+       emit_prefix(argv[0], cerr)
+         << "created & initialized write context in: "
+         << t << "\n";
 
       if (opts.abidiff)
        {
@@ -465,9 +487,15 @@ load_corpus_and_write_abixml(char* argv[],
          set_ostream(*write_ctxt, tmp_file->get_stream());
          write_corpus(*write_ctxt, corp, 0);
          tmp_file->get_stream().flush();
+         t.start();
          corpus_sptr corp2 =
            read_corpus_from_native_xml_file(tmp_file->get_path(),
                                             env.get());
+         t.stop();
+         if (opts.do_log)
+           emit_prefix(argv[0], cerr)
+             << "Read corpus in: " << t << "\n";
+
          if (!corp2)
            {
              emit_prefix(argv[0], cerr)
@@ -475,14 +503,26 @@ load_corpus_and_write_abixml(char* argv[],
                "elf file back\n";
              return 1;
            }
+
          diff_context_sptr ctxt(new diff_context);
          set_diff_context(ctxt);
          ctxt->show_locs(opts.show_locs);
+         t.start();
          corpus_diff_sptr diff = compute_diff(corp, corp2, ctxt);
+         t.stop();
+         if (opts.do_log)
+           emit_prefix(argv[0], cerr)
+             << "computed diff in: " << t << "\n";
+
          bool has_error = diff->has_incompatible_changes();
          if (has_error)
            {
+             t.start();
              diff->report(cerr);
+             t.stop();
+             if (opts.do_log)
+               emit_prefix(argv[0], cerr)
+                 << "emitted report in: " << t << "\n";
              return 1;
            }
          return 0;
@@ -502,13 +542,23 @@ load_corpus_and_write_abixml(char* argv[],
              return 1;
            }
          set_ostream(*write_ctxt, of);
+         t.start();
          write_corpus(*write_ctxt, corp, 0);
+         t.stop();
+         if (opts.do_log)
+           emit_prefix(argv[0], cerr)
+             << "emitted abixml output in: " << t << "\n";
          of.close();
          return 0;
        }
       else
        {
+         t.start();
          exit_code = !write_corpus(*write_ctxt, corp, 0);
+         t.stop();
+         if (opts.do_log)
+           emit_prefix(argv[0], cerr)
+             << "emitted abixml out in: " << t << "\n";
        }
     }
 
@@ -541,7 +591,15 @@ load_kernel_corpus_group_and_write_abixml(char* argv[],
     if (!abigail::tools_utils::check_file(opts.vmlinux, cerr, argv[0]))
       return 1;
 
+  timer t, global_timer;
   suppressions_type supprs;
+
+  if (opts.do_log)
+    emit_prefix(argv[0], cerr)
+      << "going to build ABI representation of the Linux Kernel ...\n";
+
+  global_timer.start();
+  t.start();
   corpus_group_sptr group =
     build_corpus_group_from_kernel_dist_under(opts.in_file_path,
                                              /*debug_info_root=*/"",
@@ -549,6 +607,14 @@ load_kernel_corpus_group_and_write_abixml(char* argv[],
                                              opts.suppression_paths,
                                              opts.kabi_whitelist_paths,
                                              supprs, opts.do_log, env);
+  t.stop();
+
+  if (opts.do_log)
+    {
+      emit_prefix(argv[0], cerr)
+       << "built ABI representation of the Linux Kernel in: "
+       << t << "\n";
+    }
 
   if (!group)
     return 1;
@@ -569,15 +635,36 @@ load_kernel_corpus_group_and_write_abixml(char* argv[],
                << opts.out_file_path << "'\n";
              return 1;
            }
+
+         if (opts.do_log)
+           emit_prefix(argv[0], cerr)
+             << "emitting the abixml output ...\n";
          set_ostream(*ctxt, of);
+         t.start();
          exit_code = !write_corpus_group(*ctxt, group, 0);
+         t.stop();
+         if (opts.do_log)
+           emit_prefix(argv[0], cerr)
+             << "emitted abixml output in: " << t << "\n";
        }
       else
        {
+         if (opts.do_log)
+           emit_prefix(argv[0], cerr)
+             << "emitting the abixml output ...\n";
+         t.start();
          exit_code = !write_corpus_group(*ctxt, group, 0);
+         t.stop();
+         if (opts.do_log)
+           emit_prefix(argv[0], cerr)
+             << "emitted abixml output in: " << t << "\n";
        }
     }
 
+  global_timer.stop();
+  if (opts.do_log)
+    emit_prefix(argv[0], cerr)
+      << "total processing done in " << global_timer << "\n";
   return exit_code;
 }