Author Topic: Brutal "printf" cost in C?  (Read 5646 times)

Offline Eudaimonium

  • Newbie
  • *
  • Posts: 12
  • Karma: +0/-0
    • View Profile
Brutal "printf" cost in C?
« on: July 30, 2015, 02:39:29 am »
Hi,

I have ran simple C program on Cubieboard 2 running Cubieez Debian distro,

And I wanted to see how is the performance regarding Setting pin output values.
I have a simple program:
Code: [Select]
if (StartInterface() == 1)
{
//If interface was properly initialized, blink the PD1 and PD2 pins five times in 0.2 second intervals:
int i;
for (i = 0; i < 5; i++)
{
SetPinValue(PD1, HIGH);
SetPinValue(PD2, LOW);
printf("-------------\n");

//usleep(200000);

SetPinValue(PD1, LOW);
SetPinValue(PD2, HIGH);
printf("-------------\n");

//usleep(200000);

}

//Once we are done using the interface, we need to close it.
CloseInterface();

}

This produces this output:
Code: [Select]
cubie@cubieboard2:~/code/GPIO$ sudo ./gpio
[sudo] password for cubie:
Initialized GPIO Interface.
Pin 97 in input state while outputting value, redirecting...
Pin 97 value = 1
Pin 98 in input state while outputting value, redirecting...
Pin 98 value = 0
-------------
Pin 97 value = 0
Pin 98 value = 1
-------------
Pin 97 value = 1
Pin 98 value = 0
-------------
Pin 97 value = 0
Pin 98 value = 1
-------------
Pin 97 value = 1
Pin 98 value = 0
-------------
Pin 97 value = 0
Pin 98 value = 1
-------------
Pin 97 value = 1
Pin 98 value = 0
-------------
Pin 97 value = 0
Pin 98 value = 1
-------------
Pin 97 value = 1
Pin 98 value = 0
-------------
Pin 97 value = 0
Pin 98 value = 1
-------------
GPIO interface closed.
cubie@cubieboard2:~/code/GPIO$


Now, I wanted to measure how much time would 5000 for loop iterations take, so I made for go 5000 times.
I was not impressed when it took about 2.5 seconds to execute fully.

I have then removed ALL printf commands, both within the main program and from my EInterface class (Pin Value prints) leaving only messages that GPIO is initialized, and closed.
Then, 15000 iterations (total of 60.000 Set pin operations) executed almost instantly (basically in what it took for the console to write out the two lines).

This leaves me with a calculations that a single printf command takes aproximately 80-100 nanoseconds, while pin configurations are done within order of picoseconds (a difference of a thousand times the speed!). Real test and numbers below!

Is it normal for printf to be that slow?
« Last Edit: July 31, 2015, 08:09:21 am by Eudaimonium »

Offline Eudaimonium

  • Newbie
  • *
  • Posts: 12
  • Karma: +0/-0
    • View Profile
Re: Brutal "printf" cost in C?
« Reply #1 on: July 30, 2015, 04:30:39 am »
I took some specific measurements, so we have some numbers to work with.

Program I am using:

Code: [Select]
//All needed includes for GPIO operation are here.
#include "EInterface.h"
#include <sys/time.h>

#define ITERATIONS 15000.f

int main()
{
//Initialize GPIO Interface, and check if it returns any error code.
//IF success (if errorCode is -1, it's bad!)
if (StartInterface() == 1)
{
printf("Starting %f x 4 pin switch operations\n", ITERATIONS);
struct timeval t1, t2;
gettimeofday(&t1, NULL);
//If interface was properly initialized, blink the PD1 and PD2 pins five times in 0.2 second intervals:
int i;
for (i = 0; i < ITERATIONS; i++)
{
SetPinValue(PD1, HIGH);
SetPinValue(PD2, LOW);
//printf("-------------\n");

//usleep(200000);

SetPinValue(PD1, LOW);
SetPinValue(PD2, HIGH);
//printf("-------------\n");

//usleep(200000);

}

gettimeofday(&t2, NULL);

double elapsedTime = (t2.tv_sec - t1.tv_sec) * 1000.f;
elapsedTime += (t2.tv_usec - t1.tv_usec) / 1000.f;

double timePerIteration = elapsedTime / ITERATIONS;
double timePerSwitch = timePerIteration / 4.f;


printf("Time total: %fms\n", elapsedTime);
printf("Time per iteration: %fms\n", timePerIteration);
printf("Time per switch: %fms\n", timePerSwitch);

CloseInterface();

}

return 0;

}

Produces this output:

Quote
cubie@cubieboard2:~/code/GPIO$ sudo ./gpio
Initialized GPIO Interface.
Starting 15000.000000 x 4 pin switch operations
Time total: 24.657000ms
Time per iteration: 0.001644ms
Time per switch: 0.000411ms
GPIO interface closed.


Which means one GPIO pin value switch takes about 400 nanoseconds.

Now, repeating this with one printf command uncommented within the for loop:
Code: [Select]
printf("-------------\n");

Result:
Quote
...
-------------
-------------
-------------
Time total: 760.798996ms
Time per iteration: 0.050720ms
Time per switch: 0.012680ms
GPIO interface closed.


Time for one iteration went from 1.6 microseconds, to 50.7 microseconds, which means some 49-50 microseconds for one printf command to execute.

Let's repeat the test with both printf commands:

Code: [Select]
for (i = 0; i < ITERATIONS; i++)
{
SetPinValue(PD1, HIGH);
SetPinValue(PD2, LOW);
printf("-------------\n");

//usleep(200000);

SetPinValue(PD1, LOW);
SetPinValue(PD2, HIGH);
printf("-------------\n");

//usleep(200000);

}

Result:

Quote
...
-------------
-------------
Time total: 1118.832001ms
Time per iteration: 0.074589ms
Time per switch: 0.018647ms
GPIO interface closed.


We're up to 76 microseconds for one iteration, which would be some 75 microseconds for two printf commands, or 37-38 microseconds for one printf command.

Let's run the test again with all printf commands enabled, including the debugging ones which say which pin has which value.

Code: [Select]
...
-------------
Pin 97 value = 0
Pin 98 value = 1
-------------
Pin 97 value = 1
Pin 98 value = 0
-------------
Pin 97 value = 0
Pin 98 value = 1
-------------
Time total: 4145.164993ms
Time per iteration: 0.276344ms
Time per switch: 0.069086ms
GPIO interface closed.


276 microseconds for 4 pin state switches + 6 printf messages per iteration, or
275 microseconds for 6 printf messages = aprox. 45 microseconds for each printf command.

I am guessing there are some performance considerations regarding strings as well, string for each message needs to be constructed (which is why two identical printfs produced slightly lower time of 37us per print), but point is, if you need high speec pin I/O, DO NOT USE PRINTS in between operations. Use only at start, and at end to know what happened, but iterations with pin switching should not contain any printf lines!
« Last Edit: July 30, 2015, 04:35:43 am by Eudaimonium »

Offline premoboss

  • Jr. Member
  • **
  • Posts: 51
  • Karma: +2/-0
    • View Profile
Re: Brutal "printf" cost in C?
« Reply #2 on: July 30, 2015, 06:40:28 am »
also "FOR" and "IF" kill the performaces.
must to be avoided more than possible.

Offline @lex

  • Full Member
  • ***
  • Posts: 157
  • Karma: +4/-0
    • View Profile
Re: Brutal "printf" cost in C?
« Reply #3 on: July 30, 2015, 07:46:23 am »
try to avoid printf or avoid variable args or try with puts:

void echo(int val)
{
    char buf[64];
    sprintf(buf, "val = %d", val);
    puts(buf);
}

Offline Eudaimonium

  • Newbie
  • *
  • Posts: 12
  • Karma: +0/-0
    • View Profile
Re: Brutal "printf" cost in C?
« Reply #4 on: July 30, 2015, 08:04:57 am »
also "FOR" and "IF" kill the performaces.
must to be avoided more than possible.

And how exactly am I supposed to write code without FOR and IFs?

@Lex,
Thanks, didn't know about that, I'll re-do the test with this function and see how it works.

Offline @lex

  • Full Member
  • ***
  • Posts: 157
  • Karma: +4/-0
    • View Profile
Re: Brutal "printf" cost in C?
« Reply #5 on: July 30, 2015, 08:37:33 am »

Here is how to avoid FOR loops.  ;D

Quote
i = 0;
while (i < ITERATIONS) {
  do_something()
  if (want to stop)
     break;
  i++;
}

Offline Eudaimonium

  • Newbie
  • *
  • Posts: 12
  • Karma: +0/-0
    • View Profile
Re: Brutal "printf" cost in C?
« Reply #6 on: July 31, 2015, 08:03:44 am »

Here is how to avoid FOR loops.  ;D

Quote
i = 0;
while (i < ITERATIONS) {
  do_something()
  if (want to stop)
     break;
  i++;
}

That's exact same thing as a For loop - it all gets compiled into the same machine code anyway. I would be willing to bet there's literally NO performance difference between this, and a regular For loop.

Difference I would be seeing is how easy it is to read and understand the code afterwards.

"Premature optimization is the root of all evil!"

Offline premoboss

  • Jr. Member
  • **
  • Posts: 51
  • Karma: +2/-0
    • View Profile
Re: Brutal "printf" cost in C?
« Reply #7 on: August 01, 2015, 12:25:27 pm »
also "FOR" and "IF" kill the performaces.
must to be avoided more than possible.
And how exactly am I supposed to write code without FOR and IFs?

sharping your brain is the first step.
Of course for some kind of code it is not possible to avoid condition checks and cycles, but for some routines you can rethink the logic of the algorithm: in my case, i got success rethinking the logic of the code and move code execution time from 1602 sec down to 9 sec just avoiding the "if".
(there was 10 nested for-next loop, with into inner ring the if.)
« Last Edit: August 01, 2015, 01:04:56 pm by premoboss »

Offline Eudaimonium

  • Newbie
  • *
  • Posts: 12
  • Karma: +0/-0
    • View Profile
Re: Brutal "printf" cost in C?
« Reply #8 on: August 04, 2015, 02:59:25 am »

sharping your brain is the first step.
Of course for some kind of code it is not possible to avoid condition checks and cycles, but for some routines you can rethink the logic of the algorithm: in my case, i got success rethinking the logic of the code and move code execution time from 1602 sec down to 9 sec just avoiding the "if".
(there was 10 nested for-next loop, with into inner ring the if.)

Sounds like you just had badly written code, and your "rethinking of logic" was basically just getting it right this time. IF conditionals do not slow down the code that much, it's one of the simplest things that CPU can make. Mov variable to ACC, JMP if less, is, or greater than zero.

As somebody who has written his own ultra-fast 3D collision detection and response algorithm within his 3D game written from scratch, has mastered the techniques of polymorphism and is very active in game development programming, "sharpening your brain" is a bit insulting. Maybe the true meaning got lost in translation, and you didn't mean anything bad, and if that's the case, sorry.

I am no stranger to coding. I am only new to the new General Purpose I/O devices present on these boards and drivers to interact with them, and that is what I needed help with. When you tell me that "For" and "Ifs" slow down the code by a factor of 100, I am less inclined to take any programming advice for you because that's just false.

Offline premoboss

  • Jr. Member
  • **
  • Posts: 51
  • Karma: +2/-0
    • View Profile
Re: Brutal "printf" cost in C?
« Reply #9 on: August 04, 2015, 08:28:47 am »
"sharpening your brain" here is a proverb, a "short sentence" to say something. the meaning is "train yourself and find a solution better that you did till now." Not at all intention to insulting.

About "if" and "for", i only added my experience tho this thread (yes, partially OT because the main object is related to "printf").

Of course noone is forced to trust my words.