Wednesday, July 7, 2010

performance impact of printf

Logging is a widely used debugging means. As a way of implementing logging, I saw printf used in a lot of places. It's so quick and easy to use printf to examine the behavior of an application. But it also has heavy impact of the performance of the application, meanwhile, it makes our logging a mess and difficult to read without careful forethought.
The code snippet below calculates the fibonacci number. On line eight, I used printf to print some values. Very simple code. I compiled the code with different printf statement on line eight and run the application to see the performance.

 1 int fib(int a)
 2 {
 3     int rc = 0;
 4     if(a < 2)
 5         rc = a;
 6     else
 7         rc = fib(a-1) + fib(a-2);
 8     printf("rc = %d, a = %d\n", rc, a);
 9     return rc;
10 }
11
12 int main(int argc, char* argv[])
13 {
14     int t1 = GetTickCount();
15     printf("before fib: %d\n", t1);
16     int result = fib(16);
17    
18     int t2 = GetTickCount();
19     printf("after fib: %d   %d  %d  \n", t2, t2 - t1, result);
20     return 0;
21 }
22


The list below shows the time ticks spent with different printf statements, in decreasing order.
4188  (printf("rc = %d, a = %d\n", rc, a) )
3617  (printf("helloworld"))
844    (printf("a"))
858    (printf("%d\n", rc))
302    (printf("%d", rc))
2        (no printf)

It's very clear that the performance drops dramatically if the printf statement is there, and the more complex the format string is, the poorer the performance is. The performance is even 2000 times poorer if we compare the worst case and best case.
The reason is printf needs to invoke system call to output data, which incur a lot of transitions between user mode and kernel mode. And a complex format string also consumes a lot of processing time.

In order to get rid of the performance penalty, yet keep the capability of saving log. We must use a mature logging system, instead of printf directly. An ideal logging system should support switch, logging level and many output mechanisms.
While writing code, we're always enticed to use printf simply because it's easy to write. In contrast, a logging system should require us spending 10 minutes to understand and use. But, the time spent really deserves, considering the time we must spend later on organizing and cleaning printf statement and the possible performance impact of printf.

No comments: