Enhancement of the logging entries
Reisswolf opened this issue · 4 comments
I have two suggestions that would improve the logging functionality.
1. First lets take the AXIS test script as example. It has a Source, Sink and Monitor. I think it would help during debugging if it were possible to tell which log entry is the monitor. In the example case you see:
- "RX frame: AxiStreamFrame(tdata=bytearray(b' ... "
- "RX frame: AxiStreamFrame(tdata=bytearray(b' ... "
It makes sense the way it is but it may be confusing at first and you have to think about it for a second.
Maybe a solution could be to change the log entry to:
"MON frame: AxiStreamFrame(tdata=bytearray(b' ... "
2. If you test a Verilog module with multiple AXIS sources and sinks it will get really difficult because all log entries look very similar and it is very hard to tell them apart.
I suggest to display the bus name as part of the log entry for source, sink, and for the monitor description. I think that would improve the log output and give a better overview.
Just realized that I only looked at the INFO level so far. So please disregard if this exists already.
Well, I think the first one shouldn't really a problem as I don't think you would ever put the sink and the monitor on the same connection. That's only done for the unit test, in actuality you would likely use only one of the three, with the exception of maybe putting a TX and monitor on the same interface if you want to see the rx_sim_time field for packets sent into a design. Although maybe there is a better way to get feedback for TX packets, perhaps I can add some fields for events to AxiStreamFrame for tx_start, tx_complete, etc. that can be used if required.
As to the second point, the full log output does include the bus name. However, since in that testbench, all three are connected to the same pins, the name is the same for all of the messages:
10.00ns INFO cocotb.test_axis.axis axis.py:400 in _run TX frame: AxiStreamFrame(tdata=bytearray(b'\x00'), tkeep=None, tid=1, tdest=1, tuser=None, rx_sim_time=None)
12.00ns INFO cocotb.test_axis.axis axis.py:400 in _run TX frame: AxiStreamFrame(tdata=bytearray(b'\x00\x01'), tkeep=None, tid=2, tdest=2, tuser=None, rx_sim_time=None)
12.00ns INFO cocotb.test_axis.axis axis.py:658 in _run RX frame: AxiStreamFrame(tdata=bytearray(b'\x00'), tkeep=[1], tid=[1], tdest=[1], tuser=[0], rx_sim_time=12)
12.00ns INFO cocotb.test_axis.axis axis.py:853 in _run RX frame: AxiStreamFrame(tdata=bytearray(b'\x00'), tkeep=[1], tid=[1], tdest=[1], tuser=[0], rx_sim_time=12)
16.00ns INFO cocotb.test_axis.axis axis.py:400 in _run TX frame: AxiStreamFrame(tdata=bytearray(b'\x00\x01\x02'), tkeep=None, tid=3, tdest=3, tuser=None, rx_sim_time=None)
16.00ns INFO cocotb.test_axis.axis axis.py:658 in _run RX frame: AxiStreamFrame(tdata=bytearray(b'\x00\x01'), tkeep=[1, 1], tid=[2, 2], tdest=[2, 2], tuser=[0, 0], rx_sim_time=14)
16.00ns INFO cocotb.test_axis.axis axis.py:853 in _run RX frame: AxiStreamFrame(tdata=bytearray(b'\x00\x01'), tkeep=[1, 1], tid=[2, 2], tdest=[2, 2], tuser=[0, 0], rx_sim_time=14)
Again, this is only a problem for this specific unit test, as there is no reason you would connect multiple instances to the same HDL port.
On a different testbench that actually connects things to different ports, the log entries are different:
50.00ns INFO cocotb.axis_adapter.s_axis axis.py:400 in _run TX frame: AxiStreamFrame(tdata=bytearray(b'\x00'), tkeep=None, tid=1, tdest=1, tuser=None, rx_sim_time=None)
60.00ns INFO cocotb.axis_adapter.s_axis axis.py:400 in _run TX frame: AxiStreamFrame(tdata=bytearray(b'\x00\x01'), tkeep=None, tid=2, tdest=2, tuser=None, rx_sim_time=None)
70.00ns INFO cocotb.axis_adapter.m_axis axis.py:658 in _run RX frame: AxiStreamFrame(tdata=bytearray(b'\x00'), tkeep=[1], tid=[1], tdest=[1], tuser=[0], rx_sim_time=70000)
80.00ns INFO cocotb.axis_adapter.s_axis axis.py:400 in _run TX frame: AxiStreamFrame(tdata=bytearray(b'\x00\x01\x02'), tkeep=None, tid=3, tdest=3, tuser=None, rx_sim_time=None)
90.00ns INFO cocotb.axis_adapter.m_axis axis.py:658 in _run RX frame: AxiStreamFrame(tdata=bytearray(b'\x00\x01'), tkeep=[1, 1], tid=[2, 2], tdest=[2, 2], tuser=[0, 0], rx_sim_time=80000)
110.00ns INFO cocotb.axis_adapter.s_axis axis.py:400 in _run TX frame: AxiStreamFrame(tdata=bytearray(b'\x00\x01\x02\x03'), tkeep=None, tid=4, tdest=4, tuser=None, rx_sim_time=None)
-
Maybe you are right about the monitor use, I just thought it would make the information presentation a bit more clear.
-
It's embarrassing to admit that I did not see the bus name in the log all the way to the left. I find it however a bit painful to trace the lines back and forth. I was thinking of something along:
- TX frame -> s_axis: AxiStreamFrame(tdata=bytearray(b'\x00'), tkeep=None, ....)
- m_axis -> RX frame: AxiStreamFrame(tdata=bytearray(b'\x00\x01'), tkeep=[1, 1],...)
would be more informative since you have everything in one place. I understand this would be a duplication but I feel it adds some value.
It just some suggestions and maybe even bad ones. Feel free to close the issue.
Yeah, it's not a bad idea. Also, a lot of people probably run with the 'condensed log' output that only shows the log entries and not the logger names. Since the logger name is shown, I didn't want to be redundant by including the signal name again, but perhaps displaying the path more prominently in the output message would be a good idea.
Further to this, I think that any information in an INFO line should be short and sweet, and the full details of the frame reserved for DEBUG. IMO, RX and TX frame of length n should be sufficient information for the INFO line.