Examination fails after dap returns `busy`

[NikLeberg]

Hi there!

Some prosa for context:
I'm currently developing a VHDL TAP for cosimulating RISC-V cores and also actually debug them with GDB through OpenOCD. I don't want to bore you with the details so to keep it short: I previously used the remote_bitbang driver which worked great albeit very slow. Now I changed to the jtag_dpi and everything is ~10x faster. Great! Feel free to take a look. Only that it could be very much faster still. See below.

The actual problem I have is, that as soon as the DAP returns a busy, all communication comes to an halt. After such an event I receive via the jtag_dpi driver only ever ib commands i.e. ir scans. The dr is never read anymore.

Debug log of failed examination (due to busy?)

Open On-Chip Debugger 0.12.0+dev-g6f84e90 (2025-08-07-15:13)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
User : 3 3 options.c:52 configuration_output_handler(): debug_level: 3User : 4 3 options.c:52 configuration_output_handler(): 
Debug: 5 3 options.c:348 parse_cmdline_args(): ARGV[0] = "/opt/openocd/openocd"
Debug: 6 3 options.c:348 parse_cmdline_args(): ARGV[1] = "-f"
Debug: 7 3 options.c:348 parse_cmdline_args(): ARGV[2] = "openocd.cfg"
Debug: 8 3 options.c:348 parse_cmdline_args(): ARGV[3] = "-d"
Debug: 9 4 options.c:233 add_default_dirs(): bindir=/usr/local/bin
Debug: 10 4 options.c:234 add_default_dirs(): pkgdatadir=/usr/local/share/openocd
Debug: 11 4 options.c:235 add_default_dirs(): exepath=/opt/openocd
Debug: 12 4 options.c:236 add_default_dirs(): bin2data=../share/openocd
Debug: 13 4 configuration.c:33 add_script_search_dir(): adding /root/.config/openocd
Debug: 14 4 configuration.c:33 add_script_search_dir(): adding /root/.openocd
Debug: 15 4 configuration.c:33 add_script_search_dir(): adding /opt/openocd/../share/openocd/site
Debug: 16 4 configuration.c:33 add_script_search_dir(): adding /opt/openocd/../share/openocd/scripts
Debug: 17 4 command.c:154 script_debug(): command - ocd_find openocd.cfg
Debug: 18 4 configuration.c:88 find_file(): found openocd.cfg
Debug: 19 4 command.c:154 script_debug(): command - adapter driver jtag_dpi
Info : 20 4 transport.c:107 allow_transports(): only one transport option; autoselecting 'jtag'
Debug: 21 4 command.c:154 script_debug(): command - jtag_dpi set_port 5555
Info : 22 4 jtag_dpi.c:331 jtag_dpi_set_port(): Set server port to 5555
Debug: 23 4 command.c:154 script_debug(): command - jtag_dpi set_address 127.0.0.1
Info : 24 4 jtag_dpi.c:359 jtag_dpi_set_address(): Set server address to 127.0.0.1
Debug: 25 4 command.c:154 script_debug(): command - transport select jtag
Warn : 26 4 transport.c:232 handle_transport_select(): Transport "jtag" was already selected
Debug: 27 4 command.c:154 script_debug(): command - reset_config trst_only
Debug: 28 4 command.c:154 script_debug(): command - jtag newtap riscv cpu -irlen 5 -expected-id 0x00000001
Debug: 29 4 tcl.c:404 handle_jtag_newtap_args(): Creating New Tap, Chip: riscv, Tap: cpu, Dotted: riscv.cpu, 4 params
Debug: 30 4 core.c:1488 jtag_tap_init(): Created Tap: riscv.cpu @ abs position 0, irlen 5, capture: 0x1 mask: 0x3
Debug: 31 4 command.c:154 script_debug(): command - target create riscv.cpu riscv -chain-position riscv.cpu -rtos hwthread
Debug: 32 4 target.c:2145 target_free_all_working_areas_restore(): freeing all working areas
Info : 33 4 hwthread.c:418 hwthread_create(): [riscv.cpu] Hardware thread awareness created
Debug: 34 4 riscv.c:494 riscv_create_target(): [riscv.cpu] riscv_create_target()
Debug: 35 4 command.c:154 script_debug(): command - riscv set_reset_timeout_sec 120
Warn : 36 4 riscv.c:4322 riscv_set_reset_timeout_sec(): The command 'riscv set_reset_timeout_sec' is deprecated! Please, use 'riscv set_command_timeout_sec'.
Debug: 37 4 command.c:154 script_debug(): command - riscv set_command_timeout_sec 120
Debug: 38 4 command.c:154 script_debug(): command - riscv.cpu configure -event gdb-detach shutdown
Debug: 39 4 command.c:154 script_debug(): command - init
Debug: 40 4 command.c:154 script_debug(): command - target init
Debug: 41 4 command.c:154 script_debug(): command - target names
Debug: 42 4 command.c:154 script_debug(): command - riscv.cpu cget -event gdb-flash-erase-start
Debug: 43 4 command.c:154 script_debug(): command - riscv.cpu configure -event gdb-flash-erase-start reset init
Debug: 44 4 command.c:154 script_debug(): command - riscv.cpu cget -event gdb-flash-write-end
Debug: 45 4 command.c:154 script_debug(): command - riscv.cpu configure -event gdb-flash-write-end reset halt
Debug: 46 4 command.c:154 script_debug(): command - riscv.cpu cget -event gdb-attach
Debug: 47 4 command.c:154 script_debug(): command - riscv.cpu configure -event gdb-attach halt 1000
Debug: 48 4 target.c:1603 handle_target_init_command(): Initializing targets...
Debug: 49 4 riscv.c:666 riscv_init_target(): [riscv.cpu] riscv_init_target()
Debug: 50 4 semihosting_common.c:109 semihosting_common_init():  
Info : 51 5 jtag_dpi.c:310 jtag_dpi_init(): Connection to 127.0.0.1 : 5555 succeed
Info : 52 5 adapter.c:157 adapter_init(): Note: The adapter "jtag_dpi" doesn't support configurable speed
Debug: 53 5 openocd.c:133 handle_init_command(): Debug Adapter init complete
Debug: 54 5 command.c:154 script_debug(): command - transport init
Debug: 55 5 transport.c:171 handle_transport_init(): handle_transport_init
Debug: 56 5 core.c:843 jtag_add_reset(): SRST line released
Debug: 57 5 core.c:868 jtag_add_reset(): TRST line released
Debug: 58 5 core.c:334 jtag_call_event_callbacks(): jtag event: TAP reset
Debug: 59 5 command.c:154 script_debug(): command - jtag arp_init
Debug: 60 5 core.c:1522 jtag_init_inner(): Init JTAG chain
Debug: 61 5 core.c:334 jtag_call_event_callbacks(): jtag event: TAP reset
Debug: 62 5 core.c:1248 jtag_examine_chain(): DR scan interrogation for IDCODE/BYPASS
Debug: 63 5 core.c:334 jtag_call_event_callbacks(): jtag event: TAP reset
Debug: 64 6 jep106.c:22 jep106_table_manufacturer(): BUG: Caller passed out-of-range JEP106 ID!
Info : 65 6 core.c:1146 jtag_examine_chain_display(): JTAG tap: riscv.cpu tap/device found: 0x00000001 (mfg: 0x000 (<invalid>), part: 0x0000, ver: 0x0)
Debug: 66 6 core.c:1378 jtag_validate_ircapture(): IR capture validation scan
Debug: 67 8 core.c:1435 jtag_validate_ircapture(): riscv.cpu: IR capture 0x01
Debug: 68 8 command.c:154 script_debug(): command - dap init
Debug: 69 8 arm_dap.c:96 dap_init_all(): Initializing all DAPs ...
Debug: 70 8 openocd.c:150 handle_init_command(): Examining targets...
Debug: 71 8 target.c:684 target_examine_one(): [riscv.cpu] Examination started
Debug: 72 8 target.c:1789 target_call_event_callbacks(): target event 19 (examine-start) for core riscv.cpu
Debug: 73 8 riscv.c:2474 riscv_examine(): [riscv.cpu] Starting examination
Debug: 74 11 riscv.c:447 dtmcs_scan(): TAP riscv.cpu: DTMCS: 0x0 -> 0x7071
Debug: 75 11 riscv.c:2488 riscv_examine(): [riscv.cpu] dtmcontrol=0x7071
Debug: 76 11 riscv.c:2490 riscv_examine(): [riscv.cpu] version=0x1
Debug: 77 11 riscv-013.c:2857 init_target(): [riscv.cpu] Init.
Debug: 78 11 riscv-013.c:2002 examine(): [riscv.cpu] dbgbase=0x0
Debug: 79 16 riscv.c:447 dtmcs_scan(): TAP riscv.cpu: DTMCS: 0x0 -> 0x7071
Debug: 80 16 riscv-013.c:2010 examine(): [riscv.cpu] dtmcontrol=0x7071
Debug: 81 16 riscv-013.c:2011 examine(): [riscv.cpu] dtmcs=0x7071 {version=1_0 idle=7 errinfo=not_implemented abits=7}
Debug: 82 16 riscv-013.c:543 check_dbgbase_exists(): [riscv.cpu] Searching for DM with DMI base address (dbgbase) = 0x0
Debug: 83 16 riscv-013.c:296 get_dm(): [riscv.cpu] Coreid [0] Allocating new DM
Debug: 84 16 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 85 18 batch.c:255 log_batch(): 41b r 00000000 @10 -> + 00000000 @00; 0i
Debug: 86 18 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000000 @10; 0i
Debug: 87 18 batch.c:199 log_dmi_decoded(): read: dmcontrol=0 {}
Debug: 88 18 riscv-013.c:1879 reset_dm(): [riscv.cpu] Activating the DM.
Debug: 89 18 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 90 20 batch.c:255 log_batch(): 41b w 00000001 @10 -> + 00000000 @00; 0i
Debug: 91 20 batch.c:199 log_dmi_decoded(): write: dmcontrol=1 {dmactive=active}
Debug: 92 20 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000000 @10; 0i
Debug: 93 20 riscv-013.c:1885 reset_dm(): [riscv.cpu] Waiting for the DM to come out of reset.
Debug: 94 20 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 95 22 batch.c:255 log_batch(): 41b r 00000000 @10 -> + 00000000 @00; 0i
Debug: 96 22 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000001 @10; 0i
Debug: 97 22 batch.c:199 log_dmi_decoded(): read: dmcontrol=1 {dmactive=active}
Debug: 98 22 riscv-013.c:1899 reset_dm(): [riscv.cpu] DM successfully reset.
Debug: 99 22 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 100 23 batch.c:255 log_batch(): 41b w 07ffffc1 @10 -> + 00000001 @00; 0i
Debug: 101 23 batch.c:199 log_dmi_decoded(): write: dmcontrol=0x7ffffc1 {dmactive=active hartsello=0x3ff hasel=multiple hartselhi=0x3ff}
Debug: 102 23 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000001 @10; 0i
Debug: 103 23 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 104 25 batch.c:255 log_batch(): 41b r 00000000 @10 -> + 00000001 @00; 0i
Debug: 105 25 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000001 @10; 0i
Debug: 106 25 batch.c:199 log_dmi_decoded(): read: dmcontrol=1 {dmactive=active}
Debug: 107 25 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 108 27 batch.c:255 log_batch(): 41b w 00000001 @10 -> + 00000001 @00; 0i
Debug: 109 27 batch.c:199 log_dmi_decoded(): write: dmcontrol=1 {dmactive=active}
Debug: 110 27 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000001 @10; 0i
Debug: 111 27 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 112 29 batch.c:255 log_batch(): 41b r 00000000 @11 -> + 00000001 @00; 0i
Debug: 113 29 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00400c83 @11; 0i
Debug: 114 29 batch.c:199 log_dmi_decoded(): read: dmstatus=0x400c83 {version=1_0 anyrunning=1 allrunning=1 impebreak=1 authenticated=true}
Debug: 115 29 riscv-013.c:1982 examine_dm(): [riscv.cpu] Detected 1 harts.
Debug: 116 29 riscv-013.c:5419 riscv013_invalidate_cached_progbuf(): [riscv.cpu] Invalidating progbuf cache
Debug: 117 29 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 118 33 batch.c:255 log_batch(): 41b r 00000000 @11 -> + 00400c83 @00; 0i
Debug: 119 33 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00400c83 @11; 0i
Debug: 120 33 batch.c:199 log_dmi_decoded(): read: dmstatus=0x400c83 {version=1_0 anyrunning=1 allrunning=1 impebreak=1 authenticated=true}
Debug: 121 33 riscv-013.c:2073 examine(): [riscv.cpu] dmstatus:  0x00400c83
Debug: 122 33 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 123 35 batch.c:255 log_batch(): 41b r 00000000 @12 -> + 00400c83 @00; 0i
Debug: 124 35 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00111f80 @12; 0i
Debug: 125 35 batch.c:199 log_dmi_decoded(): read: 
Debug: 126 35 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 127 37 batch.c:255 log_batch(): 41b r 00000000 @38 -> + 00111f80 @00; 0i
Debug: 128 37 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000000 @38; 0i
Debug: 129 37 batch.c:199 log_dmi_decoded(): read: sbcs=0 {}
Debug: 130 37 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 131 39 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 00000000 @00; 0i
Debug: 132 39 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000801 @16; 0i
Debug: 133 39 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2000801 {datacount=1 relaxedpriv=relaxed_checks progbufsize=2}
Info : 134 39 riscv-013.c:2105 examine(): [riscv.cpu] datacount=1 progbufsize=2
Debug: 135 39 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 136 41 batch.c:255 log_batch(): 41b r 00000000 @11 -> + 02000801 @00; 0i
Debug: 137 41 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00400c83 @11; 0i
Debug: 138 41 batch.c:199 log_dmi_decoded(): read: dmstatus=0x400c83 {version=1_0 anyrunning=1 allrunning=1 impebreak=1 authenticated=true}
Debug: 139 41 riscv-013.c:5249 riscv013_halt_go(): [riscv.cpu] halting hart
Debug: 140 41 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 141 43 batch.c:255 log_batch(): 41b w 80000001 @10 -> + 00400c83 @00; 0i
Debug: 142 43 batch.c:199 log_dmi_decoded(): write: dmcontrol=0x80000001 {dmactive=active haltreq=1}
Debug: 143 43 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000001 @10; 0i
Debug: 144 43 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 145 46 batch.c:255 log_batch(): 41b r 00000000 @11 -> + 00000001 @00; 0i
Debug: 146 46 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00400c83 @11; 0i
Debug: 147 46 batch.c:199 log_dmi_decoded(): read: dmstatus=0x400c83 {version=1_0 anyrunning=1 allrunning=1 impebreak=1 authenticated=true}
Debug: 148 46 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 149 49 batch.c:255 log_batch(): 41b r 00000000 @11 -> + 00400c83 @00; 0i
Debug: 150 49 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00400383 @11; 0i
Debug: 151 49 batch.c:199 log_dmi_decoded(): read: dmstatus=0x400383 {version=1_0 impebreak=1 authenticated=true anyhalted=1 allhalted=1}
Debug: 152 49 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 153 51 batch.c:255 log_batch(): 41b w 00000001 @10 -> + 00400383 @00; 0i
Debug: 154 51 batch.c:199 log_dmi_decoded(): write: dmcontrol=1 {dmactive=active}
Debug: 155 51 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000001 @10; 0i
Debug: 156 51 riscv_reg.c:697 riscv_reg_impl_init_cache(): [riscv.cpu] create register cache for 4194 registers
Debug: 157 52 riscv-013.c:748 riscv013_execute_abstract_command(): [riscv.cpu] access register=0x321008 {regno=0x1008 write=arg0 transfer=enabled postexec=disabled aarpostincrement=disabled aarsize=64bit}
Debug: 158 52 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 3)
Debug: 159 55 batch.c:255 log_batch(): 41b w 00321008 @17 -> + 00000001 @00; 0i
Debug: 160 55 batch.c:199 log_dmi_decoded(): write: command=0x321008 {control=0x321008}
Debug: 161 55 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 00000000 @17; 0i
Debug: 162 55 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000a01 @16; 0i
Debug: 163 55 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2000a01 {datacount=1 relaxedpriv=relaxed_checks progbufsize=2 cmderr=not_supported}
Debug: 164 55 riscv-013.c:683 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] abstractcs=0x2000a01 {datacount=1 relaxedpriv=relaxed_checks busy=ready progbufsize=2 cmderr=not_supported}
Debug: 165 55 riscv-013.c:705 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] Abstract Command execution failed (abstractcs.cmderr = 2).
Debug: 166 55 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 167 58 batch.c:255 log_batch(): 41b w 00000700 @16 -> + 02000a01 @00; 0i
Debug: 168 58 batch.c:199 log_dmi_decoded(): write: abstractcs=0x700 {cmderr=other}
Debug: 169 58 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000a01 @16; 0i
Debug: 170 58 riscv-013.c:733 mark_command_as_unsupported(): [riscv.cpu] Caching the abstract command 0x321008 as not supported
Debug: 171 58 riscv-013.c:736 mark_command_as_unsupported(): [riscv.cpu] access register=0x321008 {regno=0x1008 write=arg0 transfer=enabled postexec=disabled aarpostincrement=disabled aarsize=64bit}
Debug: 172 59 riscv_reg.c:979 riscv_reg_get(): [riscv.cpu] Reading misa from target
Debug: 173 59 riscv-013.c:5119 riscv013_get_register(): [riscv.cpu] reading register misa
Debug: 174 59 riscv-013.c:1636 register_read_direct(): [riscv.cpu] Reading misa
Debug: 175 59 riscv-013.c:748 riscv013_execute_abstract_command(): [riscv.cpu] access register=0x220301 {regno=0x301 write=arg0 transfer=enabled postexec=disabled aarpostincrement=disabled aarsize=32bit}
Debug: 176 59 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 3)
Debug: 177 61 batch.c:255 log_batch(): 41b w 00220301 @17 -> + 02000a01 @00; 0i
Debug: 178 61 batch.c:199 log_dmi_decoded(): write: command=0x220301 {control=0x220301}
Debug: 179 61 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 00000000 @17; 0i
Debug: 180 61 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000a01 @16; 0i
Debug: 181 61 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2000a01 {datacount=1 relaxedpriv=relaxed_checks progbufsize=2 cmderr=not_supported}
Debug: 182 61 riscv-013.c:683 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] abstractcs=0x2000a01 {datacount=1 relaxedpriv=relaxed_checks busy=ready progbufsize=2 cmderr=not_supported}
Debug: 183 61 riscv-013.c:705 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] Abstract Command execution failed (abstractcs.cmderr = 2).
Debug: 184 61 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 185 66 batch.c:255 log_batch(): 41b w 00000700 @16 -> + 02000a01 @00; 0i
Debug: 186 66 batch.c:199 log_dmi_decoded(): write: abstractcs=0x700 {cmderr=other}
Debug: 187 66 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000a01 @16; 0i
Debug: 188 66 riscv-013.c:733 mark_command_as_unsupported(): [riscv.cpu] Caching the abstract command 0x220301 as not supported
Debug: 189 66 riscv-013.c:736 mark_command_as_unsupported(): [riscv.cpu] access register=0x220301 {regno=0x301 write=arg0 transfer=enabled postexec=disabled aarpostincrement=disabled aarsize=32bit}
Debug: 190 66 riscv-013_reg.c:375 riscv013_reg_save(): [riscv.cpu] Saving fp
Debug: 191 66 riscv_reg.c:979 riscv_reg_get(): [riscv.cpu] Reading fp from target
Debug: 192 66 riscv-013.c:5119 riscv013_get_register(): [riscv.cpu] reading register fp
Debug: 193 66 riscv-013.c:1636 register_read_direct(): [riscv.cpu] Reading fp
Debug: 194 66 riscv-013.c:748 riscv013_execute_abstract_command(): [riscv.cpu] access register=0x221008 {regno=0x1008 write=arg0 transfer=enabled postexec=disabled aarpostincrement=disabled aarsize=32bit}
Debug: 195 66 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 3)
Debug: 196 70 batch.c:255 log_batch(): 41b w 00221008 @17 -> + 02000a01 @00; 0i
Debug: 197 70 batch.c:199 log_dmi_decoded(): write: command=0x221008 {control=0x221008}
Debug: 198 70 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 00000000 @17; 0i
Debug: 199 70 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02001801 @16; 0i
Debug: 200 70 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2}
Debug: 201 70 riscv-013.c:683 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2 cmderr=none}
Debug: 202 70 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 203 72 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 02001801 @00; 0i
Debug: 204 72 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02001801 @16; 0i
Debug: 205 72 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2}
Debug: 206 72 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 207 74 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 02001801 @00; 0i
Debug: 208 74 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02001801 @16; 0i
Debug: 209 74 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2}
Debug: 210 74 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 211 80 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 02001801 @00; 0i
Debug: 212 80 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02001801 @16; 0i
Debug: 213 80 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2}
Debug: 214 80 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 215 81 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 02001801 @00; 0i
Debug: 216 81 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02001801 @16; 0i
Debug: 217 81 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2}
Debug: 218 81 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 219 86 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 02001801 @00; 0i
Debug: 220 86 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02001801 @16; 0i
Debug: 221 86 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2}
Debug: 222 86 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 223 88 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 02001801 @00; 0i
Debug: 224 88 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000801 @16; 0i
Debug: 225 88 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2000801 {datacount=1 relaxedpriv=relaxed_checks progbufsize=2}
Debug: 226 88 batch.h:86 riscv_scan_set_delay(): Abstract Command delay is set to 1.
Debug: 227 88 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 228 90 batch.c:255 log_batch(): 41b r 00000000 @04 -> + 02000801 @00; 0i
Debug: 229 90 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000000 @04; 0i
Debug: 230 90 batch.c:199 log_dmi_decoded(): read: 
Debug: 231 90 riscv-013.c:1655 register_read_direct(): [riscv.cpu] fp = 0x0
Debug: 232 90 riscv_reg.c:988 riscv_reg_get(): [riscv.cpu] Read fp: 0x0
Debug: 233 90 program.c:33 riscv_program_write(): [riscv.cpu] progbuf[00] = DASM(0x30102473)
Debug: 234 90 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 235 92 batch.c:255 log_batch(): 41b w 30102473 @20 -> + 00000000 @00; 0i
Debug: 236 92 batch.c:199 log_dmi_decoded(): write: 
Debug: 237 92 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000000 @20; 0i
Debug: 238 92 program.c:33 riscv_program_write(): [riscv.cpu] progbuf[01] = DASM(0x00100073)
Debug: 239 92 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 240 94 batch.c:255 log_batch(): 41b w 00100073 @21 -> + 00000000 @00; 0i
Debug: 241 94 batch.c:199 log_dmi_decoded(): write: 
Debug: 242 94 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000000 @21; 0i
Debug: 243 94 riscv-013.c:748 riscv013_execute_abstract_command(): [riscv.cpu] access register=0x241000 {regno=0x1000 write=arg0 transfer=disabled postexec=enabled aarpostincrement=disabled aarsize=32bit}
Debug: 244 94 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 3)

My current workaround is, to virtually slow the communication down so much such that a busy is never generated.

Debug log of successful examination (no busy /workaround):
openocd.log

I see that there are many layers to this. Softcore (stnolting's great NEORV32!), my TAP, jtag_dpi, ... I'm happy for any pointers or ideas.

Thanks!
Nik

[NikLeberg]

Found the bug!

In commit #0847a4d the use of int was changed to unsigned int. But the runtest loop in jtag_dpi.c#L192-L213 requires the cycles variable to got negative to stop the loop. With it being unsigned now, the variable wrapped around to INT_MAX and the loop was never terminated.

[en-sc]

Great catch!

Could you please also post -d4 log of the examination? I don't quite understand this part:

Debug: 194 66 riscv-013.c:748 riscv013_execute_abstract_command(): [riscv.cpu] access register=0x221008 {regno=0x1008 write=arg0 transfer=enabled postexec=disabled aarpostincrement=disabled aarsize=32bit}
Debug: 195 66 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 3)
Debug: 196 70 batch.c:255 log_batch(): 41b w 00221008 @17 -> + 02000a01 @00; 0i
Debug: 197 70 batch.c:199 log_dmi_decoded(): write: command=0x221008 {control=0x221008}
Debug: 198 70 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 00000000 @17; 0i
Debug: 199 70 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02001801 @16; 0i
Debug: 200 70 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2}
Debug: 201 70 riscv-013.c:683 abstract_cmd_batch_check_and_clear_cmderr(): [riscv.cpu] abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2 cmderr=none}
Debug: 202 70 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 203 72 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 02001801 @00; 0i
Debug: 204 72 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02001801 @16; 0i
Debug: 205 72 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2001801 {datacount=1 relaxedpriv=relaxed_checks busy=busy progbufsize=2}
...
Debug: 222 86 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 223 88 batch.c:255 log_batch(): 41b r 00000000 @16 -> + 02001801 @00; 0i
Debug: 224 88 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 02000801 @16; 0i
Debug: 225 88 batch.c:199 log_dmi_decoded(): read: abstractcs=0x2000801 {datacount=1 relaxedpriv=relaxed_checks progbufsize=2}
Debug: 226 88 batch.h:86 riscv_scan_set_delay(): Abstract Command delay is set to 1.
Debug: 227 88 batch.c:291 riscv_batch_run_from(): [riscv.cpu] Running batch of scans [0, 2)
Debug: 228 90 batch.c:255 log_batch(): 41b r 00000000 @04 -> + 02000801 @00; 0i
Debug: 229 90 batch.c:255 log_batch(): 41b - 00000000 @00 -> + 00000000 @04; 0i
Debug: 230 90 batch.c:199 log_dmi_decoded(): read: 

AFAIU, Abstract Command delay should increase (the Abstract Command delay is set to ... line) every time we get an abstractcs.busy, not just once.

[NikLeberg]

Hi @en-sc
I assume that was simply because of the bug with jtag_dpi for which I have sent a patch to upstream openocd. Thanks for voting there!
I guess, that after riscv_scan_set_delay(), a runtest is done. This triggers the bug and openocd falls into an (nearly) infinite loop.

As far as I'm concerned, we can close this issue.

[en-sc]

@NikLeberg, I'm sorry I don't buy this explanation :)

1. Log format is:

(Info|Debug|Error|...): <log_line_no> <time_ms> ...

From the log you have provided I don't see any significant spikes in the time it took to execute JTAG scan queue.
2. The bug you have found is in jtag_dpi_runtest() that is called from jtag_dpi_execute_queue():
https://github.com/NikLeberg/riscv-openocd/blob/fda708d03e4031483adcd551faa3ca7eaa8062dc/src/jtag/drivers/jtag_dpi.c#L231-L236 when processing commands of type JTAG_RUNTEST or JTAG_STABLECLOCKS. These commands are appended to the queue by the jtag_add_runtest() and jtag_add_clocks().
RISC-V code only calls jtag_add_runtest():

riscv-openocd/src/target/riscv/batch.c

Lines 304 to 305 in 6f84e90

	if (delay > 0)
	jtag_add_runtest(delay, TAP_IDLE);

riscv-openocd/src/target/riscv/batch.c

Line 141 in 6f84e90

jtag_add_runtest(idle_change, TAP_IDLE);

It's not called from add_idle_before_batch() because there is no associated logging:

riscv-openocd/src/target/riscv/batch.c

Lines 139 to 140 in 6f84e90

	LOG_TARGET_DEBUG(batch->target, "Adding %u idle cycles before the batch.",
	idle_change);

And it should not be called from riscv_batch_run_from() because the delay is zero (as reported in the log by the 0i part):

riscv-openocd/src/target/riscv/batch.c

Line 256 in 6f84e90

" -> %s %08" PRIx32 " @%02" PRIx32 "; %ui",

So my concern about Abstract Command delays seems valid. Could you please attach -d4 logs?

[NikLeberg]

Thanks for being to persistent!

I've attached the -d4 logs. But please note, there are no spikes in the JTAG queue execution time to be observed. Because the first time the upstream bug in jtag_dpi_runtest() is hit, OpenOCD completely locks up and loops (almost) forever. Only if the other end of the TCP socket (the HDL simulator) closes the connection, then more output is printed.

d4.log

[en-sc]

Thanks for the log!

I was wrong.

AFAIU, Abstract Command delay should increase (the Abstract Command delay is set to ... line) every time we get an abstractcs.busy, not just once.

This is not correct. The delay is increased once per command, not once per status check.