DMI busy is mishandled on Microchip PolarFire SoC

[en-sc]

The issue is discovered by @tom-van and can be reproduced by running:

> poll off
> reg a0 0x123456789abcdef
a0 (/64): 0x0123456789abcdef
> step
[mpfs.e51] Found 10 triggers
mpfs.e51 halted due to single-step.
> reg a0
a0 (/64): 0x0123456789abcdef
> step
mpfs.e51 halted due to single-step.

> riscv reset_delays 1
> debug_level 3
> reg a0
a0 (/64): 0x0123456700000000

That results in:

Debug: 2605 479333 target.c:3031 handle_reg_command(): -
Debug: 2606 479333 riscv_reg.c:979 riscv_reg_get(): [mpfs.e51] Reading a0 from target
Debug: 2607 479333 riscv-013.c:5126 riscv013_get_register(): [mpfs.e51] reading register a0
Debug: 2608 479333 riscv-013.c:1636 register_read_direct(): [mpfs.e51] Reading a0
Debug: 2609 479333 riscv-013.c:748 riscv013_execute_abstract_command(): [mpfs.e51] access register=0x32100a {regno=0x100a write=arg0 transfer=enabled postexec=disabled aarpostincrement=disabled aarsize=64bit}
Debug: 2610 479333 batch.c:291 riscv_batch_run_from(): [mpfs.e51] Running batch of scans [0, 3)
Debug: 2611 479333 batch.c:255 log_batch(): 41b w 0032100a @17 -> + 00000000 @00; 3i
Debug: 2612 479333 batch.c:199 log_dmi_decoded(): write: command=0x32100a {control=0x32100a}
Debug: 2613 479333 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 00331008 @17; 0i
Debug: 2614 479333 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 0i
Debug: 2615 479333 riscv-013.c:474 decrement_reset_delays_counter(): [mpfs.e51] resetting learned delays (reset_delays_wait counter expired)
Debug: 2616 479333 riscv.c:451 dtmcs_scan(): TAP mpfs.cpu: DTMCS: 0x10000 -> ?
Debug: 2617 479333 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 1.
Debug: 2618 479333 batch.c:139 add_idle_before_batch(): [mpfs.e51] Adding 1 idle cycles before the batch.
Debug: 2619 479333 batch.c:291 riscv_batch_run_from(): [mpfs.e51] Running batch of scans [2, 3)
Debug: 2620 479333 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 10000002 @16; 1i
Debug: 2621 479333 batch.c:199 log_dmi_decoded(): read: abstractcs=0x10000002 {datacount=2 progbufsize=0x10}
Debug: 2622 479333 riscv-013.c:683 abstract_cmd_batch_check_and_clear_cmderr(): [mpfs.e51] abstractcs=0x10000002 {datacount=2 relaxedpriv=full_checks busy=ready progbufsize=0x10 cmderr=none}
Debug: 2623 479333 batch.c:291 riscv_batch_run_from(): [mpfs.e51] Running batch of scans [0, 3)
Debug: 2624 479333 batch.c:255 log_batch(): 41b r 00000000 @04 -> + 00000000 @00; 1i
Debug: 2625 479333 batch.c:255 log_batch(): 41b r 00000000 @05 -> b 00000000 @00; 1i
Debug: 2626 479333 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 1i
Debug: 2627 479333 riscv.c:451 dtmcs_scan(): TAP mpfs.cpu: DTMCS: 0x10000 -> ?
Debug: 2628 479333 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 2.
Debug: 2629 479333 batch.c:139 add_idle_before_batch(): [mpfs.e51] Adding 1 idle cycles before the batch.
Debug: 2630 479333 batch.c:291 riscv_batch_run_from(): [mpfs.e51] Running batch of scans [1, 3)
Debug: 2631 479334 batch.c:255 log_batch(): 41b r 00000000 @05 -> + 00000000 @00; 2i
Debug: 2632 479334 batch.c:199 log_dmi_decoded(): read:
Debug: 2633 479334 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 2i
Debug: 2634 479334 riscv.c:451 dtmcs_scan(): TAP mpfs.cpu: DTMCS: 0x10000 -> ?
Debug: 2635 479334 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 3.
Debug: 2636 479334 batch.c:139 add_idle_before_batch(): [mpfs.e51] Adding 1 idle cycles before the batch.
Debug: 2637 479334 batch.c:291 riscv_batch_run_from(): [mpfs.e51] Running batch of scans [2, 3)
Debug: 2638 479334 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 01234567 @05; 3i
Debug: 2639 479334 batch.c:199 log_dmi_decoded(): read:
Debug: 2640 479334 riscv-013.c:1655 register_read_direct(): [mpfs.e51] a0 = 0x123456700000000
Debug: 2641 479334 riscv_reg.c:988 riscv_reg_get(): [mpfs.e51] Read a0: 0x123456700000000
Debug: 2642 479334 riscv-013_reg.c:40 riscv013_reg_get(): [mpfs.e51] Read 0x0123456700000000 from a0 (valid=1).

The data0 read returns zeroes resulting in the lower half of the a0 register reported as zeroes.

[tom-van]

@en-sc , thanks for opening the issue (I should had done it myself, sorry).

I believe the failure you are observing is a HW issue. I will post a detailed analysis in https://github.com/riscv-collab/riscv-
openocd/issues/1307 shortly.

Yes, it is questionable.
RISC-V External Debug Support version 0.13.2 in chapter 6.1.5 Debug Module Interface Access reads about meaning of read op == 3:

The data scanned into dmi in this access will be ignored

Nothing about the data ready to scan out from dmi. So IMO the batch re-try code uses the prevailing behaviour of dmi but not explicitly required by the spec. What do you think?

[tom-van]

Could anybody please run riscv-tests with the latest version of riscv OpenOCD fork on original HiFiveUnleashed?

[en-sc]

TL;DR

I believe this is a HW issue.

Exactly for the reason mentioned by @tom-van -- DMI busy status makes the DTM ignore the requested operation.
From [6.1.5. Debug Module Interface Access (dmi, at 0x11)]:

In Update-DR, the DTM starts the operation specified in op unless the current status reported in op is
sticky.
In Capture-DR, the DTM updates data with the result from that operation, updating op if the current
op isn’t sticky.

Together with [6.1.4. DTM Control and Status (dtmcs, at 0x10)], dmireset field description:

Writing 1 to this bit clears the sticky error state and resets errinfo, but does not affect outstanding DMI transactions.

My understanding is that in the sequence of scans from the log should have the following effect:

1. capture success -> update to DMI read data0.
2. captures busy -> update to DMI read data1 (ignored).
3. captures busy -> update to NOP (no effect on status).
4. Issue DMI reset.
5. capture success, data from data0 -> update to DMI read data1.
6. captures busy -> update to NOP (no effect on status).
7. Issue DMI reset.
8. capture success, data from data1 -> update to NOP (no effect on status).

In the log the scan (5) returns zeroes instead of the data from data0.

Log analysis:

1. Resetting delays results in the read of abstractcs reporting DMI busy:

Debug: 2613 479333 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 00331008 @17; 0i
Debug: 2614 479333 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 0i
Debug: 2615 479333 riscv-013.c:474 decrement_reset_delays_counter(): [mpfs.e51] resetting learned delays (reset_delays_wait counter expired)

2. DMI busy is reset, delay is increased:

Debug: 2616 479333 riscv.c:451 dtmcs_scan(): TAP mpfs.cpu: DTMCS: 0x10000 -> ?
Debug: 2617 479333 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 1.

3. The last NOP from the batch is re-run and the result of the abstractcs read is returned.

Debug: 2618 479333 batch.c:139 add_idle_before_batch(): [mpfs.e51] Adding 1 idle cycles before the batch.
Debug: 2619 479333 batch.c:291 riscv_batch_run_from(): [mpfs.e51] Running batch of scans [2, 3)
Debug: 2620 479333 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 10000002 @16; 1i
Debug: 2621 479333 batch.c:199 log_dmi_decoded(): read: abstractcs=0x10000002 {datacount=2 progbufsize=0x10}
Debug: 2622 479333 riscv-013.c:683 abstract_cmd_batch_check_and_clear_cmderr(): [mpfs.e51] abstractcs=0x10000002 {datacount=2 relaxedpriv=full_checks busy=ready progbufsize=0x10 cmderr=none}

4. Next data0-1 registers are being read. The second scan results in DMI busy (scans 1-3 from TL;DR):

Debug: 2623 479333 batch.c:291 riscv_batch_run_from(): [mpfs.e51] Running batch of scans [0, 3)
Debug: 2624 479333 batch.c:255 log_batch(): 41b r 00000000 @04 -> + 00000000 @00; 1i
Debug: 2625 479333 batch.c:255 log_batch(): 41b r 00000000 @05 -> b 00000000 @00; 1i
Debug: 2626 479333 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 1i

5. DMI busy is reset, delay is increased (scan 4 from TL;DR):

Debug: 2627 479333 riscv.c:451 dtmcs_scan(): TAP mpfs.cpu: DTMCS: 0x10000 -> ?
Debug: 2628 479333 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 2.

6. Left-over scans are re-run (read data1 that gets the result of data0 read, nop to get the result of data1 read). NOP similarly results in a DMI busy (scans 5-6 from TL;DR):

Debug: 2629 479333 batch.c:139 add_idle_before_batch(): [mpfs.e51] Adding 1 idle cycles before the batch.
Debug: 2630 479333 batch.c:291 riscv_batch_run_from(): [mpfs.e51] Running batch of scans [1, 3)
Debug: 2631 479334 batch.c:255 log_batch(): 41b r 00000000 @05 -> + 00000000 @00; 2i
Debug: 2632 479334 batch.c:199 log_dmi_decoded(): read:
Debug: 2633 479334 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 2i

7. DMI busy is reset, delay is increased (scan 7 from TL;DR):

Debug: 2634 479334 riscv.c:451 dtmcs_scan(): TAP mpfs.cpu: DTMCS: 0x10000 -> ?
Debug: 2635 479334 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 3.

8. NOP is re-run (scans 8 from TL;DR):

Debug: 2636 479334 batch.c:139 add_idle_before_batch(): [mpfs.e51] Adding 1 idle cycles before the batch.
Debug: 2637 479334 batch.c:291 riscv_batch_run_from(): [mpfs.e51] Running batch of scans [2, 3)
Debug: 2638 479334 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 01234567 @05; 3i
Debug: 2639 479334 batch.c:199 log_dmi_decoded(): read:

9. Results are reported:

Debug: 2640 479334 riscv-013.c:1655 register_read_direct(): [mpfs.e51] a0 = 0x123456700000000
Debug: 2641 479334 riscv_reg.c:988 riscv_reg_get(): [mpfs.e51] Read a0: 0x123456700000000
Debug: 2642 479334 riscv-013_reg.c:40 riscv013_reg_get(): [mpfs.e51] Read 0x0123456700000000 from a0 (valid=1).

Attempting to reproduce on Spike

It is not possible to fully reproduce this on Spike due to an issue with how Spike handles NOPs, namely:
The Spec requires that a NOP does not affect DMI status in [6.1.5. Debug Module Interface Access (dmi, at 0x11)], op field description:

Don’t send anything over the DMI during Update-DR. This operation should never affect DMI busy or error status.

However, in Spike to consecutive NOPs can result in DMI busy:

1. capture success -> update to NOP.
2. capture busy -> update to NOP.

Therefore when the delays are reset on the abstractcs read like in the reproduction, data0 read results in DMI busy, not data1 read:

Debug: 33 14 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 0032100a @17; 0i
Debug: 34 14 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 0i
Debug: 35 14 riscv-013.c:476 decrement_reset_delays_counter(): [riscv.cpu] resetting learned delays (reset_delays_wait counter expired)
Debug: 36 14 riscv.c:451 dtmcs_scan(): TAP riscv.cpu: DTMCS: 0x10000 -> ?
Debug: 37 14 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 1.
Debug: 38 14 batch.c:139 add_idle_before_batch(): [riscv.cpu] Adding 1 idle cycles before the batch.
Debug: 39 14 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [2, 3)
Debug: 40 14 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000002 @16; 1i
Debug: 41 14 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2000002 {datacount=2 progbufsize=2}
Debug: 42 14 riscv-013.c:685 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] abstractcs=0x2000002 {datacount=2 relaxedpriv=full_checks busy=ready progbufsize=2 cmderr=none}
Debug: 43 14 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 3)
Debug: 44 14 batch.c:255 log_batch(): 41b r 00000000 @04 -> b 00000000 @00; 1i

Adjusting the delay before the reset, it is possible to induce a busy response on the data0 scan (without a busy responce on a abstractcs read):

Debug: 33 14 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 0032100a @17; 3i
Debug: 34 14 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000002 @16; 3i
Debug: 35 14 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2000002 {datacount=2 progbufsize=2}
Debug: 36 14 riscv-013.c:685 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] abstractcs=0x2000002 {datacount=2 relaxedpriv=full_checks busy=ready progbufsize=2 cmderr=none}
Debug: 37 14 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 3)
Debug: 38 14 batch.c:255 log_batch(): 41b r 00000000 @04 -> + 00000000 @00; 0i
Debug: 39 14 batch.c:255 log_batch(): 41b r 00000000 @05 -> b 00000000 @00; 0i
Debug: 40 14 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 0i
Debug: 41 14 riscv-013.c:476 decrement_reset_delays_counter(): [riscv.cpu] resetting learned delays (reset_delays_wait counter expired)
Debug: 42 14 riscv.c:451 dtmcs_scan(): TAP riscv.cpu: DTMCS: 0x10000 -> ?
Debug: 43 14 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 1.
Debug: 44 14 batch.c:139 add_idle_before_batch(): [riscv.cpu] Adding 1 idle cycles before the batch.
Debug: 45 14 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [1, 3)
Debug: 46 14 batch.c:255 log_batch(): 41b r 00000000 @05 -> + 00000001 @04; 1i
Debug: 47 14 batch.c:199 log_dmi_decoded(): read:
Debug: 48 14 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 1i
Debug: 49 14 riscv.c:451 dtmcs_scan(): TAP riscv.cpu: DTMCS: 0x10000 -> ?
Debug: 50 14 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 2.
Debug: 51 14 batch.c:139 add_idle_before_batch(): [riscv.cpu] Adding 1 idle cycles before the batch.
Debug: 52 14 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [2, 3)
Debug: 53 14 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000002 @05; 2i
Debug: 54 14 batch.c:199 log_dmi_decoded(): read:
Debug: 55 14 riscv-013.c:1657 register_read_direct(): [riscv.cpu] a0 = 0x200000001

However, the read is still successful.

I've patched the Spike to reproduce the issue (I'll post the patch shortly):

--- a/riscv/jtag_dtm.cc
+++ b/riscv/jtag_dtm.cc
@@ -199,6 +199,6 @@ void jtag_dtm_t::update_dr()
     }
     D(fprintf(stderr, "dmi=0x%lx\n", dmi));

-    rti_remaining = required_rti_cycles;
+    rti_remaining = op == DMI_OP_NOP ? 0 : required_rti_cycles;
   }
 }

This results in a complete reproduction on Spike with a different result -- the register is read successfully:

> spike --rbb-port=7777 --dmi-rti=6 ~/openocd/boot_spike64.elf

> cat spike.cfg
adapter driver remote_bitbang
remote_bitbang port 7777
remote_bitbang host 127.0.0.1

set _CHIPNAME riscv
jtag newtap $_CHIPNAME cpu -irlen 5

set _TARGETNAME $_CHIPNAME.cpu
target create $_TARGETNAME riscv -chain-position $_TARGETNAME -rtos hwthread

> openocd \
  -f spike.cfg \
  -c init \
  -c halt \
  -c 'poll disable' \
  -c 'reg a0 0x200000001' \
  -c step \
  -c 'riscv reset_delays 3' \
  -c 'debug_level 3' \
  -c 'reg a0' \
  -c 'debug_level 1' \
  -c shutdown
...
Debug: 25 20 target.c:3041 handle_reg_command(): -
Debug: 26 20 riscv_reg.c:983 riscv_reg_get(): [riscv.cpu] Reading a0 from target
Debug: 27 20 riscv-013.c:5121 riscv013_get_register(): [riscv.cpu] reading register a0
Debug: 28 20 riscv-013.c:1638 register_read_direct(): [riscv.cpu] Reading a0
Debug: 29 20 riscv-013.c:750 riscv013_execute_abstract_command(): [riscv.cpu] access register=0x32100a {regno=0x100a write=arg0 transfer=enabled postexec=disabled aarpostincrement=disabled aarsize=64bit}
Debug: 30 20 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 3)
Debug: 31 20 batch.c:255 log_batch(): 41b w 0032100a @17 -> + 00000000 @00; 3i
Debug: 32 20 batch.c:199 log_dmi_decoded(): write: command=0x32100a {control=0x32100a}
Debug: 33 20 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 0032100a @17; 3i
Debug: 34 20 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000002 @16; 3i
Debug: 35 20 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2000002 {datacount=2 progbufsize=2}
Debug: 36 20 riscv-013.c:685 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] abstractcs=0x2000002 {datacount=2 relaxedpriv=full_checks busy=ready progbufsize=2 cmderr=none}
Debug: 37 20 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 3)
Debug: 38 20 batch.c:255 log_batch(): 41b r 00000000 @04 -> + 00000000 @00; 0i
Debug: 39 20 batch.c:255 log_batch(): 41b r 00000000 @05 -> b 00000000 @00; 0i
Debug: 40 20 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 0i
Debug: 41 20 riscv-013.c:476 decrement_reset_delays_counter(): [riscv.cpu] resetting learned delays (reset_delays_wait counter expired)
Debug: 42 20 riscv.c:451 dtmcs_scan(): TAP riscv.cpu: DTMCS: 0x10000 -> ?
Debug: 43 20 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 1.
Debug: 44 20 batch.c:139 add_idle_before_batch(): [riscv.cpu] Adding 1 idle cycles before the batch.
Debug: 45 20 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [1, 3)
Debug: 46 21 batch.c:255 log_batch(): 41b r 00000000 @05 -> + 00000001 @04; 1i
Debug: 47 21 batch.c:199 log_dmi_decoded(): read:
Debug: 48 21 batch.c:255 log_batch(): 41b - 00000000 @00 -> b 00000000 @00; 1i
Debug: 49 21 riscv.c:451 dtmcs_scan(): TAP riscv.cpu: DTMCS: 0x10000 -> ?
Debug: 50 21 batch.h:86 riscv_scan_set_delay(): DM access delay is set to 2.
Debug: 51 21 batch.c:139 add_idle_before_batch(): [riscv.cpu] Adding 1 idle cycles before the batch.
Debug: 52 21 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [2, 3)
Debug: 53 21 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000002 @05; 2i
Debug: 54 21 batch.c:199 log_dmi_decoded(): read:
Debug: 55 21 riscv-013.c:1657 register_read_direct(): [riscv.cpu] a0 = 0x200000001
Debug: 56 21 riscv_reg.c:992 riscv_reg_get(): [riscv.cpu] Read a0: 0x200000001
Debug: 57 21 riscv-013_reg.c:40 riscv013_reg_get(): [riscv.cpu] Read 0x0000000200000001 from a0 (valid=1).
User : 58 21 options.c:52 configuration_output_handler(): a0 (/64): 0x0000000200000001User : 59 21 options.c:52 configuration_output_handler():
Debug: 60 21 command.c:154 script_debug(): command - debug_level 1
debug_level: 1
shutdown command invoked

Summary

I believe this is a HW issue for the following reasons:

1. My interpretation of the spec. See TL;DR.
2. The same issue of DMI operations and responses results in a successful register read.

I don't think this issue should block RISC-V Sync with mainline OpenOCD, however, since this is a readily available platform that can not be fixed a workaround should be introduced.
See #979 (comment).

[tom-van]

In Capture-DR, the DTM updates data with the result from that operation, updating op if the current
op isn’t sticky.

Yes, this is the very piece of information I missed. I fully agree with @en-sc analysis, the dmi silicon implementation of PolarFire SoC does not conform the debug spec.
I managed to finish riscv-tests with the quick and incorrect fix, so riscv-sync series can go.

I just pass the pointer to this issue to Microchip guys.

[en-sc]

I've patched the Spike to reproduce the issue (I'll post the patch shortly) ...

See riscv-software-src/riscv-isa-sim#2132