Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Improve clarity of timing report critical path format #551

Open
bl0x opened this issue Jan 13, 2021 · 5 comments
Open

Improve clarity of timing report critical path format #551

bl0x opened this issue Jan 13, 2021 · 5 comments

Comments

@bl0x
Copy link

bl0x commented Jan 13, 2021 •
edited
Loading

The current output format of the timing report showing the critical path can be improved in terms of clarity.

Issues with current output format

  • A lot of information is written multiple times
  • It is difficult to pick out the block names right away
  • It is hard to spot where most of the time is spent at first glance
  • Signal names are not aligned well, so don't easily guide the eye

Related issue is perhaps #470.

Example for current output format

Info: Critical path report for clock 'clock_$glb_clk' (posedge -> posedge):
Info: curr total
Info:  0.8  0.8  Source clock_receiver.sp.track_stream.add_full_SB_DFFSS_Q_D_SB_LUT4_O_LC.O
Info:  1.9  2.7    Net clock_receiver.sp.track_stream.add_full budget 0.000000 ns (7,30) -> (9,29)
Info:                Sink clock_receiver.sp.track_stream.counter_add_full_SB_LUT4_O_15_LC.I2
Info:  0.6  3.2  Source clock_receiver.sp.track_stream.counter_add_full_SB_LUT4_O_15_LC.O
Info:  1.9  5.1    Net clock_receiver.sp.track_stream.counter_add_full[0] budget 0.000000 ns (9,29) -> (7,28)
Info:                Sink clock_receiver.sp.track_stream.counter_add_half_SB_CARRY_I0_14$CARRY.I2
Info:  0.3  5.5  Source clock_receiver.sp.track_stream.counter_add_half_SB_CARRY_I0_14$CARRY.COUT
Info:  0.4  5.8    Net clock_receiver.sp.track_stream.counter_add_SB_LUT4_O_I3[1] budget 0.380000 ns (7,28) -> (7,28)
Info:                Sink clock_receiver.sp.track_stream.counter_add_SB_LUT4_O_8_LC.I3
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.5  6.3  Source clock_receiver.sp.track_stream.counter_add_SB_LUT4_O_8_LC.O
Info:  0.9  7.2    Net clock_receiver.sp.track_stream.counter_add[1] budget 0.000000 ns (7,28) -> (6,27)
Info:                Sink clock_receiver.sp.track_stream.counter_next_SB_LUT4_O_8_LC.I1
Info:  0.4  7.5  Source clock_receiver.sp.track_stream.counter_next_SB_LUT4_O_8_LC.COUT
Info:  0.4  7.9    Net clock_receiver.sp.track_stream.counter_next_SB_LUT4_O_I3[2] budget 0.380000 ns (6,27) -> (6,27)
Info:                Sink clock_receiver.sp.track_stream.counter_next_SB_LUT4_O_7_LC.I3
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.5  8.4  Source clock_receiver.sp.track_stream.counter_next_SB_LUT4_O_7_LC.O
Info:  1.9 10.3    Net clock_receiver.sp.track_stream.counter_next[2] budget 0.576000 ns (6,27) -> (9,26)
Info:                Sink clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_4$CARRY.I1
Info:  0.4 10.7  Source clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_4$CARRY.COUT
Info:  0.0 10.7    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[3] budget 0.000000 ns (9,26) -> (9,26)
Info:                Sink clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_3$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 10.8  Source clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_3$CARRY.COUT
Info:  0.0 10.8    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[4] budget 0.000000 ns (9,26) -> (9,26)
Info:                Sink clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_2$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 11.0  Source clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_2$CARRY.COUT
Info:  0.0 11.0    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[5] budget 0.000000 ns (9,26) -> (9,26)
Info:                Sink clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_1$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 11.2  Source clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_1$CARRY.COUT
Info:  0.0 11.2    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[6] budget 0.000000 ns (9,26) -> (9,26)
Info:                Sink clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 11.4  Source clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO$CARRY.COUT
Info:  0.0 11.4    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[7] budget 0.000000 ns (9,26) -> (9,26)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_2$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 11.6  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_2$CARRY.COUT
Info:  0.3 11.9    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[8] budget 0.290000 ns (9,26) -> (9,27)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_1$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 12.1  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_1$CARRY.COUT
Info:  0.0 12.1    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[9] budget 0.000000 ns (9,27) -> (9,27)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 12.2  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1$CARRY.COUT
Info:  0.0 12.2    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[10] budget 0.000000 ns (9,27) -> (9,27)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_9$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 12.4  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_9$CARRY.COUT
Info:  0.0 12.4    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[11] budget 0.000000 ns (9,27) -> (9,27)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_8$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 12.6  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_8$CARRY.COUT
Info:  0.0 12.6    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[12] budget 0.000000 ns (9,27) -> (9,27)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_7$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 12.8  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_7$CARRY.COUT
Info:  0.0 12.8    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[13] budget 0.000000 ns (9,27) -> (9,27)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_6$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 13.0  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_6$CARRY.COUT
Info:  0.0 13.0    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[14] budget 0.000000 ns (9,27) -> (9,27)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_5$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 13.2  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_5$CARRY.COUT
Info:  0.0 13.2    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[15] budget 0.000000 ns (9,27) -> (9,27)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_4$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 13.4  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_4$CARRY.COUT
Info:  0.3 13.7    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[16] budget 0.290000 ns (9,27) -> (9,28)
Info:                Sink clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_3$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 13.8  Source clock_receiver.sp.track_stream.target_period_SB_LUT4_I3_O_SB_CARRY_I1_3$CARRY.COUT
Info:  0.0 13.8    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[17] budget 0.000000 ns (9,28) -> (9,28)
Info:                Sink clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_6$CARRY.CIN
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.2 14.0  Source clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3_SB_CARRY_CO_6$CARRY.COUT
Info:  0.4 14.4    Net clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_I3[18] budget 0.380000 ns (9,28) -> (9,28)
Info:                Sink clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_LC.I3
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/arith_map.v:51.21-51.22
Info:  0.5 14.9  Source clock_receiver.sp.track_stream.counter_next_wrap_half_SB_LUT4_O_LC.O
Info:  1.9 16.8    Net clock_receiver.sp.track_stream.counter_next_wrap_half[18] budget 0.242000 ns (9,28) -> (7,31)
Info:                Sink clock_receiver.sp.track_stream.counter_next_wrapped_half_SB_LUT4_O_LC.I2
Info:  0.6 17.3  Source clock_receiver.sp.track_stream.counter_next_wrapped_half_SB_LUT4_O_LC.O
Info:  0.9 18.2    Net clock_receiver.sp.track_stream.counter_next_wrapped_half budget -0.065000 ns (7,31) -> (7,31)
Info:                Sink clock_receiver.sp.track_stream.counter_next_wrapped_half_SB_LUT4_I3_LC.I3
Info:  0.5 18.6  Source clock_receiver.sp.track_stream.counter_next_wrapped_half_SB_LUT4_I3_LC.O
Info:  1.3 20.0    Net clock_receiver.sp.track_stream.counter_next_wrapped_half_SB_LUT4_I3_O[3] budget 0.349000 ns (7,31) -> (10,31)
Info:                Sink clock_receiver.sp.track_stream.transitions_8_hist_SB_DFFE_Q_E_SB_LUT4_O_LC.I0
Info:                Defined in:
Info:                  /usr/bin/../share/yosys/ice40/cells_map.v:6.21-6.22
Info:  0.7 20.6  Source clock_receiver.sp.track_stream.transitions_8_hist_SB_DFFE_Q_E_SB_LUT4_O_LC.O
Info:  2.2 22.8    Net clock_receiver.sp.track_stream.transitions_8_hist_SB_DFFE_Q_E budget 0.237000 ns (10,31) -> (10,30)
Info:                Sink clock_receiver.sp.track_stream.transitions_8_hist_SB_DFFE_Q_D_SB_LUT4_O_LC.CEN
Info:  0.1 22.9  Setup clock_receiver.sp.track_stream.transitions_8_hist_SB_DFFE_Q_D_SB_LUT4_O_LC.CEN
Info: 8.4 ns logic, 14.5 ns routing

Example for improved (clearer) format

coord  block  block  logic    net  signal
------ ------ ------ -----  -----  ------------------------------
x7y30                  0.8    1.9  clock_receiver.sp.track_stream.add_full
x9y29                  0.6    1.9  clock_receiver.sp.track_stream.counter_add_full[0]
x7y28  LUT4            0.3    0.4  clock_receiver.sp.track_stream.counter_add[1]
x7y28                  0.5    0.9  clock_receiver.sp.track_stream.counter_add[1]
x6y27  LUT4            0.4    0.4  clock_receiver.sp.track_stream.counter_next[2]
x6y27                  0.5    1.9  clock_receiver.sp.track_stream.counter_next[2]
x9y26  LUT4            0.4    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[3]
x9y26  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[4]
x9y26  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[5]
x9y26  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[6]
x9y26  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[7]
x9y26  LUT4            0.2    0.3  clock_receiver.sp.track_stream.counter_next_wrap_half[8]
x9y27  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[9]
x9y27  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[10]
x9y27  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[11]
x9y27  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[12]
x9y27  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[13]
x9y27  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[14]
x9y27  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[15]
x9y27  LUT4            0.2    0.3  clock_receiver.sp.track_stream.counter_next_wrap_half[16]
x9y28  LUT4            0.2    0.0  clock_receiver.sp.track_stream.counter_next_wrap_half[17]
x9y28  LUT4            0.2    0.4  clock_receiver.sp.track_stream.counter_next_wrap_half[18]
x9y28                  0.5    1.9  clock_receiver.sp.track_stream.counter_next_wrap_half[18]
x7y31                  0.6    0.9  clock_receiver.sp.track_stream.counter_next_wrapped_half
x7y31  LUT4            0.5    1.3  clock_receiver.sp.track_stream.counter_next_wrapped_half[3]
x10y31 DFFE            0.7    2.2  clock_receiver.sp.track_stream.transitions_8_hist
x10y30 DFFE   LUT4     0.1         clock_receiver.sp.track_stream.transitions_8_hist
------ ------ ------ -----  -----  ------------------------------
                       8.4   14.5  = 22.9

Workaround

Attached below is a perl script (by H.T. Johansson) that transforms from the current output format to the clearer format by invoking e.g.:

perl ./pretty_timing_pl.txt < timing1.txt > timing1_out.txt

pretty_timing_pl.txt
@tommythorn
Copy link

@bl0x That's a lot nicer, but does pretty_timing have a home? The attached version seems to have problems with the current verision of nextpnr.

@kittennbfive
Copy link
Contributor

Hi,

quick fix to make this script work more or less: Comment die "Unhandled line: \"$line\""; by adding a # in front of it.

I agree that the current output from nextpnr is quite difficult to understand, but as pretty_timing.pl seems to be abandonware (if this word even exists...) i am trying to write a new version from scratch that works with current output of nextpnr. Currently it's just a hack and not even alpha-quality, but if i get something decent i will publish it.

I am working with Lattice ECP5 but as far as possible i am trying to make a generic helper/tool. However as i am a beginner i have some trouble with all these internals names like "SB_LUT4_O_I3_SB_CARRY_CO_6$CARRY.COUT"... I assume i have to look at the databases for the different architectures to figure out the exact naming schemes used?

Also i would appreciate if somebody could paste a recent timing report for ICE40 as i don't have Yosys/nextpnr compiled for this architecture currently.

And finally, if somebody has a good explanation regarding FPGA timing reports a link would be appreciated.

@kittennbfive
Copy link
Contributor

kittennbfive commented May 26, 2023 •
edited
Loading

Just learned that there will be major changes to the timing API of nextpnr soon: #1149

I guess (hope) the timing report will be improved also. Considering this i'll probably wait before putting lot's of work in the rewrite of the script.
EDIT: No, i won't change so i will continue my work.

@kittennbfive
Copy link
Contributor

I hope this won't be considered as spam, but i released an early version of my script (as public domain) here: https://github.com/kittennbfive/5A-75B-tools/blob/master/beautify-timing-report.pl
If you have any issues/ideas/... please comment/open PR/... in my repo and not here in this issue.

@tommythorn
Copy link

@kittennbfive I finally got around to trying it. It's definitely much nicer and readable, thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@tommythorn @bl0x @kittennbfive