route: profiling: add debugging prints.

vpr/src/route/route_profiling.cpp

@@ -2,6 +2,7 @@
 #include "globals.h"
 #include "vpr_types.h"
 #include "route_profiling.h"
+#include "rr_graph.h"
 
 namespace profiling {
 
@@ -29,6 +30,10 @@ void time_on_fanout_analysis() {}
 
 void profiling_initialization(unsigned /*max_net_fanout*/) {}
 
+void conn_start() {}
+void conn_finish(int /*src_rr*/, int /*sink_rr*/, float /*criticality*/) {}
+void net_finish() {}
+
 #else
 
 constexpr unsigned int fanout_per_bin = 1;
@@ -181,6 +186,12 @@ void congestion_analysis() {
 #    endif
 }
 
+static clock_t conn_start_time;
+static float worst_conn_time = 0.f;
+static int worst_src_rr;
+static int worst_sink_rr;
+static float worst_crit;
+
 void profiling_initialization(unsigned max_fanout) {
     // add 1 so that indexing on the max fanout would still be valid
     time_on_fanout.resize((max_fanout / fanout_per_bin) + 1, 0);
@@ -195,8 +206,37 @@ void profiling_initialization(unsigned max_fanout) {
     part_tree_preserved = 0;
     connections_forced_to_reroute = 0;
     connections_rerouted_due_to_forcing = 0;
+    worst_conn_time = 0.f;
     return;
 }
+
+void conn_start() {
+    conn_start_time = clock();
+}
+void conn_finish(int src_rr, int sink_rr, float criticality) {
+    float route_time = static_cast<float>(clock() - conn_start_time) / CLOCKS_PER_SEC;
+    if (route_time > worst_conn_time) {
+        worst_src_rr = src_rr;
+        worst_sink_rr = sink_rr;
+        worst_conn_time = route_time;
+        worst_crit = criticality;
+    }
+
+    VTR_LOG("%s to %s (crit: %f) took %f\n",
+            describe_rr_node(src_rr).c_str(),
+            describe_rr_node(sink_rr).c_str(),
+            criticality,
+            route_time);
+}
+void net_finish() {
+    if (worst_conn_time > 0.f) {
+        VTR_LOG("Worst conn was %s to %s (crit: %f) took %f\n",
+                describe_rr_node(worst_src_rr).c_str(),
+                describe_rr_node(worst_sink_rr).c_str(),
+                worst_crit,
+                worst_conn_time);
+    }
+}
 #endif
 
 } // end namespace profiling

vpr/src/route/route_profiling.h

@@ -30,6 +30,10 @@ void congestion_analysis();
 void time_on_criticality_analysis();
 void time_on_fanout_analysis();
 
+void conn_start();
+void conn_finish(int src_rr, int sink_rr, float criticality);
+void net_finish();
+
 void profiling_initialization(unsigned max_net_fanout);
 
 } // end namespace profiling

vpr/src/route/route_timing.cpp

@@ -1096,6 +1096,8 @@ bool timing_driven_route_net(ConnectionRouter& router,
             conn_delay_budget.short_path_criticality = budgeting_inf.get_crit_short_path(net_id, target_pin);
         }
 
+        profiling::conn_start();
+
         // build a branch in the route tree to the target
         if (!timing_driven_route_sink(router,
                                       net_id,
@@ -1109,10 +1111,15 @@ bool timing_driven_route_net(ConnectionRouter& router,
                                       router_stats))
             return false;
 
+        profiling::conn_finish(route_ctx.net_rr_terminals[net_id][0],
+                               sink_rr,
+                               pin_criticality[target_pin]);
+
         ++router_stats.connections_routed;
     } // finished all sinks
 
     ++router_stats.nets_routed;
+    profiling::net_finish();
 
     /* For later timing analysis. */