abidiff: Add extensive logging

While looking at something else I felt the need for having
"abidiff --verbose" emit more timing information.  I have thus added
a lot more logging around.

	* include/abg-comparison.h ({diff, corpus_diff,
	diff_context}::do_log): Declare member functions.
	* include/abg-corpus.h (corpus::do_log): Likewise.
	* src/abg-comparison-priv.h (diff_context::priv::do_log_): Add new
	data member.
	(diff_context::priv::priv): Initialize the new data member.
	* src/abg-comparison.cc ({diff, corpus_diff,
	diff_context}::do_log): Define member functions.
	(diff_context::maybe_apply_filters): Add timing logs to applying
	filters and propagating categories.
	(corpus_diff::priv::apply_filters_and_compute_diff_stats): Add
	timing logs to applying and propagating filters to changed
	functions, variables, unreachable & leaf type changes,
	suppressions application.
	* src/abg-corpus-priv.h (corpus::priv::do_log): Add new data
	member.
	(corpus::priv::priv): Initialize it.
	* src/abg-corpus.cc (corpus::do_log): Define member functions.
	* src/abg-reader.cc (reader::do_log): Likewise.
	(reader::read_corpus): Add timing log around the invocation of
	perform_late_type_canonicalizing.
	* tools/abidiff.cc (set_diff_context_from_opts): Set logging.
	(main): Add timing logging for diff computing, changes analysis &
	report generation.

Signed-off-by: Dodji Seketeli <dodji@redhat.com>

include/abg-comparison.h

@@ -649,6 +649,12 @@ public:
 
   ~diff_context();
 
+  bool
+  do_log() const;
+
+  void
+  do_log(bool);
+
   void
   set_corpus_diff(const corpus_diff_sptr&);
 
@@ -966,6 +972,12 @@ protected:
        type_or_decl_base_sptr	second_subject,
        diff_context_sptr	ctxt);
 
+  bool
+  do_log() const;
+
+  void
+  do_log(bool);
+
   void
   begin_traversing();
 
@@ -2337,6 +2349,12 @@ public:
   /// A convenience typedef for a shared pointer to @ref diff_stats
   typedef shared_ptr<diff_stats> diff_stats_sptr;
 
+  bool
+  do_log() const;
+
+  void
+  do_log(bool);
+
   corpus_sptr
   first_corpus() const;
 

include/abg-corpus.h

@@ -69,6 +69,12 @@ public:
   const environment&
   get_environment() const;
 
+  bool
+  do_log() const;
+
+  void
+  do_log(bool);
+
   void
   add(const translation_unit_sptr&);
 

src/abg-comparison-priv.h

@@ -212,6 +212,7 @@ struct diff_context::priv
   bool					show_unreachable_types_;
   bool					show_impacted_interfaces_;
   bool					dump_diff_tree_;
+  bool					do_log_;
 
   priv()
     : allowed_category_(EVERYTHING_CATEGORY),
@@ -240,7 +241,8 @@ struct diff_context::priv
       show_added_syms_unreferenced_by_di_(true),
       show_unreachable_types_(false),
       show_impacted_interfaces_(true),
-      dump_diff_tree_()
+      dump_diff_tree_(),
+      do_log_()
    {}
 };// end struct diff_context::priv
 

src/abg-comparison.cc

@@ -17,6 +17,7 @@
 
 #include "abg-comparison-priv.h"
 #include "abg-reporter-priv.h"
+#include "abg-tools-utils.h"
 
 namespace abigail
 {
@@ -916,6 +917,20 @@ diff_context::diff_context()
 
 diff_context::~diff_context() = default;
 
+/// Test if logging was requested.
+///
+/// @return true iff logging was requested.
+bool
+diff_context::do_log() const
+{return priv_->do_log_;}
+
+/// Set logging as requested.
+///
+/// @param f the flag
+void
+diff_context::do_log(bool f)
+{priv_->do_log_ = f;}
+
 /// Set the corpus diff relevant to this context.
 ///
 /// @param d the corpus_diff we are interested in.
@@ -1365,8 +1380,33 @@ diff_context::maybe_apply_filters(diff_sptr diff)
        i != diff_filters().end();
        ++i)
     {
+      tools_utils::timer t;
+      if (do_log())
+	{
+	  std::cerr << "applying a filter to diff '"
+		    << diff->get_pretty_representation()
+		    << "'...\n";
+	  t.start();
+	}
+
       filtering::apply_filter(*i, diff);
+
+      if (do_log())
+	{
+	  t.stop();
+	  std::cerr << "filter applied!:" << t << "\n";
+
+	  std::cerr << "propagating categories for the same diff node ... \n";
+	  t.start();
+	}
+
       propagate_categories(diff);
+
+      if (do_log())
+	{
+	  t.stop();
+	  std::cerr << "category propagated!: " << t << "\n";
+	}
     }
 
  }
@@ -1926,6 +1966,20 @@ diff::diff(type_or_decl_base_sptr	first_subject,
 		   /*currently_reporting=*/false))
 {}
 
+/// Test if logging was requested
+///
+/// @return true iff logging was requested.
+bool
+diff::do_log() const
+{return context()->do_log();}
+
+/// Request logging (or not)
+///
+/// @param f true iff logging is to be requested.
+void
+diff::do_log(bool f)
+{context()->do_log(f);}
+
 /// Flag a given diff node as being traversed.
 ///
 /// For certain diff nodes like @ref class_diff, it's important to
@@ -9934,6 +9988,15 @@ corpus_diff::priv::apply_filters_and_compute_diff_stats(diff_stats& stat)
 
   diff_context_sptr ctxt = get_context();
 
+  tools_utils::timer t;
+  if (get_context()->do_log())
+    {
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "applying filters to "
+		<< changed_fns_.size()
+		<< " changed fns ...\n";
+      t.start();
+    }
   // Walk the changed function diff nodes to apply the categorization
   // filters.
   diff_sptr diff;
@@ -9946,6 +10009,19 @@ corpus_diff::priv::apply_filters_and_compute_diff_stats(diff_stats& stat)
       ctxt->maybe_apply_filters(diff);
     }
 
+  if (get_context()->do_log())
+    {
+      t.stop();
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "filters to changed fn applied!:" << t << "\n";
+
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "applying filters to "
+		<< sorted_changed_vars_.size()
+		<< " changed vars ...\n";
+      t.start();
+    }
+
   // Walk the changed variable diff nodes to apply the categorization
   // filters.
   for (var_diff_sptrs_type::const_iterator i = sorted_changed_vars_.begin();
@@ -9956,6 +10032,17 @@ corpus_diff::priv::apply_filters_and_compute_diff_stats(diff_stats& stat)
       ctxt->maybe_apply_filters(diff);
     }
 
+  if (get_context()->do_log())
+    {
+      t.stop();
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "filters to changed vars applied!:" << t << "\n";
+
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "applying filters to unreachable types ...\n";
+      t.start();
+    }
+
   // walk the changed unreachable types to apply categorization
   // filters
   for (diff_sptrs_type::const_iterator i =
@@ -9967,8 +10054,30 @@ corpus_diff::priv::apply_filters_and_compute_diff_stats(diff_stats& stat)
       ctxt->maybe_apply_filters(diff);
     }
 
+  if (get_context()->do_log())
+    {
+      t.stop();
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "filters to unreachable types applied!:" << t << "\n";
+
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "categorizing redundant changed sub nodes ...\n";
+      t.start();
+    }
+
   categorize_redundant_changed_sub_nodes();
 
+  if (get_context()->do_log())
+    {
+      t.stop();
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "redundant changed sub nodes categorized!:" << t << "\n";
+
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "count changed fns ...\n";
+      t.start();
+    }
+
   // Walk the changed function diff nodes to count the number of
   // filtered-out functions and the number of functions with virtual
   // offset changes.
@@ -9998,6 +10107,17 @@ corpus_diff::priv::apply_filters_and_compute_diff_stats(diff_stats& stat)
 	  (stat.num_leaf_func_changes() + 1);
     }
 
+  if (get_context()->do_log())
+    {
+      t.stop();
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "changed fn counted!:" << t << "\n";
+
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "count changed vars ...\n";
+      t.start();
+    }
+
   // Walk the changed variables diff nodes to count the number of
   // filtered-out variables.
   for (var_diff_sptrs_type ::const_iterator i = sorted_changed_vars_.begin();
@@ -10018,6 +10138,17 @@ corpus_diff::priv::apply_filters_and_compute_diff_stats(diff_stats& stat)
 	  (stat.num_leaf_var_changes() + 1);
     }
 
+  if (get_context()->do_log())
+    {
+      t.stop();
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "changed vars counted!:" << t << "\n";
+
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "count leaf changed types ...\n";
+      t.start();
+    }
+
   stat.num_func_syms_added(added_unrefed_fn_syms_.size());
   stat.num_added_func_syms_filtered_out(suppressed_added_unrefed_fn_syms_.size());
   stat.num_func_syms_removed(deleted_unrefed_fn_syms_.size());
@@ -10036,6 +10167,17 @@ corpus_diff::priv::apply_filters_and_compute_diff_stats(diff_stats& stat)
     stat.num_leaf_type_changes_filtered_out(num_type_filtered);
   }
 
+  if (get_context()->do_log())
+    {
+      t.stop();
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "changed leaf types counted!:" << t << "\n";
+
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "count leaf changed artefacts ...\n";
+      t.start();
+    }
+
   // Walk the general leaf artefacts diff nodes to count them
   {
     size_t num_changes = 0, num_filtered = 0;
@@ -10045,6 +10187,17 @@ corpus_diff::priv::apply_filters_and_compute_diff_stats(diff_stats& stat)
     stat.num_leaf_changes_filtered_out(num_filtered);
   }
 
+  if (get_context()->do_log())
+    {
+      t.stop();
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "changed leaf artefacts counted!:" << t << "\n";
+
+      std::cerr << "in apply_filters_and_compute_diff_stats:"
+		<< "count unreachable types ...\n";
+      t.start();
+    }
+
   // Walk the unreachable types to count them
   {
     size_t num_added_unreachable_types = 0,
@@ -10061,6 +10214,13 @@ corpus_diff::priv::apply_filters_and_compute_diff_stats(diff_stats& stat)
 			    num_deleted_unreachable_types_filtered,
 			    num_changed_unreachable_types_filtered);
 
+    if (get_context()->do_log())
+      {
+	t.stop();
+	std::cerr << "in apply_filters_and_compute_diff_stats:"
+		  << "unreachable types counted!:" << t << "\n";
+      }
+
     stat.num_added_unreachable_types(num_added_unreachable_types);
     stat.num_removed_unreachable_types(num_deleted_unreachable_types);
     stat.num_changed_unreachable_types(num_changed_unreachable_types);
@@ -10495,6 +10655,20 @@ corpus_diff::finish_diff_type()
   priv_->finished_ = true;
 }
 
+/// Test if logging was requested.
+///
+/// @return true iff logging was requested.
+bool
+corpus_diff::do_log() const
+{return context()->do_log();}
+
+/// Request logging, or not.
+///
+/// @param f true iff logging is requested.
+void
+corpus_diff::do_log(bool f)
+{context()->do_log(f);}
+
 /// @return the first corpus of the diff.
 corpus_sptr
 corpus_diff::first_corpus() const
@@ -10895,10 +11069,47 @@ corpus_diff::apply_filters_and_suppressions_before_reporting()
   if (priv_->diff_stats_)
     return *priv_->diff_stats_;
 
+  tools_utils::timer t;
+  if (do_log())
+    {
+      std::cerr << "Applying suppressions ...\n";
+      t.start();
+    }
+
   apply_suppressions(this);
+
+  if (do_log())
+    {
+      t.stop();
+      std::cerr << "suppressions applied!:" << t << "\n";
+    }
+
   priv_->diff_stats_.reset(new diff_stats(context()));
+
+  if (do_log())
+    {
+      std::cerr << "Marking leaf nodes ...\n";
+      t.start();
+    }
+
   mark_leaf_diff_nodes();
+
+  if (do_log())
+    {
+      t.stop();
+      std::cerr << "leaf nodes marked!:" << t << "\n";
+      std::cerr << "Applying filters and computing diff stats ...\n";
+      t.start();
+    }
+
   priv_->apply_filters_and_compute_diff_stats(*priv_->diff_stats_);
+
+  if (do_log())
+    {
+      t.stop();
+      std::cerr << "Filters applied and diff stats computed!: " << t << "\n";
+    }
+
   return *priv_->diff_stats_;
 }
 

src/abg-corpus-priv.h

@@ -701,6 +701,7 @@ struct corpus::priv
   type_maps					type_per_loc_map_;
   mutable vector<type_base_wptr>		types_not_reachable_from_pub_ifaces_;
   unordered_set<interned_string, hash_interned_string> *pub_type_pretty_reprs_;
+  bool 						do_log;
 
 private:
   priv();
@@ -723,7 +724,8 @@ public:
       group(),
       origin_(ARTIFICIAL_ORIGIN),
       path(p),
-      pub_type_pretty_reprs_()
+      pub_type_pretty_reprs_(),
+      do_log()
   {}
 
   type_maps&

src/abg-corpus.cc

@@ -633,6 +633,20 @@ const environment&
 corpus::get_environment() const
 {return priv_->env;}
 
+/// Test if logging was requested.
+///
+/// @return true iff logging was requested.
+bool
+corpus::do_log() const
+{return priv_->do_log;}
+
+/// Request logging, or not.
+///
+/// @param f true iff logging is requested.
+void
+corpus::do_log(bool f)
+{priv_->do_log = f;}
+
 /// Add a translation unit to the current ABI Corpus.
 ///
 /// Note that two translation units with the same path (as returned by

src/abg-reader.cc

@@ -165,6 +165,13 @@ public:
   {
   }
 
+  /// Test if logging was requested.
+  ///
+  /// @return true iff logging was requested.
+  bool
+  do_log() const
+  {return options().do_log;}
+
   /// Getter for the flag that tells us if we are tracking types that
   /// are not reachable from global functions and variables.
   ///
@@ -1233,8 +1240,23 @@ public:
       }
 
 
+    tools_utils::timer t;
+    if (do_log())
+      {
+	std::cerr << "perform late type canonicalization ...\n";
+	t.start();
+      }
+
     perform_late_type_canonicalizing();
 
+    if (do_log())
+      {
+	t.stop();
+	std::cerr << "late type canonicalization DONE@"
+		  << corpus()->get_path()
+		  << ":" << t << "\n";
+      }
+
     get_environment().canonicalization_is_done(true);
 
     if (call_reader_next)

tools/abidiff.cc

@@ -830,6 +830,8 @@ set_diff_context_from_opts(diff_context_sptr ctxt,
     }
 
   ctxt->dump_diff_tree(opts.dump_diff_tree);
+
+  ctxt->do_log(opts.do_log);
 }
 
 /// Set a bunch of tunable buttons on the ELF-based reader from the
@@ -934,7 +936,9 @@ set_native_xml_reader_options(abigail::fe_iface& rdr,
 			      const options& opts)
 {
   abixml::consider_types_not_reachable_from_public_interfaces(rdr,
-									      opts.show_all_types);
+							      opts.show_all_types);
+  rdr.options().do_log = opts.do_log;
+
 }
 
 /// Set the regex patterns describing the functions to drop from the
@@ -1409,9 +1413,38 @@ main(int argc, char* argv[])
 
       if (t1)
 	{
+	  tools_utils::timer t;
+	  if (opts.do_log)
+	    {
+	      t.start();
+	      std::cerr << "Compute diff ...\n";
+	    }
+
 	  translation_unit_diff_sptr diff = compute_diff(t1, t2, ctxt);
+
+	  if (opts.do_log)
+	    {
+	      t.stop();
+	      std::cerr << "diff computed!:" << t << "\n";
+	    }
+
 	  if (diff->has_changes())
-	    diff->report(cout);
+	    {
+	      tools_utils::timer t;
+	      if (opts.do_log)
+		{
+		  t.start();
+		  std::cerr << "Computing the report ...\n";
+		}
+
+	      diff->report(cout);
+
+	      if (opts.do_log)
+		{
+		  t.stop();
+		  std::cerr << "Report computed!:" << t << "\n";
+		}
+	    }
 	}
       else if (c1)
 	{
@@ -1436,16 +1469,81 @@ main(int argc, char* argv[])
 	  set_corpus_keep_drop_regex_patterns(opts, c1);
 	  set_corpus_keep_drop_regex_patterns(opts, c2);
 
+	  tools_utils::timer t;
+	  if (opts.do_log)
+	    {
+	      t.start();
+	      std::cerr << "Compute diff ...\n";
+	    }
+
 	  corpus_diff_sptr diff = compute_diff(c1, c2, ctxt);
 
+	  if (opts.do_log)
+	    {
+	      t.stop();
+	      std::cerr << "diff computed!:" << t << "\n";
+	    }
+
+	  if (opts.do_log)
+	    {
+	      t.start();
+	      std::cerr << "Computing net changes ...\n";
+	    }
+
 	  if (diff->has_net_changes())
-	    status = abigail::tools_utils::ABIDIFF_ABI_CHANGE;
+	    {
+	      if (opts.do_log)
+		{
+		  t.stop();
+		  std::cerr << "net changes computed!: "<< t << "\n";
+		}
+	      status = abigail::tools_utils::ABIDIFF_ABI_CHANGE;
+	    }
+
+	  if (opts.do_log)
+	    {
+	      t.start();
+	      std::cerr << "Computing incompatible changes ...\n";
+	    }
 
 	  if (diff->has_incompatible_changes())
-	    status |= abigail::tools_utils::ABIDIFF_ABI_INCOMPATIBLE_CHANGE;
+	    {
+	      if (opts.do_log)
+		{
+		  t.stop();
+		  std::cerr << "incompatible changes computed!: "<< t << "\n";
+		}
+	      status |= abigail::tools_utils::ABIDIFF_ABI_INCOMPATIBLE_CHANGE;
+	    }
+
+	  if (opts.do_log)
+	    {
+	      t.start();
+	      std::cerr << "Computing changes ...\n";
+	    }
 
 	  if (diff->has_changes())
-	    diff->report(cout);
+	    {
+	      if (opts.do_log)
+		{
+		  t.stop();
+		  std::cerr << "changes computed!: "<< t << "\n";
+		}
+
+	      if (opts.do_log)
+		{
+		  t.start();
+		  std::cerr << "Computing report ...\n";
+		}
+
+	      diff->report(cout);
+
+	      if (opts.do_log)
+		{
+		  t.stop();
+		  std::cerr << "Report computed!:" << t << "\n";
+		}
+	    }
 	}
       else if (g1)
 	{
@@ -1468,16 +1566,87 @@ main(int argc, char* argv[])
 	    }
 
 	  adjust_diff_context_for_kmidiff(*ctxt);
+	  tools_utils::timer t;
+	  if (opts.do_log)
+	    {
+	      t.start();
+	      std::cerr << "Compute diff ...\n";
+	    }
+
 	  corpus_diff_sptr diff = compute_diff(g1, g2, ctxt);
 
+	  if (opts.do_log)
+	    {
+	      t.stop();
+	      diff->do_log(true);
+	      std::cerr << "diff computed!:" << t << "\n";
+	    }
+
+	  if (opts.do_log)
+	    {
+	      std::cerr << "Computing net changes ...\n";
+	      t.start();
+	    }
+
 	  if (diff->has_net_changes())
 	    status = abigail::tools_utils::ABIDIFF_ABI_CHANGE;
+	  if (opts.do_log)
+	    {
+	      t.stop();
+	      std::cerr << "net changes computed!: "<< t << "\n";
+	    }
+
+	  if (opts.do_log)
+	    {
+	      t.start();
+	      std::cerr << "Computing incompatible changes ...\n";
+	    }
 
 	  if (diff->has_incompatible_changes())
 	    status |= abigail::tools_utils::ABIDIFF_ABI_INCOMPATIBLE_CHANGE;
 
+	  if (opts.do_log)
+	    {
+	      t.stop();
+	      std::cerr << "incompatible changes computed!: "<< t << "\n";
+	    }
+
+	  if (opts.do_log)
+	    {
+	      t.start();
+	      std::cerr << "Computing changes ...\n";
+	    }
+
 	  if (diff->has_changes())
-	    diff->report(cout);
+	    {
+	      if (opts.do_log)
+		{
+		  t.stop();
+		  std::cerr << "changes computed!: "<< t << "\n";
+		}
+
+	      if (opts.do_log)
+		{
+		  t.start();
+		  std::cerr << "Computing report ...\n";
+		}
+
+	      diff->report(cout);
+
+	      if (opts.do_log)
+		{
+		  t.stop();
+		  std::cerr << "Report computed!:" << t << "\n";
+		}
+	    }
+	  else
+	    {
+	      if (opts.do_log)
+		{
+		  t.stop();
+		  std::cerr << "changes computed!: "<< t << "\n";
+		}
+	    }
 
 	}
       else