Merge pull request diffblue#363 from diffblue/micro_time_profiler

Added micro time profiler

Author: marek-trtik

src/pointer-analysis/local_value_set.cpp

@@ -10,6 +10,7 @@
 #include <util/infix.h>
 #include <util/suffix.h>
 #include <util/c_types.h>
+#include <util/tmprof.h>
 
 #include <pointer-analysis/dynamic_object_name.h>
 
@@ -87,6 +88,8 @@ void local_value_sett::get_may_alias_set(
   value_setst::valuest &dest,
   const namespacet &ns) const
 {
+  TMPROF_BLOCK();
+
   object_mapt pointed_objects;
   get_value_set(expr, pointed_objects, ns, false);
   std::vector<exprt> uniform_pointed_objects;

src/taint-analysis/taint_security_scanner.cpp

@@ -17,6 +17,7 @@
 #include <util/config.h>
 #include <util/msgstream.h>
 #include <util/json_map_serializer.h>
+#include <util/tmprof.h>
 #include "taint_serializer_traits.h"
 #include <iomanip>
 #include <memory>
@@ -336,6 +337,9 @@ bool taint_do_security_scan(
 
     logger.status() << "The security scanner has finished successfully."
       << messaget::eom;
+    tmprof_dump_as_json(
+      boost::filesystem::path(config.get_output_root_directory()) /
+      "TMPROF.json");
     return true;
   }
   catch(const std::exception &e)

src/taint-analysis/taint_summary.cpp

@@ -21,6 +21,7 @@ This module defines interfaces and functionality for taint summaries.
 #include <summaries/summary_dump.h>
 #include <pointer-analysis/local_value_set_analysis.h>
 #include <goto-programs/remove_returns.h>
+#include <util/tmprof.h>
 #include <util/std_types.h>
 #include <util/file_util.h>
 #include <util/msgstream.h>
@@ -71,6 +72,8 @@ void expand_external_objects(
   const object_numbers_by_fieldnamet& by_fieldname,
   const object_numberingt& taint_object_numbering)
 {
+  TMPROF_BLOCK();
+
   // Whenever a value like external_value_set("external_objects.x") occurs,
   // expand that to include the 'x' fields of all objects we know about,
   // as what is external to the callee might be local to us.
@@ -112,6 +115,8 @@ void expand_external_objects(
 
 static exprt transform_external_objects(const exprt& e)
 {
+  TMPROF_BLOCK();
+
   if(e.id()==ID_member && get_underlying_object(e).id()==ID_external_value_set)
   {
     // Rewrite member(externals, "x") as externals("x"), to make subsequent
@@ -167,6 +172,8 @@ static void collect_lvsa_access_paths(
   instruction_iteratort const& instit,
   std::set<exprt> &result)
 {
+  TMPROF_BLOCK();
+
   if(query_in.id()==ID_side_effect)
   {
     side_effect_exprt const see=to_side_effect_expr(query_in);
@@ -245,6 +252,8 @@ static void collect_lvsa_access_paths(
   lvalue_numbers_sett& result,
   bool &singular)
 {
+  TMPROF_BLOCK();
+
   std::set<exprt> referees;
   collect_lvsa_access_paths(
     query_in,
@@ -274,6 +283,8 @@ static void collect_lvsa_alias_access_paths(
   object_numberingt& taint_object_numbering,
   lvalue_numbers_sett& result)
 {
+  TMPROF_BLOCK();
+
   value_setst::valuest dest;
   lvsa.get_may_alias_values(inst_it, query_in, dest);
   for(const exprt &object : dest)
@@ -288,6 +299,8 @@ static void collect_lvsa_access_paths(
   instruction_iteratort const& instit,
   object_numberingt& taint_object_numbering)
 {
+  TMPROF_BLOCK();
+
   bool singular=false;
 
   collect_lvsa_access_paths(
@@ -308,6 +321,8 @@ static void populate_formals_to_actuals(
   object_numberingt& taint_object_numbering,
   formals_to_actuals_mapt& formals_to_actuals)
 {
+  TMPROF_BLOCK();
+
   for(auto instit=prog.instructions.begin(),instend=prog.instructions.end();
       instit!=instend; ++instit)
   {
@@ -382,6 +397,8 @@ numbered_lvalue_to_taint_mapt taint_algorithm_computing_summary_of_functiont::
     const numbered_lvalue_to_taint_mapt &a,
     const numbered_lvalue_to_taint_mapt &b)
 {
+  TMPROF_BLOCK();
+
   numbered_lvalue_to_taint_mapt result_dict;
   if(a.get_base()==b.get_base())
   {
@@ -428,6 +445,8 @@ numbered_lvalue_to_taint_mapt taint_algorithm_computing_summary_of_functiont::
     const numbered_lvalue_to_taint_mapt &a,
     const numbered_lvalue_to_taint_mapt &b)
 {
+  TMPROF_BLOCK();
+
   numbered_lvalue_to_taint_mapt result = a;
   for(auto  b_it=b.cbegin(); b_it!=b.cend(); ++b_it)
     assign(result, b_it->first, b_it->second);
@@ -439,6 +458,8 @@ void taint_algorithm_computing_summary_of_functiont::assign(
   taint_lvalue_numbert const lvalue,
   const taint_sett &taint)
 {
+  TMPROF_BLOCK();
+
   auto const  it = map.find(lvalue);
   if (it == map.end())
   {
@@ -454,6 +475,8 @@ void taint_algorithm_computing_summary_of_functiont::maybe_assign(
   taint_lvalue_numbert const lvalue,
   const taint_sett &taint)
 {
+  TMPROF_BLOCK();
+
   auto const  it = map.find(lvalue);
   if (it == map.end())
   {
@@ -471,6 +494,8 @@ bool taint_algorithm_computing_summary_of_functiont::proper_subset(
   const numbered_lvalue_to_taint_mapt &a,
   const numbered_lvalue_to_taint_mapt &b)
 {
+  TMPROF_BLOCK();
+
   if(b.empty())
     return false;
   bool common_base=a.get_base()==b.get_base();
@@ -492,6 +517,8 @@ bool taint_algorithm_computing_summary_of_functiont::subset(
   const numbered_lvalue_to_taint_mapt &a,
   const numbered_lvalue_to_taint_mapt &b)
 {
+  TMPROF_BLOCK();
+
   return a==b || proper_subset(a,b);
 }
 
@@ -506,6 +533,8 @@ void  taint_algorithm_computing_summary_of_functiont::
     const instruction_iteratort &Iit,
     const irep_idt &caller_ident)
 {
+  TMPROF_BLOCK();
+
   auto parameter_indices=fn_type.parameter_indices();
 
   for (const std::pair<taint_lvalue_numbert, taint_variablet>& input
@@ -568,6 +597,8 @@ void taint_algorithm_computing_summary_of_functiont::
     const instruction_iteratort &Iit,
     local_value_set_analysist &lvsa)
 {
+  TMPROF_BLOCK();
+
   auto parameter_indices=fn_type.parameter_indices();
 
   for(const std::pair<taint_lvalue_numbert, taint_sett>& lvalue_taint :
@@ -650,6 +681,8 @@ void taint_algorithm_computing_summary_of_functiont::initialise_domain(
   const std::map<goto_programt::const_targett, goto_programt::const_targetst>
     &inst_predecessors)
 {
+  TMPROF_BLOCK();
+
   // TODO: Improve this to only count as inputs those values which might be read
   // without a preceding write within the same function.
   lvalue_numbers_sett environment;
@@ -880,6 +913,8 @@ void taint_algorithm_computing_summary_of_functiont::handle_assignment(
   instruction_iteratort const& Iit,
   local_value_set_analysist &lvsa)
 {
+  TMPROF_BLOCK();
+
   const auto& lhs_type=program->get_namespace().follow(asgn.lhs().type());
   if(lhs_type.id()==ID_struct)
   {
@@ -950,6 +985,8 @@ taint_sett taint_algorithm_computing_summary_of_functiont::
     local_value_set_analysist &lvsa,
     const numbered_lvalue_to_taint_mapt &a)
 {
+  TMPROF_BLOCK();
+
   lvalue_numbers_sett numbers_of_aliases;
   collect_lvsa_access_paths(
     lvalue,
@@ -977,6 +1014,8 @@ void taint_algorithm_computing_summary_of_functiont::
     local_value_set_analysist &lvsa,
     numbered_lvalue_to_taint_mapt &result)
 {
+  TMPROF_BLOCK();
+
   lvalue_numbers_sett numbers_of_aliases;
   bool singular=false;
   collect_lvsa_access_paths(
@@ -1020,6 +1059,8 @@ numbered_lvalue_to_taint_mapt taint_algorithm_computing_summary_of_functiont::
     local_value_set_analysist &lvsa,
     taint_transition_propertiest &transition_properties)
 {
+  TMPROF_BLOCK();
+
   goto_programt::instructiont const&  I=*Iit;
   numbered_lvalue_to_taint_mapt result;
   // Take a cheap read-only view of the incoming domain:
@@ -1028,6 +1069,8 @@ numbered_lvalue_to_taint_mapt taint_algorithm_computing_summary_of_functiont::
   {
   case ASSIGN:
     {
+      TMPROF_BLOCK();
+
       transition_properties[Iit].push_back(
         {taint_transition_property_typet::ASSIGNMENT, taint_rule_idt{}, ""});
       const code_assignt &asgn=to_code_assign(I.code);
@@ -1089,6 +1132,8 @@ numbered_lvalue_to_taint_mapt taint_algorithm_computing_summary_of_functiont::
     break;
   case FUNCTION_CALL:
     {
+      TMPROF_BLOCK();
+
       const code_function_callt &fn_call = to_code_function_call(I.code);
       const exprt &callee_expr = fn_call.function();
       if(callee_expr.id()==ID_symbol)
@@ -1155,6 +1200,8 @@ numbered_lvalue_to_taint_mapt taint_algorithm_computing_summary_of_functiont::
           for(const taint_propagation_rulet &propagation_rule :
               propagation_rules)
           {
+            TMPROF_BLOCK();
+
             const taint_sett taint_from_rule =
               propagation_rule.has_input_condition()
                 ? propagation_rule.apply(
@@ -1229,6 +1276,8 @@ numbered_lvalue_to_taint_mapt taint_algorithm_computing_summary_of_functiont::
           }
           for(const taint_sanitizer_rulet &sanitizer_rule : sanitizer_rules)
           {
+            TMPROF_BLOCK();
+
             const taintable_locationt &sanitized_location =
               sanitizer_rule.get_sanitized_location();
 
@@ -1280,6 +1329,8 @@ numbered_lvalue_to_taint_mapt taint_algorithm_computing_summary_of_functiont::
           }
           for(const taint_sink_rulet &sink_rule : sink_rules)
           {
+            TMPROF_BLOCK();
+
             statistics->on_taint_analysis_apply_sink_rule(
               sink_rule.get_id(), I.location_number);
 
@@ -1475,6 +1526,8 @@ void taint_algorithm_computing_summary_of_functiont::
   taint_summaryt &summary,
   const written_expressionst &written)
 {
+  TMPROF_BLOCK();
+
   taint_sett end_values_taint;
   const numbered_lvalue_to_taint_mapt &end_value_taints =
     summary.domain.at(std::prev(fn_to_summarise.body.instructions.cend()));
@@ -1537,6 +1590,8 @@ void taint_algorithm_computing_summary_of_functiont::
     taint_summaryt::dbt &database,
     local_value_set_analysist::dbt &lvsa_db)
 {
+  TMPROF_BLOCK();
+
   const goto_functionst::function_mapt &functions=
     program->get_functions().function_map;
   const auto fn_iter=functions.find(function_id);

src/util/tmprof.cpp

@@ -0,0 +1,69 @@
+// Copyright 2018 Diffblue Limited. All Rights Reserved.
+
+/// \file
+/// Micro time profiler with code block granularity.
+
+#include <util/tmprof.h>
+#include <boost/filesystem.hpp>
+#include <iostream>
+#include <sstream>
+
+static bool enabled = true;
+
+bool is_time_profiling_enabled()
+{
+  return enabled;
+}
+
+void enable_time_profiling(const bool state)
+{
+  enabled = state;
+}
+
+std::list<tmprof_detail_datat> tmprof_detail_datat::records;
+
+tmprof_detail_datat *
+tmprof_detail_datat::create(const char *name, const unsigned long line)
+{
+  records.emplace_back(name, line);
+  return &records.back();
+}
+
+void tmprof_detail_datat::on_hit(const double duration)
+{
+  total_time += duration;
+  if(max_time < duration)
+    max_time = duration;
+  ++hit_count;
+}
+
+json_objectt tmprof_detail_datat::dump_as_json()
+{
+  json_objectt root;
+  for(const auto &record : records)
+    if(record.get_hit_count() != 0ULL)
+    {
+      json_objectt table;
+      table["total_time"] =
+        json_numbert(std::to_string(record.get_total_time()));
+      table["max_time"] = json_numbert(std::to_string(record.get_max_time()));
+      table["hit_count"] = json_numbert(std::to_string(record.get_hit_count()));
+      std::stringstream sstr;
+      sstr << record.get_name() << " [" << record.get_line() << "]";
+      root[sstr.str()] = table;
+    }
+  return root;
+}
+
+void tmprof_dump_as_json(std::ostream &ostr)
+{
+  ostr << tmprof_detail_datat::dump_as_json();
+}
+
+void tmprof_dump_as_json(const boost::filesystem::path &out_file_pathname)
+{
+  if(!boost::filesystem::exists(out_file_pathname.parent_path()))
+    boost::filesystem::create_directory(out_file_pathname.parent_path());
+  std::ofstream ostr(out_file_pathname.native());
+  tmprof_dump_as_json(ostr);
+}