Heap Size causing strange printf delay behavior.

Tip / Sign in to post questions, reply, level up, and achieve exciting badges. Know more

cross mob
JaPh_4667081
Level 2
Level 2
First like received First like given

Hello! I was hoping someone with more insight than myself might be able to point me in the right direction.

I am using a PSOC LP5 (CY8C5888LTI-LP097 on the CY8CKIT-059). I used the UART_FULL_DuplexExample project as a base which enables printf by rewriting the _write function. All this works as expected. However, when I needed to print floats to the screen I had to up the heap size from 0x300 to 0x400 which makes sense to me.

Here is the real confusing part for me. I made the following function for some debugging. There is an interrupt that decrements the timer variable every 1ms. It should print /hi every 100 ms.

//Initialize display delay to zero

    g_Timer_Display_Delay_ms = 0;

   

    for(;;)

    {

        if(g_Timer_Display_Delay_ms == 0)

        {

            g_Timer_Display_Delay_ms = 100u; //Reset timer

            Pin_Debug_Write(!Pin_Debug_Read()); //Toggle pin for testing

            //Print values

            UART_PutString("/");

            printf("hi");

        }

       

    }

If I periodically increase the heap size :

  • 0x400 Pass
  • 0x500 Pass

I get the expected output:

/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi

/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/

But when I increase the heap size further:

  • 0x600 FAIL

At 0x600 I get the following output:

////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////

////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////

/////////////////////////////////////////////////////////////////////////////////////////hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihi///////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////

I have the debug IO on a scope and it is toggled at a constant at 100ms so the printf function is not blocking. It seems to buffer a whole bunch of characters and then spits it out 51.3 seconds later! The compiler has no warning about the heap size allocation. I expect I am exceeding some memory limit and stepping on some control register or buffer somewhere?

0 Likes
1 Solution
lock attach
Attachments are accessible only for community members.
MotooTanaka
Level 9
Level 9
Distributor - Marubun (Japan)
First comment on blog Beta tester First comment on KBA

Hi,

What I learned about standard I/O and buffered I/O of Unix (actually it was HP-UX) was that

since a print to tty is an expensive operation, buffered IO such as printf (which is actually fprintf(stdout,...))

is trying to reduce the frequency of print as much as possible.

On the other hand a non buffered IO such fprintf(stderr, ...) outputs the result immediately.

Now it seems that what happening here is when heap is small the internal buffer size of printf  (actually stdout) is small,

and when heap is larger the internal buffer size of  printf is larger.

And printf prints out the buffer when

(1) Encounter an EOL (end of line)

(2) When buffer is FULL

(3) When flush() is requested.

Current situation is caused by the case (2).

If you intentionally do either (1) or (3)  the output will appear immediately.

So I added  fflush(stdout) just after printf("hi")  in your program and the result was

000-TeraTerm-log.JPG

=================

        if(g_Timer_Display_Delay_ms == 0)

        {

            g_Timer_Display_Delay_ms = 100u; //Reset timer

            Pin_Debug_Write(!Pin_Debug_Read()); //Toggle pin for testing

            //Print values

            UART_PutString("/");

            printf("hi");

            fflush(stdout) ;

        }

=================

Attached is a modified project of yours.

moto

View solution in original post

11 Replies
Len_CONSULTRON
Level 9
Level 9
Beta tester 500 solutions authored 1000 replies posted

japh,

There is no logical reason increasing the heap size should cause what you are witnessing based on your description.

Are you willing to share your project with the forum for others to reproduce your results?

Len

Len
"Engineering is an Art. The Art of Compromise."

Since this project now contains a lot of other development for a company, I will make a cleaned up version I can share and post it shortly. Thank you!

0 Likes
lock attach
Attachments are accessible only for community members.

Here is a real quick and very dirty example. I did a complete archive just in case there was an issue with my compilation.

Steps to recreate:

  • Start with uart full duplex example
  • Change the device using the device selector to the CY8C588LTI-LP097
  • Added the clock and isr
  • Added the minimum code modifications as seen in the project main.c
  • Change the heap size in the system tab to 0x600
  • Run and view uart output. It delays printing the hi text as previously described

Thank you very much!

0 Likes

vjaph,

I tried your example project.  I have been able to reproduce your results.

With heap = 0x500:

UART Full Duplex and printf() support Code Example Project

Test printf function. long:444444444, Single float:55.56

Multi float:55.56 55.56 55.56 55.56 55.56 55.56 55.56 55.56 55.56 55.56

Enter the characters to transmit

/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi/hi

With heap = 0x600:

UART Full Duplex and printf() support Code Example Project

Test printf function. long:444444444, Single float:?. 

Multi float:?.  ?.  ?.  ?.  ?.  ?.  ?.  ?.  ?.  ?. 

Enter the characters to transmit

///////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////

///////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////

///////////////////////////////////////////////////////////////////////////////////hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihih

ihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihih

ihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihih

ihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihi

hihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihihih

ihihihihihi/////////////////////////////////////////////////////////////////////////////////////////////

Besides the printf() for the float being wrong/incomplete, the '/' is put out every 10msec but the 'hi' when it does come out comes out virtually at the same time with no perceivable delay.

Len

Len
"Engineering is an Art. The Art of Compromise."

japh,

More updates:

There are two issues at play here.

Issue #1

  • In your code you have the followings two lines in the for(;;) loop:

UART_PutString("/");

printf("hi");

The printf() code uses a different buffering scheme from the UART_PutString(). 

UART_PutString() places the data almost directly in the FIFO buffer of the UART. 

The printf() places the UART data on the heap AND (this is very important) the printf() function will not move the data from the heap to the UART FIFO unless a CRLF is sent OR the heap is full.   This explains in part why the '/' character is output every 10msec but the "hi" strings aren't dumped to the UART until the heap is full.

My advice is to only use the UART_Putxxx() functions or the printf() functions with a CRLF.

For example,  I changed your printf("hi") to UART_PutString("hi").  No problem.

I changed the UART_PutString("/"); printf("hi");   to printf("/hi\r\n");.  No problem.

Issue #2

At this point you're wondering why if Issue #1 is true,  then why didn't this show up when the heap < 0x600?

Good question.  Someone will have to analyze the printf() function and its' relationship to the heap.  Since the printf() is a part of the GCC library and the source code is not included this will be difficult.

Len

Len
"Engineering is an Art. The Art of Compromise."

Thanks for the response! I am actually not using UART_PutString regularly. I only added it as an example as I knew it would write directly to the uart.

In my regular use case I am attempting to print several values with just a line return rather than a next line to overwrite the line. So my prints would regularly be printf("stuff\r"); I do still see the issue there.

You are absolutely right though, adding a \r\n to the print statement fixes the update issue!

I am a bit confused on one thing though. So if you update the code to the following by removing the UART_PutString call:

//Initalize display delay to zero

    g_Timer_Display_Delay_ms = 0;

   

    for(;;)

    {

        if(g_Timer_Display_Delay_ms == 0)

        {

            g_Timer_Display_Delay_ms = 100u; //Reset timer

            Pin_Debug_Write(!Pin_Debug_Read()); //Toggle pin for testing

            //Print values

            printf("hi ");

        }

       

    }

There is no CLRF, and only printf is being used right?

But with a heap size of 0x500 it does not wait to print. It prints right on time every time. It's not waiting to fill the heap before printing.

With a heap size of 0x600 it doesn't print anything for a while then dumps it all out!

So if what you said before was true, I would expect when I set the heap to 0x500 that it would just dump a little sooner because the heap is getting fuller sooner.

Also if printf requires a CLRF or a full heap, then wouldn't any printf without \r\n always wait until you fill up the heap to print? I have several programs that only print a small amount on boot-up that would never have filled the heap and doesn't have a return that prints right away.

0 Likes

japh,

This is the paradox of Issue #2.

Without the source code for printf() this will not be easily solvable.

Len

Len
"Engineering is an Art. The Art of Compromise."
lock attach
Attachments are accessible only for community members.
MotooTanaka
Level 9
Level 9
Distributor - Marubun (Japan)
First comment on blog Beta tester First comment on KBA

Hi,

What I learned about standard I/O and buffered I/O of Unix (actually it was HP-UX) was that

since a print to tty is an expensive operation, buffered IO such as printf (which is actually fprintf(stdout,...))

is trying to reduce the frequency of print as much as possible.

On the other hand a non buffered IO such fprintf(stderr, ...) outputs the result immediately.

Now it seems that what happening here is when heap is small the internal buffer size of printf  (actually stdout) is small,

and when heap is larger the internal buffer size of  printf is larger.

And printf prints out the buffer when

(1) Encounter an EOL (end of line)

(2) When buffer is FULL

(3) When flush() is requested.

Current situation is caused by the case (2).

If you intentionally do either (1) or (3)  the output will appear immediately.

So I added  fflush(stdout) just after printf("hi")  in your program and the result was

000-TeraTerm-log.JPG

=================

        if(g_Timer_Display_Delay_ms == 0)

        {

            g_Timer_Display_Delay_ms = 100u; //Reset timer

            Pin_Debug_Write(!Pin_Debug_Read()); //Toggle pin for testing

            //Print values

            UART_PutString("/");

            printf("hi");

            fflush(stdout) ;

        }

=================

Attached is a modified project of yours.

moto

Thank you Moto!

I was unaware of the manual flush option and your explanation was very good. I appreciate it! Indeed the modification works exactly as you described. I'm going to do some research and see if I can find a way to rewrite part of the printf functionality to reduce this delay. That or write a wrapper for printf and add the flush in.

Thanks!

JaPh_4667081
Level 2
Level 2
First like received First like given

Marking the issue solved, thank you both Len and Moto!

JaPh_4667081
Level 2
Level 2
First like received First like given

I wanted to reply with a helpful bit of information. Some searching turned up the function setbuf()

You can disable buffering of stdout (and other streams I imagine) with this:

setbuf(stdout, NULL);

I confirmed it works without needing to manually add the fflush line.

Thanks again for all the help!