How to read detailed routing log

[oharboe]

If I read this correctly, then the run of 1st iteration elapsed(wallclock) time was 10 hours, 46 minutes and 46 seconds.

4h47mn was spent up to and including completing 100%.

Q: what happens in the 6 hours between 100% and fully completing 1st iteration?

Usually very little time passes at this stage, is it expected that a lot of time can pass here?

This run is from thethe MegaBoom design I'm working on.

[INFO DRT-0195] Start 1st optimization iteration.
    Completing 10% with 1076101 violations.
    elapsed time = 00:24:49, memory = 60012.99 (MB).
    Completing 20% with 873473 violations.
    elapsed time = 01:04:14, memory = 60329.16 (MB).
    Completing 30% with 805447 violations.
    elapsed time = 01:20:27, memory = 59897.90 (MB).
    Completing 40% with 667422 violations.
    elapsed time = 01:58:03, memory = 60366.77 (MB).
    Completing 50% with 559526 violations.
    elapsed time = 02:24:50, memory = 59460.91 (MB).
    Completing 60% with 474370 violations.
    elapsed time = 02:49:13, memory = 60126.98 (MB).
    Completing 70% with 320252 violations.
    elapsed time = 03:28:15, memory = 60227.41 (MB).
    Completing 80% with 270693 violations.
    elapsed time = 03:44:28, memory = 59310.96 (MB).
    Completing 90% with 163044 violations.
    elapsed time = 04:21:50, memory = 60829.58 (MB).
    Completing 100% with 79991 violations.
    elapsed time = 04:47:55, memory = 59083.30 (MB).
[INFO DRT-0199]   Number of violations = 87967.
Viol/Layer          M1     M2     V2     M3     V3     M4     V4     M5     V5     M6     V6     M7     V7     M8
Corner Spacing       0     13      0      0      0      1      0      0      0      0      0      0      0      0
Cut Spacing          0      0      0      0      0      0      0      0      0      0      0      0     32      0
CutSpcTbl            0      0      0      0    870      0    714      0     45      0     79      0      0      0
EOL                  0  11018      0    243      0    100      0     47      0     29      0     42      0      0
Metal Spacing     1896   2198      0   1705      0    126      0     48      0     27      0     57      0     54
Min Step             0      0      0      0      0      0      0      0      0      0      0      0      0    255
NS Metal             0      0      0      0      0      0      0      0      0      0      0      1      0     27
Recheck            123   4568      0   3242      0    351      0      1      0      0      0      0      0      0
Rect Only            0      0      0      0      0      0      0      0      0      0      0     83      0      0
Short               11   6274     19    681      4    157      1    110      1    132     24      5     14     15
eolKeepOut           0  50499      0    971      0    615      0    169      0     87      0    183      0      0
[INFO DRT-0267] cpu time = 77:23:47, elapsed time = 10:14:46, memory = 56657.25 (MB), peak = 61275.99 (MB)

[oharboe]

I attached to the process during the "mystery processing", paused and looked at stack traces:

___lldb_unnamed_symbol837 (@___lldb_unnamed_symbol837:56)
___lldb_unnamed_symbol816 (@___lldb_unnamed_symbol816:16)
fr::FlexDRConnectivityChecker::check(int) (@fr::FlexDRConnectivityChecker::check(int):1143)
fr::FlexDR::searchRepair(fr::FlexDR::SearchRepairArgs const&) (@fr::FlexDR::searchRepair(fr::FlexDR::SearchRepairArgs const&):1714)
fr::FlexDR::main() (@fr::FlexDR::main():51)
triton_route::TritonRoute::main() (@triton_route::TritonRoute::main():175)
detailed_route_cmd(char const*, char const*, char const*, char const*, char const*, bool, int, char const*, char const*, int, double, char const*, char const*, int, bool, bool, bool, int, bool, char const*, int) (@detailed_route_cmd(char const*, char const*, char const*, char const*, char const*, bool, int, char const*, char const*, int, double, char const*, char const*, int, bool, bool, bool, int, bool, char const*, int):304)
_wrap_detailed_route_cmd (@_wrap_detailed_route_cmd:263)
TclNRRunCallbacks (@TclNRRunCallbacks:37)
___lldb_unnamed_symbol1497 (@___lldb_unnamed_symbol1497:339)
Tcl_EvalEx (@Tcl_EvalEx:9)
Tcl_Eval (@Tcl_Eval:11)
sta::sourceTclFile(char const*, bool, bool, Tcl_Interp*) (@sta::sourceTclFile(char const*, bool, bool, Tcl_Interp*):32)
ord::tclAppInit(Tcl_Interp*) (@ord::tclAppInit(Tcl_Interp*):131)
Tcl_MainEx (@Tcl_MainEx:111)
main (@main:727)
__libc_start_call_main (@__libc_start_call_main:29)
__libc_start_main_impl (@__libc_start_main@@GLIBC_2.34:44)
_start (@_start:15)

Then there are a number of, what I believe are, paused threads.

fr::FlexDRConnectivityChecker::astar(fr::frNet const*, std::vector<char, std::allocator<char>>&, std::vector<int, std::allocator<int>>&, std::map<std::pair<odb::Point, int>, std::set<int, std::less<int>, std::allocator<int>>, std::less<std::pair<odb::Point, int>>, std::allocator<std::pair<std::pair<odb::Point, int> const, std::set<int, std::less<int>, std::allocator<int>>>>> const&, std::vector<fr::frConnFig*, std::allocator<fr::frConnFig*>> const&, int, int) (@fr::FlexDRConnectivityChecker::astar(fr::frNet const*, std::vector<char, std::allocator<char>>&, std::vector<int, std::allocator<int>>&, std::map<std::pair<odb::Point, int>, std::set<int, std::less<int>, std::allocator<int>>, std::less<std::pair<odb::Point, int>>, std::allocator<std::pair<std::pair<odb::Point, int> const, std::set<int, std::less<int>, std::allocator<int>>>>> const&, std::vector<fr::frConnFig*, std::allocator<fr::frConnFig*>> const&, int, int):645)
fr::FlexDRConnectivityChecker::check(int) (._omp_fn.1) (@fr::FlexDRConnectivityChecker::check(int) (._omp_fn.1):162)
___lldb_unnamed_symbol813 (@___lldb_unnamed_symbol813:87)
start_thread (@start_thread:164)
__clone3 (@__clone3:19)

Hmm.... I wonder if it is stuck, I'll let it run today. In "top" there's no openroad binary that is using CPU... In the example above, it did continue after the long "mystery processing" stage.

[oharboe]

Feature request filed #4612