• State Not Answered
  • Locked Locked
  • Replies 11 replies
  • Subscribers 15 subscribers
  • Views 3483 views
  • Users 0 members are here
Options
Related
How was your experience today?
This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

Persistent C51 printf curiosities

Loren Amelang

We have a product built from the t89c51cc01 or 03 chips using C51. Timer 0 does a 10mS interrupt to check a few hardware inputs. Timer 1 runs the serial port. Timer 2 provides an adjustable clock output around 40 KHz. CAN is initialized, but during most of our testing no messages are being transmitted or received.

The program spends most of its time in a measurement loop that can be set anywhere from 20 mS to 1400 mS per iteration, with some of the time extension taken by added measurements and some by timer delays. If the user presses 'm' on a serial terminal, the loop stops while a configuration menu runs.

C51 printf causes us more problems than any other software aspect of this product. Trying to guess what will happen if we change a printf statement, or change something else near a printf statement, seems an exercise in superstition as much as logic.

When I refer to printf, I mean to include sprintf as well. I had hopes that doing an sprintf and then sending the string out with putchar would solve some of our printf problems, but so far the sprintf version has always shown the same failure as the printf version.

I've searched the web and the Keil site, and while <http://www.keil.com/support/docs/867.htm> explains some of our issues, it is far from explaining the spooky ones:

-----
... variable length argument lists must be limited to some predetermined size.

By default, we limit that to 15 bytes of arguments for memory models that use DATA memory.
The limit is 40 bytes for memory models using XDATA.

The MAXARGS compiler directive lets you change the default limit to whatever you desire.
Note that since the limit [o]f DATA space is 128 bytes (including register banks and the bit area)
you can't just set MAXARGS to 128.
-----

We've learned to live with a maximum of 7 ints, 5 string pointers, or 3 long ints or floats per printf. What made this initially confusing is that using more doesn't always fail. We've had printfs that had worked for years suddenly start crashing the entire program because we changed the timing of the loop, or changed a different nearby printf. It also seems like as long as printf prints at least one of its values incorrectly, it doesn't crash. If you manage to get that incorrect display problem fixed, it is very likely the "fixed" printf will crash within ten or maybe a hundred iterations.

The output of printf is apparently "spooled" somehow. When we speed our loop up to 20 mS per iteration, we see characters output at the serial port almost continuously, though we know the actual printf calls complete in very tiny fractions of that total time. Recently we saw a case where this "spooling" repeatably failed:

We added a new prompt in our operator menu:
    printf("\n 'U' moves +/right, 'D' -/left, 'Q' accepts: ");
Even written as:
    printf("\n 'U' moves +/right, 'D' -/left, ");
    printf("'Q' accepts: ");
it would always be truncated exactly after the 'Q'.

After the function including the above printf exited, its calling function called two more printfs:

    ANSI_cls();  // #define ANSI_cls()  printf("\x1B[2J")
    printf("\n --- RUNNING...");

Both of those, which had previously worked fine for years, vanished from the serial output when we added the new prompt.

When that calling function exited, the main loop resumed, and its first printf did still appear properly:

    printf("\n\n\nTime(ms)%cSmpl%cCnt%cNDVI%cselected_VI%c", s1, s1, s1, s1, s1);

Adding a delay after the first printf:

    printf("\n 'U' moves +/right, 'D' -/left, 'Q' accepts: ");
    TmrDelay(10);

seemed to solve (or hide) this problem. Sometimes this helps and sometimes it doesn't, and we haven't a clue why.

Sometimes there seems to be a problem with passing the results of calculations to printf. This worked perfectly...

    printf("\r%02d <%+05.1f %+05.1f> ",
        (NDVIsmoothed_16s+5)/10,
        (FP)(NDVIvalley_16s-target_nom_16s)/10.0,
        (FP)(NDVIpeak_16s-target_nom_16s)/10.0);

until the result of the third calculation got bigger than about 40000, which would crash the program almost instantly.

By the time it worked for all values, it looked like this:

    minF = (FP)(NDVIvalley_16s-target_nom_16s)/10.0;
    maxF = (FP)(NDVIpeak_16s-target_nom_16s)/10.0;
    printf("\r% 03.0f <", NDVIsmoothed*100);  // this is an FP of NDVIsmoothed_16s
    printf("%+05.1f  ", minF);
    printf("%+05.1f> ", maxF);

Sometimes no amount of separating or dividing will make a certain printf work:

    NDVIdev_16s = (NDVIpeak_16s-NDVIvalley_16s)/2;
    printf("\n%03d ±%03d ", NDVIsmoothed_16s, NDVIdev_16s);

That crashes with loop times under 400mS, even with the calculation separate.

Same with this sequence:

    printf("\n%03d ", NDVIsmoothed_16s);
    printf("{-%3d +%3d} ", minus16s, plus16s);

Both of those would crash, almost always after printing a single '-' on the new line, within maybe 100 iterations - if the loop time was under 400 mS.

This works in exactly that same spot:

    printf("\n% 05.1f ", (FP)NDVIsmoothed_16s/10.0);

Then there is the long series of printfs that form the normal output of the product, that have remained unchanged for many years, and that typically repeat every 100 mS whenever it is on. With a few particular recent hardware instances, if we set the loop time to exactly 50 mS, the program will crash after several minutes of operation. Choose any other loop time and the same device will run forever. Probably 99% of our systems run fine at any speed. We don't know for sure this is caused by printf, but the resemblance seems suggestive.

There must be much more to this than just the variable length argument limit. Could we have an in-depth explanation of the other limitations of C51 printf?

Parents
  • 0

    ! Good to see so many dedicated and helpful people here!

    I'll try to deal with all the questions and suggestions so far:


    Have you made sure that you don't try to generate more output than the serial port can handle?

    Think both about the sustained transfer speed of the serial port, and the max number of characters that may be queued.

    The serial port runs at 38400, and our worst case diagnostic output at maximum loop speed looks like this:

     235800,   4, 2012,  0.860,  0.075,  0.042,  0.561,  2560, 16672, 43552, 53920
 235830,   4, 2013,  0.855,  0.078,  0.042,  0.544,  2560, 16192, 43456, 53792
 235860,   4, 2014,  0.850,  0.081,  0.045,  0.556,  2624, 16544, 43552, 53920
 235890,   4, 2015,  0.857,  0.077,  0.042,  0.551,  2560, 16384, 43424, 53824

    The first column is milliseconds, so we're averaging 30 mS per loop. The serial port is busy for 24 of those 30 mS. (With normal 34 char wide output this "20 mS" setting actually does 20 mS.) Except for the few hardware examples that show the "50 mS loop time crash", any product can do this all day. The "50 mS" problem units can do it all day at 40 or 30 mS, and at 50 mS they will crash with only 34 characters per line as well as with the 80 char lines.


    printf() will have to use internal buffers when formatting some of it's output - numerical values are normally formatted in reverse order.

    I have the Plauger book with the standard library code, but I'm far from understanding the details of _Putfld and _Litob. I think I see where it converts numbers from lsb upward... But it looks like _Printf reads the format string left-to-right. Of course the Keil library may be different. I would think that since the number of bytes we can request to be converted is strictly limited to MAXARGS, it should be possible to guarantee that all subsequent buffers are sufficient to do the conversions.


    When emitting it's data, printf will also have to either fail with truncated output, or busy-loop, if the serial port buffer is full.

    Many of our printf issues happen in menu mode, where the human is by far the slowest factor in the loop. The menu does occasionally print more than 80 consecutive characters without the timer enforced 6+ mS pause, but I believe printf problems are as likely to appear with a single line of output as with multiple line pages. The one truncation example in my earlier post is unusual; we are much more likely to see wrong values or a complete program crash than truncation.


    sprintf() assumes (without being able to check) that the buffer you supply is big enough. After that, it is up to you to decide how to send the formatted data to the serial port, i.e. to decide what to do if the transmit buffer gets full.

    When the runtime library supports it, snprintf is a lot safer to use than sprintf, since it takes an extra parameter specifying the size of the target buffer.

    I had high hopes, and made sure my buffere were big enough, and of course I haven't tried an sprintf version of every problem line, but the ones I have tried have showed the same issues as printf.

    -----


    When you say "crash", what symptoms do you mean exactly? Garbled output on the serial port? The program stops running entirely? If so, how do you know it's not running? Lack of further output/activity, or do you have an emulator or monitor where you can break into the code and see where it is executing?

    Crash means the program stops running. There are several LEDs that flash in synch with different processes, and they all stop. A power cycle is required, as there is no hardware reset button to push. I've also looked at the processor with a scope, and nothing is moving except the Timer 2 clock out, and the ALE pin which is just tied high.


    printf() is not reentrant. You must be sure that there is only one context that can call into printf, and that it always completes before the next entry into the function. That is, you can't call printf() safely from your main loop and interrupt handlers, or from several tasks in your RTOS if you have one.

    No RTOS, and none of our interrupts use printf. I learned about "not reentrant" long ago on another project in another development system, where output from interrupt routines was required. Ended up queing all output for a single interrupt handler to print.

    But "You must be sure that there is only one context that can call into printf, and that it always completes before the next entry into the function" might still be relevant. When is printf complete? When it returns control to the next line of code? Sometimes adding a TimerDelay after a printf call seems to solve (or hide) a problem... Could that mean printf returns before it is truly "complete"?

    In my "spooling" example, it seemed like there was some interaction between printf returning and its calling function returning. If the function that called printf returns before printf is truly "complete", and the returned-to function immediately calls another printf, is that two simultaneous contexts?


    printf() outputs through putchar().

    That's a Keil adaptation, right?

    ... to be continued...

Reply
  • 0

    ! Good to see so many dedicated and helpful people here!

    I'll try to deal with all the questions and suggestions so far:


    Have you made sure that you don't try to generate more output than the serial port can handle?

    Think both about the sustained transfer speed of the serial port, and the max number of characters that may be queued.

    The serial port runs at 38400, and our worst case diagnostic output at maximum loop speed looks like this:

     235800,   4, 2012,  0.860,  0.075,  0.042,  0.561,  2560, 16672, 43552, 53920
 235830,   4, 2013,  0.855,  0.078,  0.042,  0.544,  2560, 16192, 43456, 53792
 235860,   4, 2014,  0.850,  0.081,  0.045,  0.556,  2624, 16544, 43552, 53920
 235890,   4, 2015,  0.857,  0.077,  0.042,  0.551,  2560, 16384, 43424, 53824

    The first column is milliseconds, so we're averaging 30 mS per loop. The serial port is busy for 24 of those 30 mS. (With normal 34 char wide output this "20 mS" setting actually does 20 mS.) Except for the few hardware examples that show the "50 mS loop time crash", any product can do this all day. The "50 mS" problem units can do it all day at 40 or 30 mS, and at 50 mS they will crash with only 34 characters per line as well as with the 80 char lines.


    printf() will have to use internal buffers when formatting some of it's output - numerical values are normally formatted in reverse order.

    I have the Plauger book with the standard library code, but I'm far from understanding the details of _Putfld and _Litob. I think I see where it converts numbers from lsb upward... But it looks like _Printf reads the format string left-to-right. Of course the Keil library may be different. I would think that since the number of bytes we can request to be converted is strictly limited to MAXARGS, it should be possible to guarantee that all subsequent buffers are sufficient to do the conversions.


    When emitting it's data, printf will also have to either fail with truncated output, or busy-loop, if the serial port buffer is full.

    Many of our printf issues happen in menu mode, where the human is by far the slowest factor in the loop. The menu does occasionally print more than 80 consecutive characters without the timer enforced 6+ mS pause, but I believe printf problems are as likely to appear with a single line of output as with multiple line pages. The one truncation example in my earlier post is unusual; we are much more likely to see wrong values or a complete program crash than truncation.


    sprintf() assumes (without being able to check) that the buffer you supply is big enough. After that, it is up to you to decide how to send the formatted data to the serial port, i.e. to decide what to do if the transmit buffer gets full.

    When the runtime library supports it, snprintf is a lot safer to use than sprintf, since it takes an extra parameter specifying the size of the target buffer.

    I had high hopes, and made sure my buffere were big enough, and of course I haven't tried an sprintf version of every problem line, but the ones I have tried have showed the same issues as printf.

    -----


    When you say "crash", what symptoms do you mean exactly? Garbled output on the serial port? The program stops running entirely? If so, how do you know it's not running? Lack of further output/activity, or do you have an emulator or monitor where you can break into the code and see where it is executing?

    Crash means the program stops running. There are several LEDs that flash in synch with different processes, and they all stop. A power cycle is required, as there is no hardware reset button to push. I've also looked at the processor with a scope, and nothing is moving except the Timer 2 clock out, and the ALE pin which is just tied high.


    printf() is not reentrant. You must be sure that there is only one context that can call into printf, and that it always completes before the next entry into the function. That is, you can't call printf() safely from your main loop and interrupt handlers, or from several tasks in your RTOS if you have one.

    No RTOS, and none of our interrupts use printf. I learned about "not reentrant" long ago on another project in another development system, where output from interrupt routines was required. Ended up queing all output for a single interrupt handler to print.

    But "You must be sure that there is only one context that can call into printf, and that it always completes before the next entry into the function" might still be relevant. When is printf complete? When it returns control to the next line of code? Sometimes adding a TimerDelay after a printf call seems to solve (or hide) a problem... Could that mean printf returns before it is truly "complete"?

    In my "spooling" example, it seemed like there was some interaction between printf returning and its calling function returning. If the function that called printf returns before printf is truly "complete", and the returned-to function immediately calls another printf, is that two simultaneous contexts?


    printf() outputs through putchar().

    That's a Keil adaptation, right?

    ... to be continued...

Children