Congratulations, you have found a bug in the way OpenOCD handles keep-alive!
I confirm that the keep-alive message has no impact on your
programming example (so far).
As I already said, changing the timeout on gdb side does not avoid the
message, because the message is always sent by OpenOCD after one
second, even with gdb timeout unlimited.
If you want to "revert" at the situation before the broken commit
simply apply the patch in attachment, but it only silences the issue.
The bug:
the keep-alive implementation in OpenOCD consists in sending a zero
length string to gdb, to report that the remote target (OpenOCD) is
still alive.
When we send some real text (e.g. output of a command) to gdb, there
is no need to send an empty string as keep-alive, because we are
already sending something that informs gdb that the remote is still
alive.
The bug is that when we send some text we do not check if the timeout
has already expired; after we have sent the text in gdb_put_packet(),
we only reset the counter by calling kept_alive().
In your case, the flash programming takes only ~1.5 seconds, which is
not enough to let gdb timeout, but it's already over the one second
timeout of OpenOCD and gets not detected! Before 7f260f5009, the
message
wrote 61440 bytes from file egs_z.hex in 1.488253s (40.316 KiB/s)
was sent to gdb, thus resetting the counter with kept_alive(), without
alerting that the operation has exceeded 1 second! Bad!
After 7f260f5009 the message is not printed-out anymore (my attachment
makes it again printed) so the counter is not reset and immediately
after it is detected exceeding one second!
If you go ahead flashing your MCU (thousands times), the flash will
get older and slower. After some time it will take longer to flash and
it will exceed the 2 seconds causing gdb to timeout. Bad!
So we need to add some keep_alive() in the flashing code to avoid that.
Nevertheless, it is a bug to call kept_alive() in gdb_put_packet()
without checking the counter!
Plan:
I will put on gerrit a tentative patch that adds keep_alive during
"kinetis" flash write. Easy but I cannot test it, will rely on you as
tester and reviewer if you agree.
Then I will see how to quickly fix the keep-alive bug.
The patch in attachment ... I don't know! For each command there is
always the question of what should go in the log and what as command
returned value. In TCL only the command "puts" prints something, all
the other just return the value that can either be used or ignored.
But these flash write speed statistics have no real meaning as return
value, while quite interesting in the log. Maybe this patch should be
taken too!
Antonio
On Thu, May 28, 2020 at 3:42 PM Antonio Borneo <borneo.anto...@gmail.com> wrote:
>
> Oops, I made a mistake, sorry.
> I checked as if 2caa3455ad was the first broken commit, instead it it
> the last good!
> The broken one is 7f260f5009 and that is a big change.
> Let me check better...
>
> Antonio
>
> On Thu, May 28, 2020 at 3:30 PM Jonatan Hatakeyama Zeidler
> <jonatan.zeid...@medineering.de> wrote:
> >
> > Thanks for the fast reply! The output from commit 2caa3455ad (where
> > everything is good) is attached. The relevant part would be:
> >
> > ```
> >
> > ** Programming Started **
> > auto erase enabled
> > wrote 61440 bytes from file egs_z.hex in 1.488253s (40.316 KiB/s)
> > ** Programming Finished **
> >
> > ```
> >
> > It seems you are right and the program actually is flashed to the MCU
> > despite the warning and no output stating that the any byte had been
> > written (I should have checked that before).
> >
> > A `set remotetimeout unlimited` does not change anything about the
> > warning displayed. Is that expected?
> >
> > About your questions, yes I am sure about the Commits involved. If found
> > them via git bisect and I tested both various times, the last Commit
> > working well and the first one not working correctly. I am also sure
> > about the gdb script. Never used "flash banks". How can I provide more
> > information on that?
> >
> > Is there anything else I should provide to help fixing this?
> >
> > Thanks again for your help,
> >
> > Jonatan H. Zeidler
> >
> >
> > On 27.05.20 16:55, Antonio Borneo wrote:
> > > If it works fine with 2caa3455ad and get error with 7f260f5009 that's
> > > a regression!
> > > Could be interesting to see the logs with 2caa3455ad.
> > >
> > > Brief explanation.
> > > OpenOCD sends a keep-alive message to gdb using log messages. If gdb
> > > does not receive an answer from a command in 2 seconds it timeouts and
> > > stops waiting. OpenOCD informs the user when 1 second is already
> > > passed since last keep-alive, meaning that the timeout of 2 seconds is
> > > approaching!
> > > Changing the timeout in gdb helps avoiding issues on gdb side, but
> > > openocd will still print the message after 1 second.
> > >
> > > In your case, 1524 ms has passed since last keep-alive, so gdb has not
> > > timeout yet. You can verify that the flash is programmed correctly.
> > > Also, you do the programming using "monitor program myprog.hex"; I
> > > suspect gdb doesn't timeout in this case of "monitor" commands.
> > > Should still be fine for you.
> > >
> > > Nevertheless, there is a regression !
> > > As I wrote the keep-alive is implemented through log.
> > > The commit 7f260f5009 replaces one log with one write to a buffer,
> > > buffer that is not always printed out through log. This could explain
> > > the timeout message because there are less logs.
> > > But, that specific log in the commit is from the command "flash
> > > banks", that is not used in your script !!! How can this impact your
> > > case?
> > > I do not understand how that specific commit can introduce the
> > > regression! Are you sure the has involved are really 2caa3455ad and
> > > 7f260f5009 ?
> > > Anyway, the fix should be adding a dedicated call to keep-alive in the
> > > flashing algorithm.
> > >
> > > Antonio
> > >
> > > On Wed, May 27, 2020 at 2:50 PM Jonatan Hatakeyama Zeidler
> > > <jonatan.zeid...@medineering.de> wrote:
> > >> Hi there again,
> > >>
> > >> I just forgot to add some more information:
> > >>
> > >> OS: Ubuntu 16.04 (Linux L470-JHZ 4.15.0-101-generic #102~16.04.1-Ubuntu
> > >> SMP Mon May 11 11:38:16 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux)
> > >>
> > >> GDB: GNU gdb (7.10-1ubuntu3+9) 7.10 (arm-none-eabi-gdb)
> > >>
> > >> J-Link Segger: Version 10.1 S/N 50110571
> > >>
> > >> Also tried with gdb-multiarch on Ubuntu 20.04 with the same result. So
> > >> this shouldn't really matter.
> > >>
> > >> There are two MCUs behind the JLink (as you can see from the logs) and
> > >> both show the same consistent behaviour.
> > >>
> > >> Regards
> > >>
> > >> Jonatan H. Zeidler
> > >>
> > >>
> > >> On 27.05.20 13:03, Jonatan Hatakeyama Zeidler wrote:
> > >>
> > >> Hello,
> > >>
> > >> I am hitting an issue with OpenOCD and Segger JLink when trying to
> > >> program a Kinetis MCU (MK22FX512VLH12). Until Commit 2caa3455ad
> > >> everything is fine, starting with Commit 7f260f5009 and up to latest
> > >> master d8ac0086f9 initial flashing without using the device's memory map
> > >> fails. The error message indicates that increasing the timeout limit
> > >> might help. Executing a "set remotetimeout unlimited" does not change
> > >> anything about the issue and the message displayed though.
> > >>
> > >> # OpenOCD
> > >>
> > >> ```
> > >>
> > >> $ openocd -f interface/jlink.cfg -f myboard.cfg -c 'gdb_memory_map
> > >> disable'
> > >>
> > >> [...]
> > >>
> > >> ** Programming Started **
> > >> Warn : keep_alive() was not invoked in the 1000ms timelimit. GDB alive
> > >> packet not sent! (1524). Workaround: increase "set remotetimeout" in GDB
> > >> ** Programming Finished **
> > >>
> > >> [...]
> > >>
> > >> ```
> > >>
> > >> Complete output is attached as openocd.log.
> > >>
> > >> In constrast what this part looks like when it is working (e.g. on
> > >> 2caa3455ad):
> > >>
> > >> ```
> > >>
> > >> ** Programming Started **
> > >> auto erase enabled
> > >> wrote 61440 bytes from file myprog.hex in 1.517295s (39.544 KiB/s)
> > >> ** Programming Finished **
> > >>
> > >> ```
> > >>
> > >>
> > >> # GDB
> > >>
> > >> ```
> > >>
> > >> $ arm-none-eabi-gdb -ex 'set confirm off' -ex 'target remote
> > >> localhost:3337' -ex 'mon kinetis mdm halt' -ex 'mon reset init' -ex 'mon
> > >> program myprog.hex' -ex 'quit'
> > >>
> > >> ```
> > >>
> > >> Complete output is attached as gdb.log.
> > >>
> > >>
> > >> # Board config
> > >>
> > >> ```
> > >>
> > >> transport select jtag
> > >>
> > >> gdb_port 3337
> > >> set CHIPNAME egs-z-supervisor
> > >> source [find target/kx.cfg]
> > >> set CHIPNAME egs-z-active
> > >> source [find target/kx.cfg]
> > >>
> > >> $_TARGETNAME configure -event reset-init {
> > >> puts "-event reset-init occured"
> > >> }
> > >>
> > >> ```
> > >>
> > >>
> > >> I'd be grateful for any help.
> > >>
> > >> Regards,
> > >>
> > >> Jonatan H. Zeidler
> > >>
> > >>
> > >> --
> > >> Jonatan Hatakeyama Zeidler | medineering GmbH | Olof-Palme-Str. 1
> > >> 81829 München | T +49 89 416137243 | F +49 89 416137249
> > >> Sitz der Gesellschaft: München
> > >> Handelsregister: HRB 212991 | USt-ID-Nr.: DE296021936
> > >> Geschäftsführer: Dr.-Ing. Maximilian Krinninger, Dr.-Ing. Stephan
> > >> Nowatschin
> > >>
> > >>
> > >>
> > >> _______________________________________________
> > >> OpenOCD-devel mailing list
> > >> OpenOCD-devel@lists.sourceforge.net
> > >> https://lists.sourceforge.net/lists/listinfo/openocd-devel
> > >>
> > >> --
> > >> Jonatan Hatakeyama Zeidler | medineering GmbH | Olof-Palme-Str. 1
> > >> 81829 München | T +49 89 416137243 | F +49 89 416137249
> > >> Sitz der Gesellschaft: München
> > >> Handelsregister: HRB 212991 | USt-ID-Nr.: DE296021936
> > >> Geschäftsführer: Dr.-Ing. Maximilian Krinninger, Dr.-Ing. Stephan
> > >> Nowatschin
> > >>
> > >> _______________________________________________
> > >> OpenOCD-devel mailing list
> > >> OpenOCD-devel@lists.sourceforge.net
> > >> https://lists.sourceforge.net/lists/listinfo/openocd-devel
> >
> > --
> > Jonatan Hatakeyama Zeidler | medineering GmbH | Olof-Palme-Str. 1
> > 81829 München | T +49 89 416137243 | F +49 89 416137249
> > Sitz der Gesellschaft: München
> > Handelsregister: HRB 212991 | USt-ID-Nr.: DE296021936
> > Geschäftsführer: Dr.-Ing. Maximilian Krinninger, Dr.-Ing. Stephan Nowatschin
> >
> > _______________________________________________
> > OpenOCD-devel mailing list
> > OpenOCD-devel@lists.sourceforge.net
> > https://lists.sourceforge.net/lists/listinfo/openocd-devel
diff --git a/src/flash/nor/tcl.c b/src/flash/nor/tcl.c
index b1aab56ee..17b7eab3f 100644
--- a/src/flash/nor/tcl.c
+++ b/src/flash/nor/tcl.c
@@ -463,7 +463,7 @@ COMMAND_HANDLER(handle_flash_write_image_command)
}
if ((ERROR_OK == retval) && (duration_measure(&bench) == ERROR_OK)) {
- command_print(CMD, "wrote %" PRIu32 " bytes from file %s "
+ LOG_USER("wrote %" PRIu32 " bytes from file %s "
"in %fs (%0.3f KiB/s)", written, CMD_ARGV[0],
duration_elapsed(&bench), duration_kbps(&bench, written));
}
_______________________________________________
OpenOCD-devel mailing list
OpenOCD-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/openocd-devel
