Improved Debugging

[ginty]

This PR contains various updates to help with debugging failing simulations. The docs have been updated with the new features where applicable.

Note that the DUT will have to be recompiled to enabled most of these updates, though this version of OrigenSim remains backwards compatible with earlier DUTs.

• All pattern major step comments are now output to the console and timestamped to simulation time. This gives a much better overview of progress and identification of where pin miscompares have originated from.

• All Origen.log output from the application code is similarly timestamped and synchronized with the simulation. Apps are encouraged not to use puts to output debug/status information to the console as that will occur immediately and will not be synchronized.

• Miscompares that occur during register read transactions will now be automatically translated into register actual data in the failure log. The new documentation for this is copied at the end of these notes.

• Added a register to the testbench called origen.debug.marker which can be set in application code via tester.marker = 0x1234. This then gives you something to search for in a wave viewer if you want to identify a specific point in the code.

• Change to how the verbose logging (show all simulator output) is enabled. Someway along the line it became such that running with -d(ebug) meant that verbose logging was enabled, when in fact all other Origen commands require the -verbose switch to enable this. OrigenSim now aligns with this convention. If you prefer the old behavior you can enable it at app-level via:

Origen.log.level = :verbose if Origen.debugger_enabled?

• The :time_factor simulation config option has been removed, OrigenSim will now automatically adjust if the simulation is using a timescale of 1ps instead of 1ns (for example).

• Added a :max_errors simulation config option which defaults to 100. This can also be overridden at runtime via the --max_errors switch. When exceeded, the simulation will abort immediately.

• Simulating a list of patterns in a flow, e.g. origen g pat1 pat2 pat1 --flow eng will now run all duplicate patterns, i.e. the second pat1 in this example will now execute twice as you would expect, wheres until now only the first occurrence would be executed.

• Various clean-up/refactoring of the VPI extension and significant test bench simplification. All error generation and handling is now done in the C code and the testbench is now only the DUT with a pin driver on each pin and all connections between pin drivers has been removed.

---

Failed Register Reads

The following information is logged whenever a pin mis-compare occurs within a register read transaction:

• The path (name) of the register
• Expected data
• Received (actual) data - requires support from the physical driver, see below
• Application stack trace to identify where in the application code the read originated

Here is an example:

ss "Now try and read and write a register"
dut.cmd.write!(0x1234_5678)
tester.marker = 1
dut.cmd.read!(0x1234_5078)  # Note that we just wrote ..567.. but are now expecting ..507..

[INFO]       4.098[0.000]    ||       86500 ns: ======================================================================
[INFO]       4.098[0.001]    ||       86500 ns: Now try and read and write a register
[INFO]       4.099[0.001]    ||       86500 ns: ======================================================================
[ERROR]      4.100[0.001]    ||      117400 ns: Miscompare on pin tdo, expected 0 received 1
[ERROR]      4.101[0.001]    ||      117600 ns: Miscompare on pin tdo, expected 0 received 1
[ERROR]      4.102[0.001]    ||      129100 ns: Errors occurred reading register cmd:
[ERROR]      4.102[0.001]    ||      129100 ns: cmd.d: expected 12345078 received 12345678
[ERROR]      4.103[0.001]    ||      129100 ns:
[ERROR]      4.104[0.001]    ||      129100 ns: /home/stephen/Code/github/origen_sim/pattern/test.rb:39:in `block in <top (required)>'
[ERROR]      4.110[0.006]    ||      129100 ns: /home/stephen/Code/github/origen_sim/pattern/test.rb:1:in `<top (required)>'

The received data resolution does depend on the physical protocol driver supplying meta-data when creating pin assertions (reads) that correspond to register bits, like this:

pin(:tdo).assert(bit.data, meta: { position: bit.position })

For reference, here is the update that was made to the JTAG driver to support this feature - OrigenJTAG - Add meta data for OrigenSim

If the driver has not provided this then a warning will be output and no received data will be given.

This feature will automatically be enabled for any reads launched via the register object itself, e.g. my_reg.read!, but not for reads launched by calling the read_register method manually, e.g. dut.read_register(my_reg).

If your application has a tendency to do the latter, then the following modification can be made to your read_register method to make OrigenSim aware of such transactions:

def read_register(reg_or_value, options = {})
  # Make OrigenSim aware of all transactions to enable failed transaction reporting
  tester.read_register(reg_or_value, options) do

    # Existing implementation here

  end
end

This feature will also work in the case of the read object being a value rather than a register object.

[redxeth]

@ginty I noticed that the log output was 3 lines, ala 'ss' output. Just to check, modified a log from 'ss' to 'cc' and the entry now completely disappeared from sim log output. Is that the intended behavior? I was hoping it would just make it a single-line log entry. Or is there some other setting I missed?

[redxeth]

Yeah I think this is intended per your comments above. I guess that's always been the case for OrigenSim-- 'ss' if you want stuff going to the comment signals. I would still think one may want 'cc' comments at least for the log, where there isn't a limitation like there would be for comment signals.

[redxeth]

@ginty So I guess that's a no then on adding 'cc' to the list of possible debug output ?

[chrisnappi]

Go ahead and add that to the 'Issues' list as a request. I have a few other minor things I keep meaning to put in there (mostly to do with the generation of the verilog code).

---

From: D H notifications@github.com Sent: Thursday, March 21, 2019 9:38 AM To: Origen-SDK/origen_sim Cc: Chris P Nappi; Review requested Subject: Re: [Origen-SDK/origen_sim] Improved Debugging (#30)

@gintyhttps://eur01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fginty&data=02%7C01%7Cchris.nappi%40nxp.com%7Ceb0303b4f9d6464e204108d6ae0adf35%7C686ea1d3bc2b4c6fa92cd99c5c301635%7C0%7C0%7C636887759046256606&sdata=sQ48BV2y3G326IhwkD9g3Wz7uLugh1vZGIlkUxxdb50%3D&reserved=0 So I guess that's a no then on adding 'cc' to the list of possible debug output ?

— You are receiving this because your review was requested. Reply to this email directly, view it on GitHubhttps://eur01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2FOrigen-SDK%2Forigen_sim%2Fpull%2F30%23issuecomment-475255885&data=02%7C01%7Cchris.nappi%40nxp.com%7Ceb0303b4f9d6464e204108d6ae0adf35%7C686ea1d3bc2b4c6fa92cd99c5c301635%7C0%7C0%7C636887759046256606&sdata=9s3Ax4p9um7F6inS4B3k6ml3bw3T0Ay1Z994Hepxd8Y%3D&reserved=0, or mute the threadhttps://eur01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FALZMDQUOGeeIZijd7IkAkXJwE9bwvgzsks5vY5legaJpZM4blQGj&data=02%7C01%7Cchris.nappi%40nxp.com%7Ceb0303b4f9d6464e204108d6ae0adf35%7C686ea1d3bc2b4c6fa92cd99c5c301635%7C0%7C0%7C636887759046266620&sdata=A92XYrfuXLLIlsIkc%2Fq5DvY7Bxci0NW8DHNxowQ9MJk%3D&reserved=0.

[ginty]

Sorry @redxeth, I did see your comment and meant to answer but I got sidetracked in the process of releasing this.

We can definitely add a switch somewhere to include cc's in the verbose output, but I'm not convinced they should be enabled in the verbose output by default. I think the curated/default log now strikes the right balance between giving good info but not being too noisy as to be un-usable and/or make people switch off to it.

I think the verbose switch is good to have if people really want to see the full raw output from the simulator. Do we want to throw all ccs on top of that?

To me, ccs are for vector level comments and are used heavily in drivers, so there will be loads of them and I can't think of many simulation debug scenarios where you would need this considering you have Origen.log.info/debug available to spit out anything you particularly care about.

If you really want this we could add include_cc_in_verbose_log: true or similar as an option in the environment configuration, but with a default setting of false.

[redxeth]

@ginty Yeah, debating it. Agree that it would be more cluttered due to lower-level drivers. It's more that I think someone running their app code may wonder why certain of their output isn't there. I was just thinking that 'ss' takes up too many lines and cluttered up the sim log output a bit (opinion, I'm sure people would prefer that) and an app developer may just want only their app output being output and not all 'cc' possible. For that maybe they just do an info log or debug log instead like you said.

There are other features as well that would be useful. In my app I added my own 'cc' and 'ss' that adds an app-specific prefix to all pattern comments so I can identify which comments came from my app. These methods also do the Origen.log.info/debug as well for convenience.

So probably no need for the include_cc_in_verbose_log option, just so long as it's clear to users that 'ss' is the preferred comment method when doing simulation stuff. Maybe an option to not have the 'ss' take up so many lines then or to not include 'ss' output at all.

[ginty]

Yeah, we should definitely make Origen tag ss/cc/log messages with the app/plugin ID that initiated them. As discussed over in the concurrent patgen PR (https://github.com/Origen-SDK/origen/pull/335), it prefixes a thread ID to all such messages, so we should do a similar thing with the app/plugin ID.