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>

diff --git a/include/abg-comparison.h b/include/abg-comparison.h
index 839478bff2f684173ca900324921e5e47ba21ea8..506f2bb7d4fe52583e7131ccff6ad3b22923407e 100644 (file)
--- a/include/abg-comparison.h
+++ b/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;
 

diff --git a/include/abg-corpus.h b/include/abg-corpus.h
index fabda0f96b5b1e55fc95815605a919382cb47015..090bad145a36bd97a621957a39a90af6a17daa37 100644 (file)
--- a/include/abg-corpus.h
+++ b/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&);
 

diff --git a/src/abg-comparison-priv.h b/src/abg-comparison-priv.h
index fb843665d4689b75d15d9e16f58e972e111d5c15..48a01188758bc1a1a021b3b4e55e5e0bfca26443 100644 (file)
--- a/src/abg-comparison-priv.h
+++ b/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
 

diff --git a/src/abg-comparison.cc b/src/abg-comparison.cc
index 609c5bf2d1d50f1db949adcd2edc28ef45f0bf7d..dc4518680abef207c17a4e7abdb472ae3e595846 100644 (file)
--- a/src/abg-comparison.cc
+++ b/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_;
 }
 

diff --git a/src/abg-corpus-priv.h b/src/abg-corpus-priv.h
index 300ec6876159cb60c0d3e19907ac724639eed7e5..422b7870aebd8fb138ff571ef77e3f2e3e8d93e3 100644 (file)
--- a/src/abg-corpus-priv.h
+++ b/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&

diff --git a/src/abg-corpus.cc b/src/abg-corpus.cc
index 4f20a8883c567cd1dd4d857fdc0cbcf3e7042b3f..cf6685d6cea452bd3716bc3ae5d264a7bcfcbe59 100644 (file)
--- a/src/abg-corpus.cc
+++ b/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

diff --git a/src/abg-reader.cc b/src/abg-reader.cc
index 5a4fb3c04db5a3117c9a2ec9f641d8f2dc5f462f..b93cce3a1004f8e9a3ab0353c9fd79736de22435 100644 (file)
--- a/src/abg-reader.cc
+++ b/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)

diff --git a/tools/abidiff.cc b/tools/abidiff.cc
index bf0bf9fcdbaf00439b67d85de3369d3779509b9d..a0a670cbb2eefd26431233bdf632bded96bb063c 100644 (file)
--- a/tools/abidiff.cc
+++ b/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