UPGRADE YOUR BROWSER

We have detected your current browser version is not the latest one. Xilinx.com uses the latest web technologies to bring you the best online experience possible. Please upgrade to a Xilinx.com supported browser:Chrome, Firefox, Internet Explorer 11, Safari. Thank you!

cancel
Showing results for 
Search instead for 
Did you mean: 

Saving Compile Time Series 4: Profiling Compile Time with Tcl scripts

Xilinx Employee
Xilinx Employee
1 0 227

Original Author: David Perforque

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.

report_constraints:

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:

1. set_disable_timing
2. set_case_analysis
3. create_clock
4. set_clock_sense
5. create_generated_clock
6. set_input_delay / set_output_delay
7. set_min_delay / set_max_delay
8. set_false_path
9. set_multicycle_path
10. set_bus_skew

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:

Syntax:
% report_constraints -help
Usage: report_constraints
            [<pattern>][-xdc <pattern>]
            [-dcp <checkpoint>]
            [-all][-property][-no_src_info]
            [-file <filename>]
            [-append]
            [-csv]
            [-details][-full_details]
            [-timing_graph]
            [-verbose|-v]
            [-help|-h]

Examples:

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:
a.png 
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.


 b.png
3. Report the verbose constraints information and constraint details:

 c.png

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".

 d.png
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.

 

Profiler:

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:

  1. Profile Vivado commands or user procs
  2. Perform runtime analysis to help understand the bottlenecks in terms of runtime
  3. 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:

  1. Summary table
  2. Top-50 runtimes
  3. Top-10 collections
  4. 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

Use Example:
% source profiler.tcl
% profiler add *
% profiler start
% open_checkpoint design.dcp
% profiler stop
% profiler summary
% profiler summary -log profiler.log
% profiler summary -log profiler.csv -csv

Report Section Details:

Section 1: Summary Table

The table columns are counted for a statistic result for overall time spent.

The meaning for each column is:

Command

Name for the command/phase collected

min

minimum runtime

max

maximum runtime

avg

average runtime

total

cumulative runtime

ncalls

number of times the command has been called

%runtime

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.

e.png

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:

f.png

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

g.png

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:

h.png

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:

Before structuring:

i.png

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%:

j.png


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.


Normal Release:

k.png

Problematic release:

l.png

vivadoRuntime:


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.

Syntax:
% vivadoRuntime -h
  Usage: vivadoRuntime
                  [<vivadoLog(s)>][-log <vivadoLog(s)>][-input <vivadoLog(s)>]
                  [-file <filename>|-output <filename>]                     
                  [-append]                                                 
                  [-csv]                                                    
                  [-cpu][-elapsed][-checksum][-peakmem][-gainmem][-wns][-tns][-whs][-ths][-congestion][-cmdline]
                  [-runtime][-timing][-memory][-all]                                                          
                  [-split]                                                                                    
                  [-reference <num>]                                                                          
                  [-seconds][-duration]                                                                       
                  [-loose_match]                                                                              
                  [-diff]                                                                                     
                  [-show_unreported]                                                                          
                  [-hide_steps]                                                                               
                  [-transpose]                                                                                
                  [-vivado_only][-custom_only]                                                                
                  [-verbose|-v]                                                                               
                  [-help|-h]                                                                                  
 

Example:


This example shows the table for comparing multiple log files for each phase in the Vivado flow.


% source vivadoRuntime
% vivadoRuntime ./*/*.log

m.png

 

Summary:

By using these 3 powerful scripts, you can quickly identify the bottleneck in your constraints and run phases, ultimately helping you to save on runtime.