From b5ab4d2009ba290e62855d326bcc3374f27f4d0a Mon Sep 17 00:00:00 2001 From: Dodji Seketeli Date: Wed, 15 Feb 2023 13:18:07 +0100 Subject: [PATCH] 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 --- include/abg-comparison.h | 18 ++++ include/abg-corpus.h | 6 ++ src/abg-comparison-priv.h | 4 +- src/abg-comparison.cc | 211 ++++++++++++++++++++++++++++++++++++++ src/abg-corpus-priv.h | 4 +- src/abg-corpus.cc | 14 +++ src/abg-reader.cc | 22 ++++ tools/abidiff.cc | 181 ++++++++++++++++++++++++++++++-- 8 files changed, 452 insertions(+), 8 deletions(-) diff --git a/include/abg-comparison.h b/include/abg-comparison.h index 839478bf..506f2bb7 100644 --- 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_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 fabda0f9..090bad14 100644 --- 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 fb843665..48a01188 100644 --- 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 609c5bf2..dc451868 100644 --- 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 300ec687..422b7870 100644 --- 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 types_not_reachable_from_pub_ifaces_; unordered_set *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 4f20a888..cf6685d6 100644 --- 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 5a4fb3c0..b93cce3a 100644 --- 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 bf0bf9fc..a0a670cb 100644 --- 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 -- 2.34.1