Add tracing to the abstract interpreter core algorithms

This includes debugging to dump out the full history and domain as we go
which allows tracing of the full computation if needed.

Author: martin

src/analyses/ai.cpp

@@ -269,6 +269,10 @@ bool ai_baset::visit(
 {
   bool new_data=false;
   locationt l = p->current_location();
+  messaget log(message_handler);
+
+  log.progress() << "ai_baset::visit " << l->location_number << " in "
+                 << function_id << messaget::eom;
 
   // Function call and end are special cases
   if(l->is_function_call())
@@ -325,11 +329,27 @@ bool ai_baset::visit_edge(
   const namespacet &ns,
   working_sett &working_set)
 {
+  messaget log(message_handler);
+  log.progress() << "ai_baset::visit_edge from "
+                 << p->current_location()->location_number << " to "
+                 << to_l->location_number << "... ";
+
   // Has history taught us not to step here...
   auto next =
     p->step(to_l, *(storage->abstract_traces_before(to_l)), caller_history);
   if(next.first == ai_history_baset::step_statust::BLOCKED)
+  {
+    log.progress() << "blocked by history" << messaget::eom;
     return false;
+  }
+  else if(next.first == ai_history_baset::step_statust::NEW)
+  {
+    log.progress() << "gives a new history... ";
+  }
+  else
+  {
+    log.progress() << "merges with existing history... ";
+  }
   trace_ptrt to_p = next.second;
 
   // Abstract domains are mutable so we must copy before we transform
@@ -339,21 +359,50 @@ bool ai_baset::visit_edge(
   statet &new_values = *tmp_state;
 
   // Apply transformer
+  log.progress() << "applying transformer... ";
   new_values.transform(function_id, p, to_function_id, to_p, *this, ns);
 
   // Expanding a domain means that it has to be analysed again
   // Likewise if the history insists that it is a new trace
   // (assuming it is actually reachable).
+  log.progress() << "merging... ";
+  bool return_value = false;
   if(
     merge(new_values, p, to_p) ||
     (next.first == ai_history_baset::step_statust::NEW &&
      !new_values.is_bottom()))
   {
     put_in_working_set(working_set, to_p);
-    return true;
+    log.progress() << "result queued." << messaget::eom;
+    return_value = true;
+  }
+  else
+  {
+    log.progress() << "domain unchanged." << messaget::eom;
   }
 
-  return false;
+  // Branch because printing some histories and domains can be expensive
+  // esp. if the output is then just discarded and this is a critical path.
+  if(message_handler.get_verbosity() >= messaget::message_levelt::M_DEBUG)
+  {
+    log.debug() << "p = ";
+    p->output(log.debug());
+    log.debug() << messaget::eom;
+
+    log.debug() << "current = ";
+    current.output(log.debug(), *this, ns);
+    log.debug() << messaget::eom;
+
+    log.debug() << "to_p = ";
+    to_p->output(log.debug());
+    log.debug() << messaget::eom;
+
+    log.debug() << "new_values = ";
+    new_values.output(log.debug(), *this, ns);
+    log.debug() << messaget::eom;
+  }
+
+  return return_value;
 }
 
 bool ai_baset::visit_edge_function_call(
@@ -366,6 +415,11 @@ bool ai_baset::visit_edge_function_call(
   const goto_functionst &,
   const namespacet &ns)
 {
+  messaget log(message_handler);
+  log.progress() << "ai_baset::visit_edge_function_call from "
+                 << p_call->current_location()->location_number << " to "
+                 << l_return->location_number << messaget::eom;
+
   // The default implementation is not interprocedural
   // so the effects of the call are approximated but nothing else
   return visit_edge(
@@ -391,6 +445,10 @@ bool ai_baset::visit_function_call(
 
   PRECONDITION(l_call->is_function_call());
 
+  messaget log(message_handler);
+  log.progress() << "ai_baset::visit_function_call at "
+                 << l_call->location_number << messaget::eom;
+
   locationt l_return = std::next(l_call);
 
   // operator() allows analysis of a single goto_program independently
@@ -405,6 +463,8 @@ bool ai_baset::visit_function_call(
       const irep_idt &callee_function_id =
         to_symbol_expr(callee_expression).get_identifier();
 
+      log.progress() << "Calling " << callee_function_id << messaget::eom;
+
       goto_functionst::function_mapt::const_iterator it =
         goto_functions.function_map.find(callee_function_id);
 
@@ -464,6 +524,10 @@ bool ai_baset::visit_end_function(
   locationt l = p->current_location();
   PRECONDITION(l->is_end_function());
 
+  messaget log(message_handler);
+  log.progress() << "ai_baset::visit_end_function " << function_id
+                 << messaget::eom;
+
   // Do nothing
   return false;
 }
@@ -478,6 +542,11 @@ bool ai_recursive_interproceduralt::visit_edge_function_call(
   const goto_functionst &goto_functions,
   const namespacet &ns)
 {
+  messaget log(message_handler);
+  log.progress() << "ai_recursive_interproceduralt::visit_edge_function_call"
+                 << " from " << p_call->current_location()->location_number
+                 << " to " << l_return->location_number << messaget::eom;
+
   // This is the edge from call site to function head.
   {
     locationt l_begin = callee.instructions.begin();
@@ -495,6 +564,9 @@ bool ai_recursive_interproceduralt::visit_edge_function_call(
       ns,
       catch_working_set);
 
+    log.progress() << "Handle " << callee_function_id << " recursively"
+                   << messaget::eom;
+
     // do we need to do/re-do the fixedpoint of the body?
     if(new_data)
       fixedpoint(
@@ -507,6 +579,8 @@ bool ai_recursive_interproceduralt::visit_edge_function_call(
 
   // This is the edge from function end to return site.
   {
+    log.progress() << "Handle return edges" << messaget::eom;
+
     // get location at end of the procedure we have called
     locationt l_end = --callee.instructions.end();
     DATA_INVARIANT(

src/analyses/variable-sensitivity/three_way_merge_abstract_interpreter.cpp

@@ -43,6 +43,11 @@ bool ai_three_way_merget::visit_edge_function_call(
     l_callee_end->is_end_function(),
     "The last instruction of a goto_program must be END_FUNCTION");
 
+  messaget log(message_handler);
+  log.progress() << "ai_three_way_merget::visit_edge_function_call"
+                 << " from " << l_call_site->location_number << " to "
+                 << l_callee_start->location_number << messaget::eom;
+
   // Histories for call_site and callee_start are easy
   trace_ptrt p_call_site = p_call;
 
@@ -54,6 +59,7 @@ bool ai_three_way_merget::visit_edge_function_call(
   {
     // Unexpected...
     // We can't three-way merge without a callee start so
+    log.progress() << "Blocked by history step!" << messaget::eom;
     return false;
   }
   trace_ptrt p_callee_start = next.second;
@@ -74,6 +80,9 @@ bool ai_three_way_merget::visit_edge_function_call(
       ns,
       catch_working_set);
 
+    log.progress() << "Handle " << callee_function_id << " recursively"
+                   << messaget::eom;
+
     // do we need to do/re-do the fixedpoint of the body?
     if(new_data)
       fixedpoint(
@@ -85,6 +94,7 @@ bool ai_three_way_merget::visit_edge_function_call(
   }
 
   // Now we can give histories for the return part
+  log.progress() << "Handle return edges" << messaget::eom;
 
   // Find the histories at the end of the function
   auto traces = storage->abstract_traces_before(l_callee_end);
@@ -96,19 +106,37 @@ bool ai_three_way_merget::visit_edge_function_call(
   // p_call_site and p_callee_start
   for(auto p_callee_end : *traces)
   {
+    log.progress() << "ai_three_way_merget::visit_edge_function_call edge from "
+                   << l_callee_end->location_number << " to "
+                   << l_return_site->location_number << "... ";
+
     // First off, is it even reachable?
     const statet &s_callee_end = get_state(p_callee_end);
 
     if(s_callee_end.is_bottom())
+    {
+      log.progress() << "unreachable on this trace" << messaget::eom;
       continue; // Unreachable in callee -- no need to merge
+    }
 
     // Can it return to p_call_site?
     auto return_step = p_callee_end->step(
       l_return_site,
       *(storage->abstract_traces_before(l_return_site)),
       p_call_site); // Because it is a return edge!
     if(return_step.first == ai_history_baset::step_statust::BLOCKED)
+    {
+      log.progress() << "blocked by history" << messaget::eom;
       continue; // Can't return -- no need to merge
+    }
+    else if(return_step.first == ai_history_baset::step_statust::NEW)
+    {
+      log.progress() << "gives a new history... ";
+    }
+    else
+    {
+      log.progress() << "merges with existing history... ";
+    }
 
     // The fourth history!
     trace_ptrt p_return_site = return_step.second;
@@ -123,6 +151,7 @@ bool ai_three_way_merget::visit_edge_function_call(
     // Apply transformer
     // This is for an end_function instruction which normally doesn't do much
     // but in VSD it does, so this cannot be omitted.
+    log.progress() << "applying transformer... ";
     s_working.transform(
       callee_function_id,
       p_callee_end,
@@ -137,20 +166,48 @@ bool ai_three_way_merget::visit_edge_function_call(
     const std::unique_ptr<statet> ptr_s_working_copy(
       make_temporary_state(s_working));
 
+    log.progress() << "three way merge... ";
     s_working.merge_three_way_function_return(
       get_state(p_call_site),
       get_state(p_callee_start),
       *ptr_s_working_copy,
       ns);
 
+    log.progress() << "merging... ";
     if(
       merge(s_working, p_callee_end, p_return_site) ||
       (return_step.first == ai_history_baset::step_statust::NEW &&
        !s_working.is_bottom()))
     {
       put_in_working_set(working_set, p_return_site);
+      log.progress() << "result queued." << messaget::eom;
       new_data = true;
     }
+    else
+    {
+      log.progress() << "domain unchanged." << messaget::eom;
+    }
+
+    // Branch because printing some histories and domains can be expensive
+    // esp. if the output is then just discarded and this is a critical path.
+    if(message_handler.get_verbosity() >= messaget::message_levelt::M_DEBUG)
+    {
+      log.debug() << "p_callee_end = ";
+      p_callee_end->output(log.debug());
+      log.debug() << messaget::eom;
+
+      log.debug() << "s_callee_end = ";
+      s_callee_end.output(log.debug(), *this, ns);
+      log.debug() << messaget::eom;
+
+      log.debug() << "p_return_site = ";
+      p_return_site->output(log.debug());
+      log.debug() << messaget::eom;
+
+      log.debug() << "s_working = ";
+      s_working.output(log.debug(), *this, ns);
+      log.debug() << messaget::eom;
+    }
   }
 
   return new_data;