Menu
▾
▴
#362 Script performance degradation due to jim_command_dispatch() / target_call_timer_callbacks_now()
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-part1@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-part1@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 ()
Andrey,
thanks for reporting the problem.
git bisect revealed the regression comes from
c7eaaf620488 (openocd: prepare for jimtcl 0.81 'expr' syntax change)
https://review.openocd.org/c/openocd/+/6510
The performance degradation is related to 'expr' command only.
Antonio, could you propose a fix?
IMO target_call_timer_callbacks_now() is a hack which we should get rid of in the future. We can substitute calling all callbacks by calling the particular function we need, e.g. target poll.
But such change is too risky now, just before tagging 0.12 rc
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.
Didn't test but I'm sure this change will fix script performance degradation. Also the weird timing of target timers will be less broken.
On the other hand the change may trigger another regression. Some Tcl scripts may rely on polling the target before the execution of each OpenOCD command in the script. Would we take that risk now, before the release?
Yep, there could be side effects on scripts.
Andrey, what is the performance degradation that you see? Would it be acceptable for a release?
Antonio,
It's pretty terrible honestly at least for our use-case, which I understand might not be the most common one. As I mentioned previously we calculate CRC32 as part of the flashing process and compared to vanilla 0.11.0 it now takes up to 30 minutes to just flash 1MB binary vs under a minute via a relatively slow DAPLink debuggers which we use for test automation.
We've also tested last week that changing to target_call_timer_callbacks() does resolve the problem, but I'm not sure about other negative effects this change might cause.
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)
Andrey, possible workaround: use command 'poll off' before CRC and 'poll on' after?
But with a GDB attached, GDB could timeout...
Antonio,
Oh that's great. Thanks for the suggested workaround, can confirm that it does help and GDB is not a concern either as we talk to OpenOCD directly.
Andrey, Tomas,
could you please check this patch?
https://review.openocd.org/c/openocd/+/7174
Antonio,
Works great even without
poll offworkaround. Still about 2x slower compared to 0.11.0 in our CRC calculation specifically, but in absolute values it's just under a second overhead, nothing significant.Thanks!
It's strange that it's still slower than 0.11.0.
Do debug_level 3 traces show anything strange/different?