cembeddedcompiler-optimizationc99

How to prevent reordering of calls to a function that prints log messages in C?


typedef enum {
    A = 0,
    B = 1,
    C = 2
} my_enum;

/**
 * @warning If random is NULL or blabla is invalid the behavior of this function is undefined.
 */
int foo(int *random, my_enum blabla)
{
    //Prints: [DBG][<timestamp>][<thread_name>][foo:<line_no>]: Entering - Hello world!
    LOG_DEBUG_ENTERING("%s", "Hello world!");
    int ret_code = 0;
    
    *random = 50;
    ret_code = do_something(*random, blabla);
    
    //Prints: [DBG][<timestamp>][<thread_name>][foo:<line_no>]: Exiting - <ret_code>
    LOG_DEBUG_EXITING("%d", ret_code);
    return ret_code;
}

I'm developing a portable multi-thread application, that can run on embedded and non-embedded systems, that works with different compilers that support at least c99.

Some platforms I work on do not have a debugger, and therefore intercepting bugs is quite difficult, the only tool that can help me in these situations are the log messages generated by the application itself.
So in all the functions of this application I added the LOG_DEBUG_ENTERING() and LOG_DEBUG_EXITING() macros so that I can track the execution of the application.

These macros/functions are designed to ensure that the message has been printed out once they finish executing, or at most the message to be printed has been queued somewhere (maybe in another process) to be printed as soon as possible, this is implementation and platform dependant, in any case all messages are printed out even if the application crashes due to a bug.

This above is a more or less a real example in my application.
If foo() is called in one of the following ways it will crash the application:

int random;
foo(NULL, A); //It will crash when foo() tries to assign 100 to the address pointed to by random
foo(&random, 1000); //Crash because the bheaviour of do_something() is not defined if blabla is out of range

I can easily find out where in the code the application crashed from the log messages, but I'm worried that the compiler might change the macro calling order, for example like this:

int foo(int *random, my_enum blabla)
{
    int ret_code = 0;
    
    *random = 50;
    ret_code = do_something(*random, blabla);
    
    //Prints: [DBG][<timestamp>][<thread_name>][foo:<line_no>]: Entering - Hello world!
    LOG_DEBUG_ENTERING("%s", "Hello world!");

    //Prints: [DBG][<timestamp>][<thread_name>][foo:<line_no>]: Exiting - <ret_code>
    LOG_DEBUG_EXITING("%d", ret_code);
    return ret_code;
}

in this case the application would crash without any message being printed out.

How can I prevent the compiler/CPU from changing the calling order of LOG_DEBUG_ENTERING()?

EDIT

The input parameters of foo() and do_something() are not checked on purpose, the idea is that we do not protect our application from bad-coding, but we still want to be able to catch these bugs when necessary.


Solution

  • The C standard (C17 5.1.2.3) speaks of "observable behavior" which are things that must not be changed during optimization.

    Writing to a log ultimately means writing to some manner of volatile qualified register, like the UART peripheral hardware. Accessing a volatile variable is a side effect which cannot get optimized away or re-ordered, so the re-ordering you describe cannot happen in conforming C.

    Similarly, modifying any non-volatile variable (or a file) is also a side effect and if that one is a needed side effect - for example because you are passing the variable to a print function the next thing you do - then it cannot get optimized out or re-ordered across the function call. The compiler may otherwise optimize the code in ways that don't affect the behavior, like putting the variable in a register instead of the stack etc.

    Now of course if your program is in a state of chaos because of bugs and undefined behavior, you'll have to analyze what will happen on the assembler and memory level.