Added sta registered commands tracing and tests

[dav77227]

The solution is implemented using the Tcl_CreateObjTrace function. It performs tracing for all execution modes: prompt, batch and GUI modes. Only OpenROAD registered commands are being logged. During the testing I have encountered that there are some commands which are logged twice, and I have not yet found the exact reason of this behavior, so I have applied a workaround solution to this issue (maintained the last executed command). @maliberty @QuantamHD @gadfort @stefanottili because of this workaround, this PR is currently a draft, so please let me know if you have a clue what might be the reason of double logging?

Please see the sample log files attached with and without the workaround 2_2_floorplan_io.log without the workaround 2_2_floorplan_io.log with the workaround

[maliberty]

create_clock -name core_clock -period 0.46 _c08bf46215630000_p_Port

It isn't ideal to include the swig'ed pointer instead of the name as it won't be reproducible in another run.

[github-actions[bot]]

clang-tidy review says "All clean, LGTM! :+1:"

[maliberty]

When running ng45/gcd I see in the sdc:

current_design gcd

set clk_name  core_clock
set clk_port_name clk
set clk_period 0.46 
set clk_io_pct 0.2

set clk_port [get_ports $clk_port_name]

while in the trace

OpenROAD> current_design gcd 
OpenROAD> get_name _e095730700000000_p_Cell 
OpenROAD> get_ports clk 

The call to get_name is internal to current_design and should not be logged despite being a public command (it wasn't directly issued by the user).

[dav77227]

When running ng45/gcd I see in the sdc:

current_design gcd

set clk_name  core_clock
set clk_port_name clk
set clk_period 0.46 
set clk_io_pct 0.2

set clk_port [get_ports $clk_port_name]

while in the trace

OpenROAD> current_design gcd 
OpenROAD> get_name _e095730700000000_p_Cell 
OpenROAD> get_ports clk 

The call to get_name is internal to current_design and should not be logged despite being a public command (it wasn't directly issued by the user).

The tcl_CreateObjTrace function that I used for tracing has a level argument, which makes it possible to trace commands based on their nesting level. A value of 0 means that commands at any level are traced. A value of 1 means only top-level commands are traced, 2 means top-level commands or those invoked as immediate consequences of executing top-level commands, and so on.

As an experiment I have printed all commands and all levels and discovered that if we run design through flow scripts (batch mode), then the command current_design gcd in the ng45/gcd 1_synth.sdc file, is at level 20, and get_name _e095730700000000_p_Cell is at level 23. By filtering logging of traced commands where the level is 20 or less, we can log only user issued commands. However, in case of interactive mode level 20 is too much, so I think we need to do extensive testing to find correct levels for every mode.

@maliberty Please let me know what you think.

[dav77227]

create_clock -name core_clock -period 0.46 _c08bf46215630000_p_Port

It isn't ideal to include the swig'ed pointer instead of the name as it won't be reproducible in another run.

We evaluate all arguments of the TCL command and log the evaluated arguments. For this particular command it's not that much informative, but in general it's always more informative than printing just some TCL variable names.

[maliberty]

We evaluate all arguments of the TCL command and log the evaluated arguments. For this particular command it's not that much informative, but in general it's always more informative than printing just some TCL variable names.

Ideally this would be the most descriptive of what the user did:

set clk_port_name clk
set clk_port [get_ports $clk_port_name]

the next best

set clk_port [get_ports clk]

the fully evaluated version doesn't tell you anything about what port was used.

[maliberty]

Can you keep track if you are already inside of a public command and not log any further public commands until the outer one is done?

[dav77227]

I made changes to the code and improved TCL command tracing to avoid logging nested commands, also no more any workaround is needed. With these changes, we log only public commands and do not log any further public commands until the outer one is done. Please see attached log file. 2_2_floorplan_io.log

As for the evaluation of the commands arguments: after changing the code, as I already mentioned, we do not log commands called inside public commands, so we no longer see the internal get_name (get_name is called from inside read_sdc -> current_design) command in this example, and accordingly, the argument passed to the get_name command is not logged. But if the get_name command is called in a not-nested place, then its arguments will be evaluated as before. One way that I can think of to fix this issue is to keep a list of public commands, for which we will not evaluate arguments (I think logging set commands will create a mess in log files), @maliberty please let me know what you think about this?

Regarding test failures: once we agree on a solution, I'll re-golden all tests.