Strange semihosting debug problem

[splin]

My progran is about as simple as it gets:

Code: [Select]

#include "stm32f4xx_conf.h"
#include <stdio.h>

int main(void)
{
    printf("\fBegin\n");
    printf("123456789abcdefghijklmnopqerstuvwxyz\n");
    printf("Done123456789\n");
}

I'm running it on an STM32F407 Discovery board using Embitz as the development environment, though I'm not certain that's relevant.

What is bizarre is that I can debug this perfectly well except that I only get semihosted logging output of the above printfs to the debugger console if the string in the *last* printf() happens to have certain number of characters. It works for:

"Done123",
"Done1234"
"Done1234567"
"Done1234568"
"Done1234568901"

 but not if it is:

"Done12"
"Done12345"
"Done123456"
"Done123456789"
"Done1234567890"

It doesn't seem to matter what the contents of the last string are, only the length.

It also doesn't seem to matter how long the middle printf is or how many printfs there are before the last. But what is really baffling me is that the problem shows even when I'm single stepping the program so that it has not even executed the last printf.

Presumably this is something to do with the layout of the strings in memory but the fact that the intermediate printfs make no difference to the behaviour seems to suggest otherwise.

Any ideas or suggestions? FWIW I'm loading the program into and executing it from RAM rather than Flash.

[EDIT] The addresses of the format strings of all three printfs are all 32 bit aligned, and don't change in the working and non-working cases.

[splin]

I don't immediately see why.
But just in case it could tangentially be relevant (it doesn't make so much sense as "the problem"),
maybe try:
fflush(stdout); // after the last printf.

I did try that earlier while experimenting but the key point to note is that the problem manifests when single-stepping over the first printf() - it either works or it doesn't depending on the content of the third printf. At which point neither the second or third printf statements have been executed, so the code following the first printf cannot be a factor (other than how it affects memory layout).

And maybe
for(; { ; }
at the end of main?
I don't know what your startup code / c-library does if main() returns.
Sometimes there's an infinite loop in the code external to the program.
Anyway stuff like closing / flushing file descriptors / streams and atexit routines and stuff would "normally" happen on a program "exit()"ing on non MCU systems but for embedded...YMMV.

All good stuff - but again, single stepping the first printf will either work or not depending on the code following - which hasn't been (and won't be) executed yet.

You could take working and non-working examples and simply permute the order of the printfs without changing the strings and see what that does.  The string layout in memory may well be the same or similar in such a case though the I/O call order would certainly change.

Alternatively you could make the string definitions independent of the printf calls like

const char * const pc_str1="String1\n";
const char * const pc_str2="String2\n";
const char * const pc_str3="String3\n";

printf(pc_str1);
printf(pc_str2);
printf(pc_str3);

Hmm, good idea - back in a minute....

...Yes it works properly by replacing only the last string with a const string pointer and the string content is now immaterial. But although it is another clue to the underlying problem, it isn't a solution.

Also check your stack and heap just in case something is going on that is over-taxing those.

You can also see if compiling with -Og or -O0 or -O1 alternatively to whatever it is set to now makes any difference.

There are only three lines of code and a function call with one parameter so I'll assume the stack is fine for now. It's compiling with no optimization - optimization might hide the problem but is almost certainly not a good solution.

Thanks for your ideas - some good food for thought.

[splin]

Just tried placing code in Flash rather than RAM and it makes no difference - "Done1234\n" Ok, "Done12\n" not OK.

[ejeffrey]

This is a cool problem!

Are there any compiler warnings?  Try compiling with "-O1 -Wall".  There are some warnings that won't show up if the optimizer is off.

I noticed in your code the first printf starts with a form-feed.  Is that intentional?  It shouldn't make a difference but is a bit unusual.

printf() returns an integer number of characters written.  I would try checking the result and verifying it makes sense.  That should let you know if the printf thinks it is executing properly in which case your bug is probably with the low level semihosting calls or the connection to the host, rather than anything going on in your main function.

I would look at the disassembly of the resulting .o files and see if you can make sense of the differences and how they relate to whether a given version works.

I would double check your toolchain configuration.  Is it possible you are doing something like compiling against one set of headers and linking against a different library version?

[splin]

This is a cool problem!

Yes, it's a bit of an odd one that's for sure!

Are there any compiler warnings?  Try compiling with "-O1 -Wall".  There are some warnings that won't show up if the optimizer is off.

Ok, still no warnings. -O1 seems to 'fix' the problem. Here is the build log:

Code: [Select]

arm-none-eabi-gcc.exe -mcpu=cortex-m4 -mthumb -mfpu=fpv4-sp-d16 -D__HEAP_SIZE=0x0000 -D__STACK_SIZE=0x0100 -mfloat-abi=hard -fno-strict-aliasing -Wextra -Wall -fdata-sections -ffunction-sections -O1 -g3 -DARM_MATH_CM4 -D__FPU_USED -DSTM32F407VG -DSTM32F4XX -DUSE_STDPERIPH_DRIVER -c src\startup_stm32f4xx.S -o obj\debug\src\startup_stm32f4xx.o -MMD -I.\inc -I.\src -I.\cmsis -I.\SPL\inc -I.\SPL\src -ID:\Development\tools\EmBitz\1.11\share\em_armgcc\bin\..\arm-none-eabi\include -ID:\Development\tools\EmBitz\1.11\share\em_armgcc\bin\..\arm-none-eabi -ID:\Development\tools\EmBitz\1.11\share\em_armgcc\bin\..\lib\cmsis\include
arm-none-eabi-gcc.exe -mcpu=cortex-m4 -mthumb -mfpu=fpv4-sp-d16 -D__HEAP_SIZE=0x0000 -D__STACK_SIZE=0x0100 -mfloat-abi=hard -fno-strict-aliasing -Wextra -Wall -fdata-sections -ffunction-sections -O1 -g3 -DARM_MATH_CM4 -D__FPU_USED -DSTM32F407VG -DSTM32F4XX -DUSE_STDPERIPH_DRIVER -c src\system_stm32f4xx.c -o obj\debug\src\system_stm32f4xx.o -MMD -I.\inc -I.\src -I.\cmsis -I.\SPL\inc -I.\SPL\src -ID:\Development\tools\EmBitz\1.11\share\em_armgcc\bin\..\arm-none-eabi\include -ID:\Development\tools\EmBitz\1.11\share\em_armgcc\bin\..\arm-none-eabi -ID:\Development\tools\EmBitz\1.11\share\em_armgcc\bin\..\lib\cmsis\include
arm-none-eabi-gcc.exe -mcpu=cortex-m4 -mthumb -mfpu=fpv4-sp-d16 -D__HEAP_SIZE=0x0000 -D__STACK_SIZE=0x0100 -mfloat-abi=hard -fno-strict-aliasing -Wextra -Wall -fdata-sections -ffunction-sections -O1 -g3 -DARM_MATH_CM4 -D__FPU_USED -DSTM32F407VG -DSTM32F4XX -DUSE_STDPERIPH_DRIVER -c src\main.c -o obj\debug\src\main.o -MMD -I.\inc -I.\src -I.\cmsis -I.\SPL\inc -I.\SPL\src -ID:\Development\tools\EmBitz\1.11\share\em_armgcc\bin\..\arm-none-eabi\include -ID:\Development\tools\EmBitz\1.11\share\em_armgcc\bin\..\arm-none-eabi -ID:\Development\tools\EmBitz\1.11\share\em_armgcc\bin\..\lib\cmsis\include
arm-none-eabi-gcc.exe -mcpu=cortex-m4 -mthumb -mfpu=fpv4-sp-d16 -Wl,--defsym=__HEAP_SIZE=0x0000 -Wl,--defsym=__STACK_SIZE=0x0100 -mfloat-abi=hard -fno-strict-aliasing -Wextra -Wall -fdata-sections -ffunction-sections -O1 -g3 -Wl,-script="./stm32f407vg_sram.ld" -o bin\Debug\semihost1.elf obj\debug\src\startup_stm32f4xx.o obj\debug\src\system_stm32f4xx.o obj\debug\src\main.o -Wl,-Map=bin\Debug\semihost1.map -specs=nano.specs -Wl,--gc-sections -specs=rdimon.specs -lrdimon
Process terminated with status 0 (0 minutes, 0 seconds)


I noticed in your code the first printf starts with a form-feed.  Is that intentional?  It shouldn't make a difference but is a bit unusual.

Yes - it has been recommended to flush the buffers and the console log window so you know where you are starting from. It's not essential and you could use fflush().

printf() returns an integer number of characters written.  I would try checking the result and verifying it makes sense.  That should let you know if the printf thinks it is executing properly in which case your bug is probably with the low level semihosting calls or the connection to the host, rather than anything going on in your main function

Hmm, good idea and where it gets even more interesting. In cases where the fprinted string gets correctly printed to the console, fprint() returns -1, when it doesn't work it returns the correct number of characters! 

Even curioser... just added code to assign the return value of the last printf and now it 'works' whatever the contents of the last printf() - but it too returns -1! So the code layout is affecting the behaviour not just the literals.

Another test just ocurred to me: when it 'works' printf() returns -1 and errno is 0. When it doesn't errno is 22 - EINVAL?

I would look at the disassembly of the resulting .o files and see if you can make sense of the differences and how they relate to whether a given version works.

In the debugger, all cases are the same - a simple call to puts(). I may try stepping through the call chain to see if I can make any sense that way.

I would double check your toolchain configuration.  Is it possible you are doing something like compiling against one set of headers and linking against a different library version?

I guess it's possible, but it will take time to check that thoroughly. I have recently installed Atollic Studio but I'd be surprised if that was the problem. I don't use semihosting very often so I don't know if it used to work reliably in Embitz. It wasn't a problem in the earlier release 'Emblocks'.

[AlfBaz]

hmmm I wonder if there may be a conflict between -specs=nano.specs and -specs=rdimon.specs
Try getting rid of nano.specs or changing their order, see if that makes a difference

Personally I tend to dispense with -specs=rdimon.specs and its library -lrdimon by simply adding my own _write and/or put_char (from memory which gets called depends on which lib you are using)

Here are the 2 functions using inline extended asm including comments and links to reference info

Code: [Select]

int _write(int __fd, const void *__buf, size_t __nbyte )
{
/* Semihosting command SYS_WRITE requires the register r1 contain a pointer
* to a 3 word data block
* WORD 1 = Handle to file prev opened with SYS_OPEN. In this instance we are using
* filedescriptor (__fd) which is usually stdout
* WORD 2 = pointer to the data to be written out
* WORD 3 = Number of bytes to written from the data pointed to by word 2
* http://infocenter.arm.com/help/index.jsp?topic=/com.arm.doc.dui0471c/Bacbejbe.html
*/
uint32_t m[] = {__fd, (uint32_t) __buf, __nbyte};
uint32_t bytes_written;

/* Ther follwoing inline assembly construct is described here
* https://gcc.gnu.org/onlinedocs/gcc/Extended-Asm.html
*/
asm("mov r0, #0x05;" /*SYS_WRITE*/
"mov r1, %[msg];"
"bkpt #0xAB;"
         : "=r" (bytes_written)
         : [msg] "r" (m)
         : "r0", "r1", "memory");
asm("mov %0, r0;"
: "=r" (bytes_written)
:
:);
return __nbyte - bytes_written;
}

void put_char(char c)
{
    asm (
    "mov r0, #0x03\n"   /* SYS_WRITEC */
    "mov r1, %[msg]\n"
    "bkpt #0xAB\n"
    :
    : [msg] "r" (&c)
    : "r0", "r1"
    );
}


[ejeffrey]

Hmm, good idea and where it gets even more interesting. In cases where the fprinted string gets correctly printed to the console, fprint() returns -1, when it doesn't work it returns the correct number of characters! 

Even curioser... just added code to assign the return value of the last printf and now it 'works' whatever the contents of the last printf() - but it too returns -1! So the code layout is affecting the behaviour not just the literals.

So this makes me think that there are two versions of _write() available -- one that behaves correctly with respect to the return values but is calling a non-functional "write" stub, and the other that invokes semihosting but isn't supplying a correct return code.  For some reason, the one that gets called depends on weird layout issues.  One possibility is that your individual callsite is changing, for instance between using an inline vs. non-inline version of a function call.  You can get all sorts of weird behavior if you have multiple definitions which depend on whether the call address is determined by the compiler or linker.  Turning on optimization could change this behavior.  The other is that printf() has multiple code paths that call different versions of the IO code.  This seems somewhat less likely since the behavior of the first printf depends on the argument to the third call.

I would look at the disassembly of the resulting .o files and see if you can make sense of the differences and how they relate to whether a given version works.

In the debugger, all cases are the same - a simple call to puts(). I may try stepping through the call chain to see if I can make any sense that way.

I actually meant to look at the generated main.o files before linking using objdump.  Also just look at 'objdump -t main.o' and see if the list of undefined (and defined) symbols is any different.

When you do look in the debugger, check to make sure they are actually calling to the same address.

[splin]

Some interesting thoughts which I'll look into. I'm travelling now but I did manage a bit of debugging last night and discovered that the call chain through printf() to _write() seems to be pretty much identical in both cases but:

When it works it invokes the semihosting service call  _WRITE0() (BKPT #AB) to print the whole string.

When it fails it invokes _PRINTC() to print a single character.

I'll debug it more to see where things diverge but it does have the hallmarks of a corrupted/mismatched tool chain. I'll try and find a debug version of newlib nano which might help. Would a more recent version be likely to work or is it essential to have exactly the same version matching the compiler/linker I'm using?

I'll update when I have more information.