sbbusyerror model breaks openOCD

[fborisovskii]

Hello,

A question about sbbusyerror model in Debug module. https://github.com/riscv-software-src/riscv-isa-sim/pull/1513 I suppose triggering of sbbusyerror flag is not certain. In Debug spec sbbusyerror is set when next read is started before the previous is done. But in current implementation sbbusyerror is set every time reading of any DM_SBDATA is processed.

case DM_SBDATA0:
result = sbdata[0];
if (sb_busy()) {
  sbcs.sbbusyerror = true;
} else if (sbcs.error == 0) {
  if (sbcs.readondata) {
    sb_read_start();
  }
}
break;

So the assumption that the very first read has no sbbusyerror becomes wrong. Correct me if this model has benefits against model when the very first read is always clean.

I've fond that this model breaks read_memory_bus_v1 function in openOCD In case when (for example) 64 bit value is read from 32 bit hart (with two subsequent reads)

First read is assumed to be executed correctly and data in SBDATA is assumed to be correct. Correct for the last successful read. But this assumption becomes wrong and first read can fail as well. There is a relative issue in openOCD: https://github.com/riscv-collab/riscv-openocd/issues/1080

I am a bit confused about what is to be fixed - openOCD or spike. From my point of view - spike model is not truly similar as real HW behaves.

Thank you, Fedor

[fborisovskii]

I also attach my openOCD log

Debug: 1590 3719 gdb_server.c:424 gdb_log_incoming_packet(): [riscv.cpu0] {1} received packet: m40000000,8
Debug: 1591 3719 gdb_server.c:1577 gdb_read_memory_packet(): addr: 0x0000000040000000, len: 0x00000008
Debug: 1592 3719 target.c:2416 target_read_buffer(): reading buffer of 8 byte at 0x40000000
Debug: 1593 3719 riscv.c:5721 riscv_get_register(): [riscv.cpu0] Reading priv from target
Debug: 1594 3719 riscv.c:5717 riscv_get_register(): [riscv.cpu0] Read dcsr: 0x400090c3 (cached)
Debug: 1595 3719 riscv.c:5730 riscv_get_register(): [riscv.cpu0] Read priv: 0x3
Debug: 1596 3719 riscv.c:5721 riscv_get_register(): [riscv.cpu0] Reading priv from target
Debug: 1597 3719 riscv.c:5717 riscv_get_register(): [riscv.cpu0] Read dcsr: 0x400090c3 (cached)
Debug: 1598 3719 riscv.c:5730 riscv_get_register(): [riscv.cpu0] Read priv: 0x3
Debug: 1599 3719 riscv.c:5717 riscv_get_register(): [riscv.cpu0] Read mstatus: 0x0 (cached)
Debug: 1600 3719 riscv.c:2698 riscv_effective_privilege_mode(): [riscv.cpu0] Effective mode=3; v=0
Debug: 1601 3719 riscv.c:2773 riscv_mmu(): [riscv.cpu0] SATP/MMU ignored in Machine mode.
Debug: 1602 3719 riscv.c:3003 riscv_virt2phys(): [riscv.cpu0] MMU is disabled. 0x40000000 -> 0x40000000
Debug: 1603 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b w 00158000 @38 -> + 00000000 @38; 0i
Debug: 1604 3719 riscv-013.c:438 riscv_decode_dmi_scan(): write: sbcs=0x158000 {sbreadondata=1 sbautoincrement=1 sbaccess=32bit sbreadonaddr=1}
Debug: 1605 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 00158000 @38; 0i
Debug: 1606 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b w 00000000 @3a -> + 00000000 @38; 0i
Debug: 1607 3719 riscv-013.c:438 riscv_decode_dmi_scan(): write: 
Debug: 1608 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b w 40000000 @39 -> + 00000000 @3a; 0i
Debug: 1609 3719 riscv-013.c:438 riscv_decode_dmi_scan(): write: 
Debug: 1610 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @39 -> + 40000000 @39; 0i
Debug: 1611 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @3c -> + 00000000 @39; 0i
Debug: 1612 3719 riscv-013.c:428 riscv_decode_dmi_scan(): read: 
Debug: 1613 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @00 -> + deadbeef @3c; 0i
Debug: 1614 3719 riscv-013.c:428 riscv_decode_dmi_scan(): read: 
Debug: 1615 3719 riscv-013.c:3216 log_memory_access64(): M[0x40000000] reads 0xdeadbeef
Debug: 1616 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @38 -> + 00000000 @00; 0i
Debug: 1617 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 20758807 @38; 0i
Debug: 1618 3719 riscv-013.c:428 riscv_decode_dmi_scan(): read: sbcs=0x20758807 {sbaccess8=1 sbaccess16=1 sbreadondata=1 sbautoincrement=1 sbaccess=32bit sbaccess32=1 sbreadonaddr=1 sbbusy=1 sbbusyerror=1 sbversion=1_0 sbasize=0x40}
Debug: 1619 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @38 -> + 00000000 @38; 0i
Debug: 1620 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 20758807 @38; 0i
Debug: 1621 3719 riscv-013.c:428 riscv_decode_dmi_scan(): read: sbcs=0x20758807 {sbaccess8=1 sbaccess16=1 sbreadondata=1 sbautoincrement=1 sbaccess=32bit sbaccess32=1 sbreadonaddr=1 sbbusy=1 sbbusyerror=1 sbversion=1_0 sbasize=0x40}
Debug: 1622 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @38 -> + 00000000 @38; 0i
Debug: 1623 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 20558807 @38; 0i
Debug: 1624 3719 riscv-013.c:428 riscv_decode_dmi_scan(): read: sbcs=0x20558807 {sbaccess8=1 sbaccess16=1 sbreadondata=1 sbautoincrement=1 sbaccess=32bit sbaccess32=1 sbreadonaddr=1 sbbusyerror=1 sbversion=1_0 sbasize=0x40}
Debug: 1625 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b w 00150000 @38 -> + 00000000 @38; 0i
Debug: 1626 3719 riscv-013.c:438 riscv_decode_dmi_scan(): write: sbcs=0x150000 {sbautoincrement=1 sbaccess=32bit sbreadonaddr=1}
Debug: 1627 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 00150000 @38; 0i
Debug: 1628 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b w 00400000 @38 -> + 00000000 @38; 0i
Debug: 1629 3719 riscv-013.c:438 riscv_decode_dmi_scan(): write: sbcs=0x400000 {sbbusyerror=1}
Debug: 1630 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 00400000 @38; 0i
Debug: 1631 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @3a -> + 00000000 @38; 0i
Debug: 1632 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @3a -> + 00000000 @3a; 0i
Debug: 1633 3719 riscv-013.c:428 riscv_decode_dmi_scan(): read: 
Debug: 1634 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @39 -> + 00000000 @3a; 0i
Debug: 1635 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @39 -> + 40000004 @39; 0i
Debug: 1636 3719 riscv-013.c:428 riscv_decode_dmi_scan(): read: 
Debug: 1637 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @3c -> + 00000000 @39; 0i
Debug: 1638 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @3c -> + 5555aaaa @3c; 0i
Debug: 1639 3720 riscv-013.c:428 riscv_decode_dmi_scan(): read: 
Debug: 1640 3720 riscv-013.c:3216 log_memory_access64(): M[0x40000000] reads 0x5555aaaa
Debug: 1641 3720 riscv-013.c:3558 read_memory_bus_v1(): [riscv.cpu0] Increasing bus_master_read_delay to 1.
Debug: 1642 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b w 00158000 @38 -> + 00000000 @3c; 0i
Debug: 1643 3720 riscv-013.c:438 riscv_decode_dmi_scan(): write: sbcs=0x158000 {sbreadondata=1 sbautoincrement=1 sbaccess=32bit sbreadonaddr=1}
Debug: 1644 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 00158000 @38; 0i
Debug: 1645 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b w 00000000 @3a -> + 00000000 @38; 0i
Debug: 1646 3720 riscv-013.c:438 riscv_decode_dmi_scan(): write: 
Debug: 1647 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b w 40000004 @39 -> + 00000000 @3a; 0i
Debug: 1648 3720 riscv-013.c:438 riscv_decode_dmi_scan(): write: 
Debug: 1649 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @39 -> + 40000004 @39; 0i
Debug: 1650 3720 riscv-013.c:3435 read_memory_bus_v1(): [riscv.cpu0] Waiting 1 cycles for bus master read delay
Debug: 1651 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @00 -> + 00000000 @39; 0i
Debug: 1652 3720 riscv-013.c:428 riscv_decode_dmi_scan(): read: 
Debug: 1653 3720 riscv-013.c:3216 log_memory_access64(): M[0x3fffffff] reads 0x00000000
Debug: 1654 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @38 -> + 00000000 @00; 0i
Debug: 1655 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 20358807 @38; 0i
Debug: 1656 3720 riscv-013.c:428 riscv_decode_dmi_scan(): read: sbcs=0x20358807 {sbaccess8=1 sbaccess16=1 sbreadondata=1 sbautoincrement=1 sbaccess=32bit sbaccess32=1 sbreadonaddr=1 sbbusy=1 sbversion=1_0 sbasize=0x40}
Debug: 1657 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @38 -> + 00000000 @38; 0i
Debug: 1658 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 20358807 @38; 0i
Debug: 1659 3720 riscv-013.c:428 riscv_decode_dmi_scan(): read: sbcs=0x20358807 {sbaccess8=1 sbaccess16=1 sbreadondata=1 sbautoincrement=1 sbaccess=32bit sbaccess32=1 sbreadonaddr=1 sbbusy=1 sbversion=1_0 sbasize=0x40}
Debug: 1660 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @38 -> + 00000000 @38; 0i
Debug: 1661 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 20158807 @38; 0i
Debug: 1662 3720 riscv-013.c:428 riscv_decode_dmi_scan(): read: sbcs=0x20158807 {sbaccess8=1 sbaccess16=1 sbreadondata=1 sbautoincrement=1 sbaccess=32bit sbaccess32=1 sbreadonaddr=1 sbversion=1_0 sbasize=0x40}
Debug: 1663 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b w 00150000 @38 -> + 00000000 @38; 0i
Debug: 1664 3720 riscv-013.c:438 riscv_decode_dmi_scan(): write: sbcs=0x150000 {sbautoincrement=1 sbaccess=32bit sbreadonaddr=1}
Debug: 1665 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 00150000 @38; 0i
Debug: 1666 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @3c -> + 00000000 @38; 0i
Debug: 1667 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @3c -> + 08675309 @3c; 0i
Debug: 1668 3720 riscv-013.c:428 riscv_decode_dmi_scan(): read: 
Debug: 1669 3720 riscv-013.c:3216 log_memory_access64(): M[0x40000004] reads 0x08675309
Debug: 1670 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @38 -> + 00000000 @3c; 0i
Debug: 1671 3720 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 20150807 @38; 0i
Debug: 1672 3720 riscv-013.c:428 riscv_decode_dmi_scan(): read: sbcs=0x20150807 {sbaccess8=1 sbaccess16=1 sbautoincrement=1 sbaccess=32bit sbaccess32=1 sbreadonaddr=1 sbversion=1_0 sbasize=0x40}

I see that after first read (when no sbbusy was set). I receive sbbusyerror in status. While only one read was triggered.

[en-sc]

Regarding https://github.com/riscv-collab/riscv-openocd/issues/1080, this particular issue is with OpenOCD. Please, see https://github.com/riscv-collab/riscv-openocd/pull/1081#issuecomment-2199791096 for the analysis and the fix.

[en-sc]

A question about sbbusyerror model in Debug module. #1513 I suppose triggering of sbbusyerror flag is not certain. In Debug spec sbbusyerror is set when next read is started before the previous is done. But in current implementation sbbusyerror is set every time reading of any DM_SBDATA is processed.

AFAIU, you are refering to debug_module_t::dmi_read(): https://github.com/riscv-software-src/riscv-isa-sim/blob/1b1a333763eae2e74dbf38b39d9adab39c4bed7c/riscv/debug_module.cc#L551-L560

I don't quite understand what you mean by "in current implementation sbbusyerror is set every time reading of any DM_SBDATA is processed" My understanding is debug_module_t::sb_busy() returns true iff a read or write is in progress. https://github.com/riscv-software-src/riscv-isa-sim/blob/1b1a333763eae2e74dbf38b39d9adab39c4bed7c/riscv/debug_module.cc#L301-L304 So it's exactly as specified in RISC-V Debug Specification, version 1.0.0-rc3 [3.14.22. System Bus Access Control and Status (sbcs, at 0x38)], sbbusyerror field description:

Set when the debugger attempts to read data while a read is in progress, or when the debugger initiates a new access while one is already in progress (while sbbusy is set).

[en-sc]

In the log you have attached, the read of 8 bytes is requested. However, for whatever reason it is split into two reads of 4 bytes (I'd bet it is caused by XLEN being 32). This can be seen by checking that there are no reads of sbdata1 (at 0x3d). sbbusyerror is caused by the second read, not the first one. This is evident by the read of sbaddress*:

Debug: 1631 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @3a -> + 00000000 @38; 0i
Debug: 1632 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @3a -> + 00000000 @3a; 0i
Debug: 1633 3719 riscv-013.c:428 riscv_decode_dmi_scan(): read: 
Debug: 1634 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @39 -> + 00000000 @3a; 0i
Debug: 1635 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @39 -> + 40000004 @39; 0i

The address read is 0x40000004. If the first read have resulted in sbbusyerror, it would have been 0x40000000 in case the first read caused the error. So this is essentially the same issue as in https://github.com/riscv-collab/riscv-openocd/issues/1080 and should be fixed by https://github.com/riscv-collab/riscv-openocd/pull/1081

[fborisovskii]

Hello,

Thank you for reply. Log is the result of reading long long variable from rv32 core. And it is split to two 4 byte transactions via system bus access. I've tried fix attached to the issue in openOCD and it doesn't work for me.

I missed that sbreadondata=1 is set So the error is for the second read - this is true. But this read is triggered when the first half data is read I suppose

Debug: 1613 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @00 -> + deadbeef @3c; 0i
Debug: 1614 3719 riscv-013.c:428 riscv_decode_dmi_scan(): read: 
Debug: 1615 3719 riscv-013.c:3216 log_memory_access64(): M[0x40000000] reads 0xdeadbeef
Debug: 1616 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b r 00000000 @38 -> + 00000000 @00; 0i
Debug: 1617 3719 riscv-013.c:417 riscv_decode_dmi_scan(): 40b - 00000000 @38 -> + 20758807 @38; 0i

So this must be openOCD issue. But there is one thing I disagree. https://github.com/riscv-software-src/riscv-isa-sim/blob/1b1a333763eae2e74dbf38b39d9adab39c4bed7c/riscv/debug_module.cc#L551-L560

Why sbbusyerror is set whithout sbcs.readondata check? Such a read has to set only busy flag. Not sbbusyerror flag. So I expect something like that

case DM_SBDATA0:
result = sbdata[0];
if (sb_busy()) {
  sbcs.sbbusyerror = sbcs.readondata;
} else if (sbcs.error == 0) {
  if (sbcs.readondata) {
    sb_read_start();
  }
}
break;

Set when the debugger attempts to read data while a read is in progress, or when the debugger initiates a new access while one is already in progress (while sbbusy is set).

With this comment it becomes clear.

Thank you. I'm closing this issue. The problem is in openOCD side.

[en-sc]

@fborisovskii, please file an OpenOCD issue https://github.com/riscv-collab/riscv-openocd/issues/new/. Attaching full logs before/after https://github.com/riscv-collab/riscv-openocd/pull/1084 is applied would be very helpful.

[fborisovskii]

@fborisovskii, please file an OpenOCD issue https://github.com/riscv-collab/riscv-openocd/issues/new/. Attaching full logs before/after riscv-collab/riscv-openocd#1084 is applied would be very helpful.

Of cause. I'll try to check it again. Last I tried on friday. I see you have changed it a bit since friday. I remember on friday compare-sections broke in rv64 cores after applying that change. I'll give it a try again.

[fborisovskii]

Hello,

With https://github.com/riscv-collab/riscv-openocd/pull/1081 and https://github.com/riscv-collab/riscv-openocd/pull/1084 together error is fixed.

With only https://github.com/riscv-collab/riscv-openocd/pull/1084 behavior is the same.

2024-07-01 20:21:02,042 gdb      INFO     Command: p/x sizeof(long long)
2024-07-01 20:21:02,042 gdb      INFO       Output: $1 = 0x8

2024-07-01 20:21:02,042 gdb      INFO     Command: p/x *((long long*)0x40000000) = 0x86753095555aaaa
2024-07-01 20:21:02,043 gdb      INFO       Output: $2 = 0x86753095555aaaa

2024-07-01 20:21:02,043 gdb      INFO     Command: p/x *((long long*)0x4003fff8) = 0xdeadbeef12345678
2024-07-01 20:21:02,044 gdb      INFO       Output: $3 = 0xdeadbeef12345678

2024-07-01 20:21:02,044 gdb      INFO     Command: p/x *((long long*)0x40000000)
2024-07-01 20:21:02,045 gdb      INFO       Output: $4 = 0x867530900000000

2024-07-01 20:21:02,045 gdb      ERROR    

openocd (2).txt

I think after both changes merge the issue will be fixed.

[en-sc]

@fborisovskii, I'm really sorry, I've meant https://github.com/riscv-collab/riscv-openocd/pull/1081 in https://github.com/riscv-software-src/riscv-isa-sim/issues/1712#issuecomment-2200374357. https://github.com/riscv-collab/riscv-openocd/pull/1084 is irrelevant to this issue.