This blog entry covers some some efficient ways to automate the reporting work when trying to debug the compile time spent on specific phases in a design, for example, the time spent loading design constraints, the duration for each command, or even runtime differences across multiple designs.
It also gives advice on reading the results.
Three powerful scripts will be covered which address these use-cases.
Before profiling the constraints analysis time, you should be aware of the recommended sequence requirements for when the constraints are being written. These are based on the precedence on each type of constraint.
The optimal ordering for the timing constraints is as follows:
With the exception of set_bus_skew, the constraint types with higher numbers have a higher priority and are likely to override the previous constraints types. As a result, the covered paths will only be analyzed by the constraints with higher priority.
To reduce the time spent parsing the constraints, the constraints should be precise and get scoped to the targets as much as possible. For more information, you can refer to the “Recommended Constraints Sequence” section of (UG949).
In a complicated design, there are always many constraints files being added, including the IP constraints and user added constraints.
To get a summary table of these constraints, the script report_constraints can be called in a Tcl shell to report the number of constraints Tcl commands (both timing and non-timing) used inside an XDC or DCP file.
It can also provide a coarse estimate on the number of timing updates generated based on the constraints ordering.
You will need to source this script using the syntax below:
1. Report number of timing constraints by XDC file names.
This example shows the number of each type of constraint in four individual XDC files: 2. Report both timing and non-timing constraints with the -all option.
The non-timing commands include all of the Vivado commands being used, such as get_pins, get_clocks, etc.
3. Report the verbose constraints information and constraint details:
4. Report timing graph:
The script can estimate the impact of the commands on the timing graph, and it can help to understand whether the constraints are optimally ordered or not, by reporting the number of estimated timing updates (partial or full updates) with "Estimated updates: xxx".
A timing update is detected when the flow of commands goes from "Invalidate timing" to "Require valid timing".
By using this script, you should be able to see how many times those constraints are updated and loaded, and determine if constraints have duplicate definitions or a valid status.
Note: the reported number of timing updates is only a gross estimate. However, it does provide visibility on whether timing constraints are optimally ordered or not.
When debugging the runtime issue of a specific design in the Vivado shell based on executing the targeted operations, the profiler file “profiler.tcl” can be sourced in a Vivado Tcl shell to do the following:
Profile Vivado commands or user procs
Perform runtime analysis to help understand the bottlenecks in terms of runtime
Analyze the number of times a specific command or proc is called (in order to improve script efficiency)
The profiler report includes four sections inside the output log file:
Detailed runtime for all profiled commands
Note: The output format can be tabular (default) or CSV (profiler summary -csv).
Syntax: % profiler Usage: profiler <sub-command> [<arguments>] Where <sub-command> is: ? - This help message add - Add Vivado command(s) to the profiler (-help) configure - Configure the profiler (-help) remove - Remove Vivado command(s) from the profiler reset - Reset the profiler start - Start the profiler (-help) status - Status of the profiler stop - Stop the profiler summary - Return the profiler summary (-help) time - Profile the inline Tcl code (-help) version - Version of the profiler
The table columns are counted for a statistic result for overall time spent.
The meaning for each column is:
Name for the command/phase collected
number of times the command has been called
percentage of the runtime taken by this command relative to the total runtime
It is easy to determine which commands contribute most of the runtime.
As shown in the figure below, the get_clocks and get_nets commands have been called for multiple times and taken up most of the runtime.
Section 2: Top-50 Runtimes
The 50 worst runtimes are reported and sorted from the worst to the best. It provides a quick summary of the commands that had the worst impact on the runtime.
The columns are: • ID (can be used to find the command inside the log file): match the order in which the command has been processed by Vivado. ID 1 was the first command run, ID 2 the second and so on. • runtime: runtime in ms • command: command run by Vivado The screen capture below shows part of the 50 lines of the list:
Section 3: Top 10 collections
This section includes the 10 largest collections of objects that are returned by any of the profiled commands. It includes for each collection: • size: size of the collection • count: number of collections with the same size • total: total number of objects (size * count) • commands: list of commands that returned the collection
Section 4: Details Report
This section includes all of the verbose information for each command been profiled, ordered from the first to the last.
It includes command ID, runtime, command, and the number of objects for each command:
Example use case:
1. Improve constraints efficiency
Profiling a Tcl script can be useful to understand how the runtime is spent and how many times Vivado commands or user procs are called.
It helps to restructure runtime critical Tcl code and improve runtime significantly.
The example below compares the runtime difference and number of times the Vivado commands are called between two equivalent versions of a Tcl loop:
The results show that 75216 of the calls were for the get_property command, which accounts for most of the runtime.
So we can move the “get_property” command outside of the loop to save time.
After code structuring, the total time spent is reduced by 95%:
2. Compare runtime across multiple designs:
You might encounter time differences in the netlist loading or constraints parsing across different Vivado releases.
The example below shows how the runtime is spent across 2 different Vivado runs.
This method is helpful to debug the number of calls for each command spent across the releases.
In this case, the problematic release run had doubled the calls for each command.
When you need to compare the runtime of Vivado commands across multiple phases on multiple designs, the script vivadoRuntime can be used to extract some debug information from the runtime/memory/checksum/timing/congestion/command lines inside a Vivado log file.
It can also be used to compare the information between multiple Vivado log files.
The script can also be used to extract custom runtimes if they are properly formatted.
It extracts information from a text log file, and can be executed in a shell prompt.