Tomas,
the reason "should" be linked to moving "expr" command from a jimtcl command to
an openocd command.
Running an openocd command triggers:
src/helper/command.c:939: target_call_timer_callbacks_now();
Here the correct call should be target_call_timer_callbacks().
Can you please verify that after such replacement the issue is fixed?
Historically, openocd try to implement its own timer callback; I think this was
even from before using jimtcl.
But if you run a long sequence of jimtcl TCL commands (with no openocd
commands in between) then the openocd timer callback gets never executed. This
causes the issue of, e.g. openocd not responsive to CTRL-C during a TCL loop.
But jimtcl has its own implementation of signals, including SIGALRM for time
callback. In my TODO list I have an item on investigate about moving CTRL-C
stuff using jim-signal.c. I will include SIGALRM too.
---
** [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:** Sun Sep 04, 2022 11:57 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.
