Print out info/report on overused rr-nodes at the end of a failed routing iteration (#1455)

* Print overused info if routing fails. Formatted header and overused nodes info body

* Minor fix to display format

* Added option to set the limit for max reported overused RR nodes

* Changed the command line option to --generate_rr_node_overuse_report. Also print a message if the # of overused nodes is too large for logging.

* Added option --generate_rr_node_overuse_report on for a detailed report on overused nodes

* Added congested nets to the overuse report

* Moved overuse info routines to separate files

* Changed the overused nodes report generation to take effect only when the final routing attempt has failed. Also fixed a bug where a single net counts a overused node for multiple times in the report

* Changed indexing of the report functions from size_t to RRNodeId (strong ids). Also added new accessors for the rr_graph_storage interface

* Added documentation for the two new command line options

* Added detailed congested net info to the overused RR node report

* Improved the logging file: will display overused nodes entries up to the threshold number if the threshold is exceeded. Add reminder for the report generation option at the end of vpr.out logfile should the router fails to implement the circuit.

* Update documentation according to the latest change to the logfile

Author: Bill-hbrhbr

doc/src/vpr/command_line_usage.rst

@@ -1008,6 +1008,24 @@ VPR uses a negotiated congestion algorithm (based on Pathfinder) to perform rout
 
     **Default:** ``16``
 
+.. option:: --max_logged_overused_rr_nodes <int>
+
+    Prints the information on overused RR nodes to the VPR log file after the each failed routing attempt.
+
+    If the number of overused nodes is above the given threshold ``N``, then only the first ``N`` entries are printed to the logfile.
+
+    **Default:** ``20``
+
+.. option:: --generate_rr_node_overuse_report {on | off}
+
+    Generates a detailed report on the overused RR nodes' information: **report_overused_nodes.rpt**.
+
+    This report is generated only when the final routing attempt fails (i.e. the whole routing process has failed).
+
+    In addition to the information that can be seen via ``--max_logged_overused_rr_nodes``, this report prints out all the net ids that are associated with each overused RR node. Also, this report does not place a threshold upon the number of RR nodes printed.
+
+    **Default:** ``off``
+
 .. _timing_driven_router_options:
 
 Timing-Driven Router Options

vpr/src/base/SetupVPR.cpp

@@ -392,6 +392,9 @@ static void SetupRouterOpts(const t_options& Options, t_router_opts* RouterOpts)
 
     RouterOpts->check_route = Options.check_route;
     RouterOpts->timing_update_type = Options.timing_update_type;
+
+    RouterOpts->max_logged_overused_rr_nodes = Options.max_logged_overused_rr_nodes;
+    RouterOpts->generate_rr_node_overuse_report = Options.generate_rr_node_overuse_report;
 }
 
 static void SetupAnnealSched(const t_options& Options,

vpr/src/base/read_options.cpp

@@ -1855,6 +1855,16 @@ argparse::ArgumentParser create_arg_parser(std::string prog_name, t_options& arg
         .default_value("off")
         .show_in(argparse::ShowIn::HELP_ONLY);
 
+    route_grp.add_argument(args.max_logged_overused_rr_nodes, "--max_logged_overused_rr_nodes")
+        .help("Maximum number of overused RR nodes logged each time the routing fails")
+        .default_value("20")
+        .show_in(argparse::ShowIn::HELP_ONLY);
+
+    route_grp.add_argument<bool, ParseOnOff>(args.generate_rr_node_overuse_report, "--generate_rr_node_overuse_report")
+        .help("Generate detailed reports on overused rr nodes and congested nets should the routing fails")
+        .default_value("off")
+        .show_in(argparse::ShowIn::HELP_ONLY);
+
     auto& route_timing_grp = parser.add_argument_group("timing-driven routing options");
 
     route_timing_grp.add_argument(args.astar_fac, "--astar_fac")

vpr/src/base/read_options.h

@@ -150,6 +150,8 @@ struct t_options {
     argparse::ArgValue<bool> read_rr_edge_metadata;
     argparse::ArgValue<bool> exit_after_first_routing_iteration;
     argparse::ArgValue<e_check_route_option> check_route;
+    argparse::ArgValue<size_t> max_logged_overused_rr_nodes;
+    argparse::ArgValue<bool> generate_rr_node_overuse_report;
 
     /* Timing-driven router options only */
     argparse::ArgValue<float> astar_fac;

vpr/src/base/vpr_api.cpp

@@ -69,6 +69,7 @@
 #include "cluster.h"
 
 #include "pack_report.h"
+#include "overuse_report.h"
 
 #include "timing_graph_builder.h"
 #include "timing_reports.h"
@@ -726,13 +727,24 @@ RouteStatus vpr_route_flow(t_vpr_setup& vpr_setup, const t_arch& arch) {
 
             //Update status
             VTR_LOG("Circuit successfully routed with a channel width factor of %d.\n", route_status.chan_width());
-            graphics_msg = vtr::string_fmt("Routing succeeded with a channel width factor of %d.", route_status.chan_width());
+            graphics_msg = vtr::string_fmt("Routing succeeded with a channel width factor of %d.\n", route_status.chan_width());
         } else {
             //Update status
             VTR_LOG("Circuit is unroutable with a channel width factor of %d.\n", route_status.chan_width());
             graphics_msg = vtr::string_fmt("Routing failed with a channel width factor of %d. ILLEGAL routing shown.", route_status.chan_width());
+
+            //Generate a report on overused nodes if specified
+            //Otherwise, remind the user of this possible report option
+            if (router_opts.generate_rr_node_overuse_report) {
+                VTR_LOG("See report_overused_nodes.rpt for a detailed report on the RR node overuse information.\n");
+                report_overused_nodes();
+            } else {
+                VTR_LOG("For a detailed report on the RR node overuse information (report_overused_nodes.rpt), specify --generate_rr_node_overuse_report on.\n");
+            }
         }
 
+        VTR_LOG("\n");
+
         //Echo files
         if (vpr_setup.Timing.timing_analysis_enabled) {
             if (isEchoFileEnabled(E_ECHO_FINAL_ROUTING_TIMING_GRAPH)) {

vpr/src/base/vpr_types.h

@@ -1099,6 +1099,9 @@ struct t_router_opts {
 
     e_check_route_option check_route;
     e_timing_update_type timing_update_type;
+
+    size_t max_logged_overused_rr_nodes;
+    bool generate_rr_node_overuse_report;
 };
 
 struct t_analysis_opts {

vpr/src/route/overuse_report.cpp

@@ -0,0 +1,186 @@
+#include "overuse_report.h"
+
+#include <fstream>
+#include "globals.h"
+#include "vtr_log.h"
+
+static void log_overused_nodes_header();
+static void log_single_overused_node_status(int overuse_index, RRNodeId inode);
+
+void log_overused_nodes_status(int max_logged_overused_rr_nodes) {
+    const auto& device_ctx = g_vpr_ctx.device();
+    const auto& route_ctx = g_vpr_ctx.routing();
+
+    //Print overuse info header
+    log_overused_nodes_header();
+
+    //Print overuse info body
+    int overuse_index = 0;
+    for (size_t inode = 0; inode < device_ctx.rr_nodes.size(); inode++) {
+        int overuse = route_ctx.rr_node_route_inf[inode].occ() - device_ctx.rr_nodes[inode].capacity();
+
+        if (overuse > 0) {
+            log_single_overused_node_status(overuse_index, RRNodeId(inode));
+            ++overuse_index;
+
+            //Reached the logging limit
+            if (overuse_index >= max_logged_overused_rr_nodes) {
+                return;
+            }
+        }
+    }
+}
+
+void report_overused_nodes() {
+    const auto& device_ctx = g_vpr_ctx.device();
+    const auto& route_ctx = g_vpr_ctx.routing();
+    const auto& clb_nlist = g_vpr_ctx.clustering().clb_nlist;
+
+    //Generate overuse infor lookup table
+    std::map<RRNodeId, std::set<ClusterNetId>> nodes_to_nets_lookup;
+    generate_overused_nodes_to_congested_net_lookup(nodes_to_nets_lookup);
+
+    //Open the report file
+    std::ofstream os("report_overused_nodes.rpt");
+    os << "Overused nodes information report on the final failed routing attempt" << '\n';
+    os << "Total number of overused nodes = " << nodes_to_nets_lookup.size() << '\n';
+
+    int inode = 0;
+
+    for (const auto& lookup_pair : nodes_to_nets_lookup) {
+        const RRNodeId node_id = lookup_pair.first;
+        const auto& congested_nets = lookup_pair.second;
+
+        os << "************************************************\n\n"; //RR Node Separation line
+
+        //Report Basic info
+        os << "Overused RR node #" << inode << '\n';
+        os << "Node id = " << size_t(node_id) << '\n';
+        os << "Occupancy = " << route_ctx.rr_node_route_inf[size_t(node_id)].occ() << '\n';
+        os << "Capacity = " << device_ctx.rr_nodes.node_capacity(node_id) << '\n';
+        os << "Node type = " << device_ctx.rr_nodes.node_type_string(node_id) << '\n';
+        os << "PTC number = " << device_ctx.rr_nodes.node_ptc_num(node_id) << '\n';
+        os << "Xlow = " << device_ctx.rr_nodes.node_xlow(node_id) << ", ";
+        os << "Ylow = " << device_ctx.rr_nodes.node_ylow(node_id) << '\n';
+        os << "Xhigh = " << device_ctx.rr_nodes.node_xhigh(node_id) << ", ";
+        os << "Yhigh = " << device_ctx.rr_nodes.node_yhigh(node_id) << '\n';
+
+        //Report Selective info
+        auto node_type = device_ctx.rr_nodes.node_type(node_id);
+
+        if (node_type == e_rr_type::CHANX || node_type == e_rr_type::CHANY) {
+            os << "Direction = " << device_ctx.rr_nodes.node_direction_string(node_id) << '\n';
+
+            os << "Resistance = " << device_ctx.rr_nodes.node_R(node_id) << '\n';
+            os << "Capacitance = " << device_ctx.rr_nodes.node_C(node_id) << '\n';
+        } else if (node_type == e_rr_type::IPIN || node_type == e_rr_type::OPIN) {
+            os << "Side = " << device_ctx.rr_nodes.node_side_string(node_id) << '\n';
+        }
+
+        os << "-----------------------------\n"; //Node/net info separation line
+
+        //Reported corresponding congested nets
+        int inet = 0;
+
+        os << "Number of nets passing through this RR node = " << congested_nets.size() << '\n';
+        for (ClusterNetId net_id : congested_nets) {
+            ClusterBlockId block_id = clb_nlist.net_driver_block(net_id);
+
+            os << "Net #" << inet << ": ";
+            os << "Net ID = " << size_t(net_id) << ", ";
+            os << "Net name = " << clb_nlist.net_name(net_id) << ", ";
+            os << "Driving block name = " << clb_nlist.block_pb(block_id)->name << ", ";
+            os << "Driving block type = " << clb_nlist.block_type(block_id)->name << '\n';
+
+            ++inet;
+        }
+
+        os << '\n';
+        ++inode;
+    }
+
+    os.close();
+}
+
+void generate_overused_nodes_to_congested_net_lookup(std::map<RRNodeId, std::set<ClusterNetId>>& nodes_to_nets_lookup) {
+    const auto& device_ctx = g_vpr_ctx.device();
+    const auto& route_ctx = g_vpr_ctx.routing();
+    const auto& cluster_ctx = g_vpr_ctx.clustering();
+
+    //Create overused nodes to congested nets look up by
+    //traversing through the net trace backs linked lists
+    for (ClusterNetId net_id : cluster_ctx.clb_nlist.nets()) {
+        for (t_trace* tptr = route_ctx.trace[net_id].head; tptr != nullptr; tptr = tptr->next) {
+            int inode = tptr->index;
+
+            int overuse = route_ctx.rr_node_route_inf[inode].occ() - device_ctx.rr_nodes[inode].capacity();
+            if (overuse > 0) {
+                nodes_to_nets_lookup[RRNodeId(inode)].insert(net_id);
+            }
+        }
+    }
+}
+
+static void log_overused_nodes_header() {
+    VTR_LOG("Routing Failure Diagnostics: Printing Overused Nodes Information\n");
+    VTR_LOG("------ ------- ---------- --------- -------- ------------ ------- ------- ------- ------- ------- -------\n");
+    VTR_LOG("   No.  NodeId  Occupancy  Capacity  RR Node    Direction    Side     PTC    Xlow    Ylow   Xhigh   Yhigh\n");
+    VTR_LOG("                                        type                          NUM                                \n");
+    VTR_LOG("------ ------- ---------- --------- -------- ------------ ------- ------- ------- ------- ------- -------\n");
+}
+
+static void log_single_overused_node_status(int overuse_index, RRNodeId node_id) {
+    const auto& device_ctx = g_vpr_ctx.device();
+    const auto& route_ctx = g_vpr_ctx.routing();
+
+    //Determines if direction or side is available for printing
+    auto node_type = device_ctx.rr_nodes.node_type(node_id);
+
+    //Overuse #
+    VTR_LOG("%6d", overuse_index);
+
+    //Inode
+    VTR_LOG(" %7d", size_t(node_id));
+
+    //Occupancy
+    VTR_LOG(" %10d", route_ctx.rr_node_route_inf[size_t(node_id)].occ());
+
+    //Capacity
+    VTR_LOG(" %9d", device_ctx.rr_nodes.node_capacity(node_id));
+
+    //RR node type
+    VTR_LOG(" %8s", device_ctx.rr_nodes.node_type_string(node_id));
+
+    //Direction
+    if (node_type == e_rr_type::CHANX || node_type == e_rr_type::CHANY) {
+        VTR_LOG(" %12s", device_ctx.rr_nodes.node_direction_string(node_id));
+    } else {
+        VTR_LOG(" %12s", "N/A");
+    }
+
+    //Side
+    if (node_type == e_rr_type::IPIN || node_type == e_rr_type::OPIN) {
+        VTR_LOG(" %7s", device_ctx.rr_nodes.node_side_string(node_id));
+    } else {
+        VTR_LOG(" %7s", "N/A");
+    }
+
+    //PTC number
+    VTR_LOG(" %7d", device_ctx.rr_nodes.node_ptc_num(node_id));
+
+    //X_low
+    VTR_LOG(" %7d", device_ctx.rr_nodes.node_xlow(node_id));
+
+    //Y_low
+    VTR_LOG(" %7d", device_ctx.rr_nodes.node_ylow(node_id));
+
+    //X_high
+    VTR_LOG(" %7d", device_ctx.rr_nodes.node_xhigh(node_id));
+
+    //Y_high
+    VTR_LOG(" %7d", device_ctx.rr_nodes.node_yhigh(node_id));
+
+    VTR_LOG("\n");
+
+    fflush(stdout);
+}

vpr/src/route/overuse_report.h

@@ -0,0 +1,8 @@
+#pragma once
+
+#include "rr_graph_storage.h"
+#include <map>
+
+void log_overused_nodes_status(int max_logged_overused_rr_nodes);
+void report_overused_nodes();
+void generate_overused_nodes_to_congested_net_lookup(std::map<RRNodeId, std::set<ClusterNetId>>& nodes_to_nets_lookup);

vpr/src/route/route_timing.cpp

@@ -39,6 +39,7 @@
 #include "router_lookahead_map.h"
 
 #include "tatum/TimingReporter.hpp"
+#include "overuse_report.h"
 
 #define CONGESTED_SLOPE_VAL -0.04
 
@@ -65,6 +66,9 @@ struct RoutingMetrics {
 //Note only enables debug output if compiled with VTR_ENABLE_DEBUG_LOGGING defined
 bool f_router_debug = false;
 
+//Count the number of times the router has failed
+static int num_routing_failed = 0;
+
 /******************** Subroutines local to route_timing.c ********************/
 
 template<typename ConnectionRouter>
@@ -131,6 +135,8 @@ static void print_route_status(int itry,
                                std::shared_ptr<const SetupHoldTimingInfo> timing_info,
                                float est_success_iteration);
 
+static void print_overused_nodes_status(const t_router_opts& router_opts, const OveruseInfo& overuse_info);
+
 static void print_router_criticality_histogram(const SetupTimingInfo& timing_info,
                                                const ClusteredPinAtomPinsLookup& netlist_pin_lookup);
 
@@ -715,6 +721,12 @@ bool try_timing_driven_route_tmpl(const t_router_opts& router_opts,
         VTR_LOG("Successfully routed after %d routing iterations.\n", itry);
     } else {
         VTR_LOG("Routing failed.\n");
+
+        //If the routing fails, print the overused info
+        print_overused_nodes_status(router_opts, overuse_info);
+
+        ++num_routing_failed;
+
 #ifdef VTR_ENABLE_DEBUG_LOGGING
         if (f_router_debug) print_invalid_routing_info();
 #endif
@@ -1669,6 +1681,24 @@ static void print_route_status(int itry, double elapsed_sec, float pres_fac, int
     fflush(stdout);
 }
 
+static void print_overused_nodes_status(const t_router_opts& router_opts, const OveruseInfo& overuse_info) {
+    //Print the index of this routing failure
+    VTR_LOG("\nFailed routing attempt #%d\n", num_routing_failed);
+
+    size_t num_overused = overuse_info.overused_nodes;
+    size_t max_logged_overused_rr_nodes = router_opts.max_logged_overused_rr_nodes;
+
+    //Overused nodes info logging upper limit
+    VTR_LOG("Total number of overused nodes: %d\n", num_overused);
+    if (num_overused > max_logged_overused_rr_nodes) {
+        VTR_LOG("Total number of overused nodes is larger than the logging limit (%d).\n", max_logged_overused_rr_nodes);
+        VTR_LOG("Displaying the first %d entries.\n", max_logged_overused_rr_nodes);
+    }
+
+    log_overused_nodes_status(max_logged_overused_rr_nodes);
+    VTR_LOG("\n");
+}
+
 static void print_router_criticality_histogram(const SetupTimingInfo& timing_info, const ClusteredPinAtomPinsLookup& netlist_pin_lookup) {
     print_histogram(create_criticality_histogram(timing_info, netlist_pin_lookup, 10));
 }