From cfd3a52a3c25580741b1d03fd59028b8eab8e6d6 Mon Sep 17 00:00:00 2001 From: rowanG077 Date: Fri, 16 Jun 2023 13:20:36 +0200 Subject: [PATCH] tmg: add timing_report --- common/kernel/command.cc | 2 +- common/kernel/context.h | 7 +- common/kernel/nextpnr_types.h | 5 +- common/kernel/{report.cc => report_json.cc} | 15 +- common/kernel/timing.cc | 12 - common/kernel/timing_old.cc | 10 +- common/kernel/timing_report.cc | 365 ++++++++++++++++++++ 7 files changed, 389 insertions(+), 27 deletions(-) rename common/kernel/{report.cc => report_json.cc} (94%) create mode 100644 common/kernel/timing_report.cc diff --git a/common/kernel/command.cc b/common/kernel/command.cc index 6e94b300..aa070450 100644 --- a/common/kernel/command.cc +++ b/common/kernel/command.cc @@ -505,7 +505,7 @@ int CommandHandler::executeMain(std::unique_ptr ctx) std::ofstream f(filename); if (!f) log_error("Failed to open report file '%s' for writing.\n", filename.c_str()); - ctx->writeReport(f); + ctx->writeJsonReport(f); } #ifndef NO_PYTHON diff --git a/common/kernel/context.h b/common/kernel/context.h index b4e7920d..1a5529ce 100644 --- a/common/kernel/context.h +++ b/common/kernel/context.h @@ -99,8 +99,11 @@ struct Context : Arch, DeterministicRNG // -------------------------------------------------------------- - // provided by report.cc - void writeReport(std::ostream &out) const; + // provided by report_json.cc + void writeJsonReport(std::ostream &out) const; + + // provided by timing_report.cc + void log_timing_results(bool print_histogram, bool print_path, bool warn_on_failure); // -------------------------------------------------------------- uint32_t checksum() const; diff --git a/common/kernel/nextpnr_types.h b/common/kernel/nextpnr_types.h index c88dcc9c..3b053f61 100644 --- a/common/kernel/nextpnr_types.h +++ b/common/kernel/nextpnr_types.h @@ -362,8 +362,11 @@ struct TimingResult // Detailed net timing data dict> detailed_net_timings; + // clock to clock delays + dict, delay_t> clock_delays; + // Histogram of delays - dict delay_frequency; + dict slack_histogram; }; // Represents the contents of a non-leaf cell in a design diff --git a/common/kernel/report.cc b/common/kernel/report_json.cc similarity index 94% rename from common/kernel/report.cc rename to common/kernel/report_json.cc index 38cf9d0a..f95dad79 100644 --- a/common/kernel/report.cc +++ b/common/kernel/report_json.cc @@ -44,14 +44,14 @@ dict> get_utilization(const Context *ctx) static std::string clock_event_name(const Context *ctx, const ClockEvent &e) { std::string value; - if (e.clock == ctx->id("$async$")) + if (e.clock == IdString() || e.clock == ctx->id("$async$")) value = std::string(""); else value = (e.edge == FALLING_EDGE ? std::string("negedge ") : std::string("posedge ")) + e.clock.str(ctx); return value; }; -static Json::array report_critical_paths(const Context *ctx) +static Json::array json_report_critical_paths(const Context *ctx) { auto report_critical_path = [ctx](const CriticalPath &report) { @@ -118,7 +118,7 @@ static Json::array report_critical_paths(const Context *ctx) return critPathsJson; } -static Json::array report_detailed_net_timings(const Context *ctx) +static Json::array json_report_detailed_net_timings(const Context *ctx) { auto detailedNetTimingsJson = Json::array(); @@ -219,7 +219,7 @@ Report JSON structure: } */ -void Context::writeReport(std::ostream &out) const +void Context::writeJsonReport(std::ostream &out) const { auto util = get_utilization(this); dict util_json; @@ -238,10 +238,13 @@ void Context::writeReport(std::ostream &out) const } Json::object jsonRoot{ - {"utilization", util_json}, {"fmax", fmax_json}, {"critical_paths", report_critical_paths(this)}}; + { "utilization", util_json }, + { "fmax", fmax_json }, + { "critical_paths", json_report_critical_paths(this) } + }; if (detailed_timing_report) { - jsonRoot["detailed_net_timings"] = report_detailed_net_timings(this); + jsonRoot["detailed_net_timings"] = json_report_detailed_net_timings(this); } out << Json(jsonRoot).dump() << std::endl; diff --git a/common/kernel/timing.cc b/common/kernel/timing.cc index b0c7980e..9cfc397f 100644 --- a/common/kernel/timing.cc +++ b/common/kernel/timing.cc @@ -1043,18 +1043,6 @@ void TimingAnalyser::build_crit_path_reports() clock_delays_ctx = clock_delays; } -static std::string clock_event_name(const Context *ctx, const ClockDomainKey &e, int field_width = 0) -{ - std::string value; - if (e.clock == IdString() || e.clock == ctx->id("$async$")) - value = std::string(""); - else - value = (e.edge == FALLING_EDGE ? std::string("negedge ") : std::string("posedge ")) + e.clock.str(ctx); - if (int(value.length()) < field_width) - value.insert(value.length(), field_width - int(value.length()), ' '); - return value; -}; - void TimingAnalyser::build_slack_histogram_report() { auto& slack_histogram = ctx->timing_result.slack_histogram; diff --git a/common/kernel/timing_old.cc b/common/kernel/timing_old.cc index 080bbf59..5632203b 100644 --- a/common/kernel/timing_old.cc +++ b/common/kernel/timing_old.cc @@ -21,13 +21,13 @@ #include #include #include +#include +#include #include #include #include "log.h" #include "timing.h" #include "util.h" -#include -#include NEXTPNR_NAMESPACE_BEGIN @@ -622,14 +622,14 @@ void timing_analysis(Context *ctx, bool print_histogram, bool print_fmax, bool p timingAnalyser.setup(true, true, true, true); log("start timingAnalyser.print_report();\n\n"); - // timingAnalyser.print_report(); + ctx->log_timing_results(true, true, true); log("end timingAnalyser.print_report();\n\n"); std::string filename = "timingAnalyser.json"; std::ofstream f(filename); if (!f) log_error("Failed to open report file '%s' for writing.\n", filename.c_str()); - ctx->writeReport(f); + ctx->writeJsonReport(f); bool report_critical_paths = print_path || print_fmax || update_results; @@ -1041,7 +1041,7 @@ void timing_analysis(Context *ctx, bool print_histogram, bool print_fmax, bool p std::ofstream f2(filename2); if (!f) log_error("Failed to open report file '%s' for writing.\n", filename.c_str()); - ctx->writeReport(f2); + ctx->writeJsonReport(f2); } NEXTPNR_NAMESPACE_END diff --git a/common/kernel/timing_report.cc b/common/kernel/timing_report.cc new file mode 100644 index 00000000..969e848c --- /dev/null +++ b/common/kernel/timing_report.cc @@ -0,0 +1,365 @@ +/* + * nextpnr -- Next Generation Place and Route + * + * Copyright (C) 2023 rowanG077 + * + * Permission to use, copy, modify, and/or distribute this software for any + * purpose with or without fee is hereby granted, provided that the above + * copyright notice and this permission notice appear in all copies. + * + * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES + * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF + * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR + * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES + * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN + * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF + * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. + * + */ + +#include "log.h" +#include "nextpnr.h" +#include "util.h" + +NEXTPNR_NAMESPACE_BEGIN + +static std::string clock_event_name(const Context *ctx, const ClockEvent &e, int field_width = 0) +{ + std::string value; + if (e.clock == IdString() || e.clock == ctx->id("$async$")) + value = std::string(""); + else + value = (e.edge == FALLING_EDGE ? std::string("negedge ") : std::string("posedge ")) + e.clock.str(ctx); + if (int(value.length()) < field_width) + value.insert(value.length(), field_width - int(value.length()), ' '); + return value; +}; + +static void log_crit_paths(const Context *ctx) +{ + static auto print_net_source = [ctx](const NetInfo *net) { + // Check if this net is annotated with a source list + auto sources = net->attrs.find(ctx->id("src")); + if (sources == net->attrs.end()) { + // No sources for this net, can't print anything + return; + } + + // Sources are separated by pipe characters. + // There is no guaranteed ordering on sources, so we just print all + auto sourcelist = sources->second.as_string(); + std::vector source_entries; + size_t current = 0, prev = 0; + while ((current = sourcelist.find("|", prev)) != std::string::npos) { + source_entries.emplace_back(sourcelist.substr(prev, current - prev)); + prev = current + 1; + } + // Ensure we emplace the final entry + source_entries.emplace_back(sourcelist.substr(prev, current - prev)); + + // Iterate and print our source list at the correct indentation level + log_info(" Defined in:\n"); + for (auto entry : source_entries) { + log_info(" %s\n", entry.c_str()); + } + }; + + // A helper function for reporting one critical path + auto print_path_report = [ctx](const CriticalPath &path) { + delay_t total = 0, logic_total = 0, route_total = 0; + + log_info("curr total\n"); + for (const auto &segment : path.segments) { + + total += segment.delay; + + if (segment.type == CriticalPath::Segment::Type::CLK_TO_Q || + segment.type == CriticalPath::Segment::Type::SOURCE || + segment.type == CriticalPath::Segment::Type::LOGIC || + segment.type == CriticalPath::Segment::Type::SETUP) { + logic_total += segment.delay; + + const std::string type_name = + (segment.type == CriticalPath::Segment::Type::SETUP) ? "Setup" : "Source"; + + log_info("%4.1f %4.1f %s %s.%s\n", ctx->getDelayNS(segment.delay), ctx->getDelayNS(total), + type_name.c_str(), segment.to.first.c_str(ctx), segment.to.second.c_str(ctx)); + } else if (segment.type == CriticalPath::Segment::Type::ROUTING) { + route_total += segment.delay; + + const auto &driver = ctx->cells.at(segment.from.first); + const auto &sink = ctx->cells.at(segment.to.first); + + auto driver_loc = ctx->getBelLocation(driver->bel); + auto sink_loc = ctx->getBelLocation(sink->bel); + + log_info("%4.1f %4.1f Net %s (%d,%d) -> (%d,%d)\n", ctx->getDelayNS(segment.delay), + ctx->getDelayNS(total), segment.net.c_str(ctx), + driver_loc.x, driver_loc.y, sink_loc.x, sink_loc.y); + log_info(" Sink %s.%s\n", segment.to.first.c_str(ctx), segment.to.second.c_str(ctx)); + + const NetInfo *net = ctx->nets.at(segment.net).get(); + + if (ctx->verbose) { + + PortRef sink_ref; + sink_ref.cell = sink.get(); + sink_ref.port = segment.to.second; + + auto driver_wire = ctx->getNetinfoSourceWire(net); + auto sink_wire = ctx->getNetinfoSinkWire(net, sink_ref, 0); + log_info(" prediction: %f ns estimate: %f ns\n", + ctx->getDelayNS(ctx->predictArcDelay(net, sink_ref)), + ctx->getDelayNS(ctx->estimateDelay(driver_wire, sink_wire))); + auto cursor = sink_wire; + delay_t delay; + while (driver_wire != cursor) { +#ifdef ARCH_ECP5 + if (net->is_global) + break; +#endif + auto it = net->wires.find(cursor); + assert(it != net->wires.end()); + auto pip = it->second.pip; + NPNR_ASSERT(pip != PipId()); + delay = ctx->getPipDelay(pip).maxDelay(); + log_info(" %1.3f %s\n", ctx->getDelayNS(delay), ctx->nameOfPip(pip)); + cursor = ctx->getPipSrcWire(pip); + } + } + + if (!ctx->disable_critical_path_source_print) { + print_net_source(net); + } + } + } + log_info("%.1f ns logic, %.1f ns routing\n", ctx->getDelayNS(logic_total), ctx->getDelayNS(route_total)); + }; + + // Single domain paths + for (auto &clock : ctx->timing_result.clock_paths) { + log_break(); + std::string start = clock.second.clock_pair.start.edge == FALLING_EDGE ? std::string("negedge") + : std::string("posedge"); + std::string end = + clock.second.clock_pair.end.edge == FALLING_EDGE ? std::string("negedge") : std::string("posedge"); + log_info("Critical path report for clock '%s' (%s -> %s):\n", clock.first.c_str(ctx), start.c_str(), + end.c_str()); + auto &report = clock.second; + print_path_report(report); + } + + // Cross-domain paths + for (auto &report : ctx->timing_result.xclock_paths) { + log_break(); + std::string start = clock_event_name(ctx, report.clock_pair.start); + std::string end = clock_event_name(ctx, report.clock_pair.end); + log_info("Critical path report for cross-domain path '%s' -> '%s':\n", start.c_str(), end.c_str()); + print_path_report(report); + } +}; + +static void log_fmax(Context *ctx, bool warn_on_failure) +{ + log_break(); + + unsigned max_width = 0; + for (auto &clock : ctx->timing_result.clock_paths) + max_width = std::max(max_width, clock.first.str(ctx).size()); + + for (auto &clock : ctx->timing_result.clock_paths) { + const auto &clock_name = clock.first.str(ctx); + const int width = max_width - clock_name.size(); + + float fmax = ctx->timing_result.clock_fmax[clock.first].achieved; + float target = ctx->timing_result.clock_fmax[clock.first].constraint; + bool passed = target < fmax; + + if (!warn_on_failure || passed) + log_info("Max frequency for clock %*s'%s': %.02f MHz (%s at %.02f MHz)\n", width, "", + clock_name.c_str(), fmax, passed ? "PASS" : "FAIL", target); + else if (bool_or_default(ctx->settings, ctx->id("timing/allowFail"), false)) + log_warning("Max frequency for clock %*s'%s': %.02f MHz (%s at %.02f MHz)\n", width, "", + clock_name.c_str(), fmax, passed ? "PASS" : "FAIL", target); + else + log_nonfatal_error("Max frequency for clock %*s'%s': %.02f MHz (%s at %.02f MHz)\n", width, "", + clock_name.c_str(), fmax, passed ? "PASS" : "FAIL", target); + } + log_break(); + + + // Clock to clock delays for xpaths + dict xclock_delays; + for (auto &report : ctx->timing_result.xclock_paths) { + const auto &clock1_name = report.clock_pair.start.clock; + const auto &clock2_name = report.clock_pair.end.clock; + + const auto key = std::make_pair(clock1_name, clock2_name); + if (ctx->timing_result.clock_delays.count(key)) { + xclock_delays[report.clock_pair] = ctx->timing_result.clock_delays.at(key); + } + } + + unsigned max_width_xca = 0; + unsigned max_width_xcb = 0; + for (auto &report : ctx->timing_result.xclock_paths) { + max_width_xca = std::max((unsigned)clock_event_name(ctx, report.clock_pair.start).length(), max_width_xca); + max_width_xcb = std::max((unsigned)clock_event_name(ctx, report.clock_pair.end).length(), max_width_xcb); + } + + // Check and report xpath delays for related clocks + if (!ctx->timing_result.xclock_paths.empty()) { + for (auto &report : ctx->timing_result.xclock_paths) { + const auto &clock_a = report.clock_pair.start.clock; + const auto &clock_b = report.clock_pair.end.clock; + + const auto key = std::make_pair(clock_a, clock_b); + if (!ctx->timing_result.clock_delays.count(key)) { + continue; + } + + delay_t path_delay = 0; + for (const auto &segment : report.segments) { + path_delay += segment.delay; + } + + // Compensate path delay for clock-to-clock delay. If the + // result is negative then only the latter matters. Otherwise + // the compensated path delay is taken. + auto clock_delay = ctx->timing_result.clock_delays.at(key); + path_delay -= clock_delay; + + float fmax = std::numeric_limits::infinity(); + if (path_delay < 0) { + fmax = 1e3f / ctx->getDelayNS(clock_delay); + } else if (path_delay > 0) { + fmax = 1e3f / ctx->getDelayNS(path_delay); + } + + // Both clocks are related so they should have the same + // frequency. However, they may get different constraints from + // user input. In case of only one constraint preset take it, + // otherwise get the worst case (min.) + float target; + auto &clock_fmax = ctx->timing_result.clock_fmax; + if (clock_fmax.count(clock_a) && !clock_fmax.count(clock_b)) { + target = clock_fmax.at(clock_a).constraint; + } else if (!clock_fmax.count(clock_a) && clock_fmax.count(clock_b)) { + target = clock_fmax.at(clock_b).constraint; + } else { + target = std::min(clock_fmax.at(clock_a).constraint, clock_fmax.at(clock_b).constraint); + } + + bool passed = target < fmax; + + auto ev_a = clock_event_name(ctx, report.clock_pair.start, max_width_xca); + auto ev_b = clock_event_name(ctx, report.clock_pair.end, max_width_xcb); + + if (!warn_on_failure || passed) + log_info("Max frequency for %s -> %s: %.02f MHz (%s at %.02f MHz)\n", ev_a.c_str(), ev_b.c_str(), + fmax, passed ? "PASS" : "FAIL", target); + else if (bool_or_default(ctx->settings, ctx->id("timing/allowFail"), false) || + bool_or_default(ctx->settings, ctx->id("timing/ignoreRelClk"), false)) + log_warning("Max frequency for %s -> %s: %.02f MHz (%s at %.02f MHz)\n", ev_a.c_str(), + ev_b.c_str(), fmax, passed ? "PASS" : "FAIL", target); + else + log_nonfatal_error("Max frequency for %s -> %s: %.02f MHz (%s at %.02f MHz)\n", ev_a.c_str(), + ev_b.c_str(), fmax, passed ? "PASS" : "FAIL", target); + } + log_break(); + } + + // Report clock delays for xpaths + if (!ctx->timing_result.clock_delays.empty()) { + for (auto &pair : xclock_delays) { + auto ev_a = clock_event_name(ctx, pair.first.start, max_width_xca); + auto ev_b = clock_event_name(ctx, pair.first.end, max_width_xcb); + + delay_t delay = pair.second; + if (pair.first.start.edge != pair.first.end.edge) { + delay /= 2; + } + + log_info("Clock to clock delay %s -> %s: %0.02f ns\n", ev_a.c_str(), ev_b.c_str(), + ctx->getDelayNS(delay)); + } + + log_break(); + } + + for (auto &eclock : ctx->timing_result.empty_paths) { + if (eclock != IdString()) + log_info("Clock '%s' has no interior paths\n", eclock.c_str(ctx)); + } + log_break(); + + int start_field_width = 0, end_field_width = 0; + for (auto &report : ctx->timing_result.xclock_paths) { + start_field_width = std::max((int)clock_event_name(ctx, report.clock_pair.start).length(), start_field_width); + end_field_width = std::max((int)clock_event_name(ctx, report.clock_pair.end).length(), end_field_width); + } + + for (auto &report : ctx->timing_result.xclock_paths) { + const ClockEvent &a = report.clock_pair.start; + const ClockEvent &b = report.clock_pair.end; + delay_t path_delay = 0; + for (const auto &segment : report.segments) { + path_delay += segment.delay; + } + auto ev_a = clock_event_name(ctx, a, start_field_width), ev_b = clock_event_name(ctx, b, end_field_width); + log_info("Max delay %s -> %s: %0.02f ns\n", ev_a.c_str(), ev_b.c_str(), ctx->getDelayNS(path_delay)); + } + log_break(); +} + +static void log_histogram(Context *ctx) { + unsigned num_bins = 20; + unsigned bar_width = 60; + + int min_slack = INT_MAX; + int max_slack = INT_MIN; + + for (const auto &i : ctx->timing_result.slack_histogram) { + if (i.first < min_slack) + min_slack = i.first; + if (i.first > max_slack) + max_slack = i.first; + } + + auto bin_size = std::max(1, ceil((max_slack - min_slack + 1) / float(num_bins))); + std::vector bins(num_bins); + unsigned max_freq = 0; + for (const auto &i : ctx->timing_result.slack_histogram) { + int bin_idx = int((i.first - min_slack) / bin_size); + if (bin_idx < 0) + bin_idx = 0; + else if (bin_idx >= int(num_bins)) + bin_idx = num_bins - 1; + auto &bin = bins.at(bin_idx); + bin += i.second; + max_freq = std::max(max_freq, bin); + } + bar_width = std::min(bar_width, max_freq); + + log_break(); + log_info("Slack histogram:\n"); + log_info(" legend: * represents %d endpoint(s)\n", max_freq / bar_width); + log_info(" + represents [1,%d) endpoint(s)\n", max_freq / bar_width); + for (unsigned i = 0; i < num_bins; ++i) + log_info("[%6d, %6d) |%s%c\n", min_slack + bin_size * i, min_slack + bin_size * (i + 1), + std::string(bins[i] * bar_width / max_freq, '*').c_str(), + (bins[i] * bar_width) % max_freq > 0 ? '+' : ' '); +} + +void Context::log_timing_results(bool print_histogram, bool print_path, bool warn_on_failure) +{ + if (print_path) + log_crit_paths(this); + + log_fmax(this, warn_on_failure); + + if (print_histogram) + log_histogram(this); +} + +NEXTPNR_NAMESPACE_END