I think we have only two ways:
1) Risk regression on scripts
2) Make a hack to detect 'expr' in jim_command_dispatch() and suppress
target_call_timer_callbacks_now().
Considering the expr syntax workaround is mentioned to be dropped after 0.12
release, I would temporarily accept hackish 2)
---
** [tickets:#362] Script performance degradation due to jim_command_dispatch()
/ target_call_timer_callbacks_now()**
**Status:** new
**Milestone:** 0.11.0
**Created:** Thu Sep 01, 2022 07:13 PM UTC by Andrey
**Last Updated:** Mon Sep 05, 2022 09:41 AM UTC
**Owner:** nobody
Hi,
As of current master we are seeing a severe degradation in the performance of
executing some of the TCL scripts (some of our scripts have to pre-process
binaries for specific targets or e.g. calculate CRC32).
We've traced this down to target_call_timer_callbacks_now() call in
jim_command_dispatch() causing a call into the debugger (target_poll()) on
pretty much every expression in the TCL script when the script is executing
while the target is initialized:
~~~
Debug: 8025 4650 command.c:166 script_debug(): command - expr ($crc_value ^
[scan $c %c])&0xff
Debug: 8026 4650 cmsis_dap.c:778 cmsis_dap_swd_write_from_queue(): Executing 2
queued transactions from FIFO index 0
Debug: 8027 4650 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): AP read reg
0 0
Debug: 8028 4650 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): DP read reg
c 0
Debug: 8029 4654 cmsis_dap.c:893 cmsis_dap_swd_read_process(): Received results
of 2 queued transactions FIFO index 0
Debug: 8030 4654 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
Debug: 8031 4654 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
Debug: 8032 4654 command.c:166 script_debug(): command - expr [lindex $CRCTABLE
[expr {($crc_value ^ [scan $c %c])&0xff}]]^(($crc_value>>8)&0xffffff)
Debug: 8033 4654 cmsis_dap.c:778 cmsis_dap_swd_write_from_queue(): Executing 2
queued transactions from FIFO index 0
Debug: 8034 4654 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): AP read reg
0 0
Debug: 8035 4654 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): DP read reg
c 0
Debug: 8036 4658 cmsis_dap.c:893 cmsis_dap_swd_read_process(): Received results
of 2 queued transactions FIFO index 0
Debug: 8037 4658 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
Debug: 8038 4658 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
Debug: 8039 4658 command.c:166 script_debug(): command - expr ($crc_value ^
[scan $c %c])&0xff
Debug: 8040 4658 cmsis_dap.c:778 cmsis_dap_swd_write_from_queue(): Executing 2
queued transactions from FIFO index 0
Debug: 8041 4658 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): AP read reg
0 0
Debug: 8042 4658 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): DP read reg
c 0
Debug: 8043 4662 cmsis_dap.c:893 cmsis_dap_swd_read_process(): Received results
of 2 queued transactions FIFO index 0
Debug: 8044 4662 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
Debug: 8045 4662 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
Debug: 8046 4662 command.c:166 script_debug(): command - expr [lindex $CRCTABLE
[expr {($crc_value ^ [scan $c %c])&0xff}]]^(($crc_value>>8)&0xffffff)
Debug: 8047 4662 cmsis_dap.c:778 cmsis_dap_swd_write_from_queue(): Executing 2
queued transactions from FIFO index 0
Debug: 8048 4662 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): AP read reg
0 0
Debug: 8049 4662 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): DP read reg
c 0
Debug: 8050 4666 cmsis_dap.c:893 cmsis_dap_swd_read_process(): Received results
of 2 queued transactions FIFO index 0
Debug: 8051 4666 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
Debug: 8052 4666 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
Debug: 8053 4666 command.c:166 script_debug(): command - expr ($crc_value ^
[scan $c %c])&0xff
Debug: 8054 4666 cmsis_dap.c:778 cmsis_dap_swd_write_from_queue(): Executing 2
queued transactions from FIFO index 0
Debug: 8055 4666 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): AP read reg
0 0
Debug: 8056 4666 cmsis_dap.c:798 cmsis_dap_swd_write_from_queue(): DP read reg
c 0
Debug: 8057 4670 cmsis_dap.c:893 cmsis_dap_swd_read_process(): Received results
of 2 queued transactions FIFO index 0
Debug: 8058 4670 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
Debug: 8059 4670 cmsis_dap.c:904 cmsis_dap_swd_read_process(): Read result:
30003
...
~~~
Stack trace:
~~~
#0 0x00007f954db3892f in write () from /lib64/libc.so.6
#1 0x00007f954dd39c1e in hid_write () from /lib64/libhidapi-hidraw.so.0
#2 0x000000000041cf95 in cmsis_dap_hid_write (dap=0x242c720, txlen=<optimized
out>, timeout_ms=<optimized out>) at src/jtag/drivers/cmsis_dap_usb_hid.c:207
#3 0x0000000000418b92 in cmsis_dap_swd_write_from_queue (dap=<optimized out>)
at src/jtag/drivers/cmsis_dap.c:829
#4 0x00000000004190ca in cmsis_dap_swd_run_queue () at
src/jtag/drivers/cmsis_dap.c:929
#5 0x0000000000448974 in swd_run_inner (dap=0x2210c30) at
src/target/adi_v5_swd.c:97
#6 swd_run (dap=0x2210c30) at src/target/adi_v5_swd.c:553
#7 swd_run (dap=0x2210c30) at src/target/adi_v5_swd.c:545
#8 0x00000000005346dd in cortex_m_read_dhcsr_atomic_sticky (target=0x21c8660)
at src/target/cortex_m.c:142
#9 cortex_m_poll (target=0x21c8660) at src/target/cortex_m.c:882
#10 0x000000000045f2c9 in target_poll (target=0x21c8660) at
src/target/target.c:567
#11 0x00000000004605f8 in handle_target (priv=<optimized out>) at
src/target/target.c:3056
#12 handle_target (priv=<optimized out>) at src/target/target.c:2979
#13 0x00000000004570e1 in target_call_timer_callback (now=<synthetic pointer>,
cb=0x242c6e0) at src/target/target.c:1895
#14 target_call_timer_callbacks_check_time (checktime=checktime@entry=0) at
src/target/target.c:1939
#15 0x000000000045b46b in target_call_timer_callbacks_check_time (checktime=0)
at src/target/target.c:1958
#16 target_call_timer_callbacks_now () at src/target/target.c:1959
#17 0x000000000048649d in jim_command_dispatch (interp=0x2182300, argc=2,
argv=0x7ffccf92db20) at src/helper/command.c:952
#18 0x00000000005c01ca in JimInvokeCommand (interp=interp@entry=0x2182300,
objc=2, objv=objv@entry=0x7ffccf92db20) at jim.c:10682
#19 0x00000000005c0aa9 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=0x5d1ae30) at jim.c:11175
#20 0x00000000005c0b58 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=0x21dde10) at jim.c:11108
#21 0x00000000005bfc7e in JimCallProcedure (interp=interp@entry=0x2182300,
cmd=cmd@entry=0x221f150, argc=argc@entry=3, argv=argv@entry=0x7ffccf92dd60)
at jim.c:11421
#22 0x00000000005c02a5 in JimInvokeCommand (interp=interp@entry=0x2182300,
objc=3, objv=objv@entry=0x7ffccf92dd60) at jim.c:10678
#23 0x00000000005c0aa9 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=0x5d1a560) at jim.c:11175
#24 0x00000000005c0b58 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=scriptObjPtr@entry=0x245d610) at jim.c:11108
#25 0x00000000005ca85a in JimForeachMapHelper (interp=<optimized out>,
argc=<optimized out>, argv=<optimized out>, doMap=0) at jim.c:12497
#26 0x00000000005c01ca in JimInvokeCommand (interp=interp@entry=0x2182300,
objc=4, objv=objv@entry=0x7ffccf92dff0) at jim.c:10682
#27 0x00000000005c0aa9 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=0x21dd9f0) at jim.c:11175
#28 0x00000000005bfc7e in JimCallProcedure (interp=interp@entry=0x2182300,
cmd=cmd@entry=0x221f330, argc=argc@entry=2, argv=argv@entry=0x7ffccf92e170)
at jim.c:11421
#29 0x00000000005c02a5 in JimInvokeCommand (interp=interp@entry=0x2182300,
objc=2, objv=objv@entry=0x7ffccf92e170) at jim.c:10678
#30 0x00000000005c0aa9 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=0x245ee20) at jim.c:11175
#31 0x00000000005c0b58 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=0x21dd5d0) at jim.c:11108
#32 0x00000000005bfc7e in JimCallProcedure (interp=interp@entry=0x2182300,
cmd=cmd@entry=0x221f500, argc=argc@entry=2, argv=argv@entry=0x7ffccf92e3b0)
at jim.c:11421
#33 0x00000000005c02a5 in JimInvokeCommand (interp=interp@entry=0x2182300,
objc=2, objv=objv@entry=0x7ffccf92e3b0) at jim.c:10678
#34 0x00000000005c0aa9 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=0x2453b40) at jim.c:11175
#35 0x00000000005c0b58 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=0x21dfc40) at jim.c:11108
#36 0x00000000005bfc7e in JimCallProcedure (interp=interp@entry=0x2182300,
cmd=cmd@entry=0x221e840, argc=argc@entry=5, argv=argv@entry=0x7ffccf92e5f0)
at jim.c:11421
#37 0x00000000005c02a5 in JimInvokeCommand (interp=interp@entry=0x2182300,
objc=5, objv=objv@entry=0x7ffccf92e5f0) at jim.c:10678
#38 0x00000000005c0aa9 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=0x21e0060) at jim.c:11175
#39 0x00000000005bfc7e in JimCallProcedure (interp=interp@entry=0x2182300,
cmd=cmd@entry=0x221e650, argc=argc@entry=3, argv=argv@entry=0x7ffccf92e770)
at jim.c:11421
#40 0x00000000005c02a5 in JimInvokeCommand (interp=interp@entry=0x2182300,
objc=3, objv=objv@entry=0x7ffccf92e770) at jim.c:10678
#41 0x00000000005c0aa9 in Jim_EvalObj (interp=interp@entry=0x2182300,
scriptObjPtr=scriptObjPtr@entry=0x21f0d00) at jim.c:11175
#42 0x00000000005c16ab in Jim_EvalSource (interp=interp@entry=0x2182300,
filename=filename@entry=0x0, lineno=lineno@entry=0,
script=script@entry=0x21b40d0 "rtl872x_flash_write_bin
p2-system-pa...@5.0.0.bin 0x8060000") at jim.c:11470
#43 0x000000000048609f in command_run_line (context=context@entry=0x21822a0,
line=0x21b40d0 "rtl872x_flash_write_bin p2-system-pa...@5.0.0.bin
0x8060000") at src/helper/command.c:591
#44 0x0000000000487928 in parse_config_file (cmd_ctx=cmd_ctx@entry=0x21822a0)
at src/helper/configuration.c:136
#45 0x000000000040687d in openocd_thread (cmd_ctx=0x21822a0,
argv=0x7ffccf92e9d8, argc=17) at src/openocd.c:356
#46 openocd_main (argc=17, argv=0x7ffccf92e9d8) at src/openocd.c:416
#47 0x00007f954da60550 in __libc_start_call_main () from /lib64/libc.so.6
#48 0x00007f954da60609 in __libc_start_main_impl () from /lib64/libc.so.6
#49 0x0000000000406205 in _start ()
~~~
---
Sent from sourceforge.net because openocd-devel@lists.sourceforge.net is
subscribed to https://sourceforge.net/p/openocd/tickets/
To unsubscribe from further messages, a project admin can change settings at
https://sourceforge.net/p/openocd/admin/tickets/options. Or, if this is a
mailing list, you can unsubscribe from the mailing list.
