Re: -finstrument-function -O2 and printf() instrumentation

[Stefan Ruppert <sr@xxxxxxxxx>]

Am 18.08.2015 um 21:57 schrieb Martin Sebor:
> On 08/17/2015 06:45 AM, Stefan Ruppert wrote:
>> Hi all,
>>
>> I'm just playing arounnd with instrumenting source code using
>> -finstrument-function compiler switch. I noticed the following behaviour
>> within gcc (Ubuntu 4.8.4-2ubuntu1~14.04) 4.8.4:
>>
>> If I compile a simple C program using printf() calls without
>> optimization the printf() calls are not instrumented. But if I compile
>> the simple C program with -O2 the instrumentation functions are also
>> called for any printf() call.
>>
>> However if I look into the object file using nm there is only an U
>> reference to printf():
>>
>> nm ./ComplexChain-ComplexChain.o
>>                   U __cyg_profile_func_enter
>>                   U __cyg_profile_func_exit
>> 0000000000000000 d _init.4299
>> 0000000000000000 r .LC0
>> 0000000000000000 T main
>> 00000000000003a0 T Main
>>                   U printf
>>                   U __printf_chk
>>                   U strtol
>> 0000000000000110 T SubTran1
>> 00000000000000c0 T SubTran2
>>                   U time
>>                   U usleep
>>
>> Any idea why func_enter and func_exit are called for printf() if
>> compiled with -O2? Is the printf() call somehow inlined with -O2?
> 
> From the nm output it looks like the program was compiled with
> the _FORTIFY_SOURCE macro defined to a non-zero value (either
> explicitly or otherwise(*)). With optimization (i.e., when the
> __OPTIMIZE__ macro is also defined) printf is an inline function
> defined in bits/stdio2.h that calls __printf_chk. It's this inline
> function that's instrumented. When _FORTIFY_SOURCE is not defined
> (or 0), or when not optimizing (_FORTIFY_SOURCE depends on
> optimization), printf is a non-inline function defined in libc
> and thus not subject to instrumentation.
> 
> Martin
> 
> [*] It's helpful to show the compiler options and the code when
> posting these sorts of questions so that the results can be more
> easily reproduced.

Hi Martin,

thanks for the hint! And yes ubuntu gcc uses _FORTIFY_SOURCE macro
with -O2:

gcc -O2 -I../c/include -std=gnu99 -rdynamic -finstrument-functions
ComplexChain.c -E -dM | grep FORTIFY
#define _FORTIFY_SOURCE 2
#define __USE_FORTIFY_LEVEL 2
#define __bos(ptr) __builtin_object_size (ptr, __USE_FORTIFY_LEVEL > 1)

Maybe add an __attribute__((no_instrument_function)) to the inline
printf() function within bits/stdio2.h!?

If anyone is interested I attached the code.

Regards,
Stefan

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <inttypes.h>
#include <unistd.h>

#define mysleep(x)  usleep((x)*1000)

void SubTran2(int sleep_level)
{
   if(sleep_level > 1)
      mysleep(20);
}

void SubTran1(int num_level2, int sleep_level)
{
   int l2;

   if(sleep_level > 0)
      mysleep(5);

   for(l2=1; l2<=num_level2; ++l2)
   {
      printf("     start %d/%d level two\n", l2, num_level2);
      SubTran2(sleep_level);
      printf("     stop %d/%d level two\n", l2, num_level2);
   }

   if(sleep_level > 2)
      mysleep(6);
}

void Main(int i, int num_level1, int num_level2, int sleep_level)
{
   int l1;
   printf("%d complex_chain:\n", i);
   for(l1=1; l1<=num_level1; ++l1)
   {
      printf("  start %d/%d level one\n", l1, num_level1);
      SubTran1(num_level2, sleep_level);
      printf("  stop %d/%d level one\n", l1, num_level1);
   }
}

int main(int argc, char *argv[])
{
   int rc = 0;
   int i;
   int num= argc > 1 ? atoi(argv[1]) : 1;
   int num_level1 = argc > 2 ? atoi(argv[2]) : 3;
   int num_level2 = argc > 3 ? atoi(argv[3]) : 2;
   int sleep_level = argc > 4 ? atoi(argv[4]) : 3;

   for(i=1; i<=num; ++i)
   {
      /* now start the transaction measurement */
      printf("start %d/%d main\n", i, num);
      Main(i, num_level1, num_level2, sleep_level);
      printf("stop %d/%d main\n", i, num);
   }

   return rc;
}

#define MYARM_CPROFILER_APPLICATION_NAME "ComplexChain"
/* we define here our instrumented functions */
#define MYARM_CPROFILER_INSTRUMENT_FUNCTIONS					\
   MYARM_CPROFILER_FUNCTION(Main,    "Main",                      MYARM_CPROFILER_FLAG_NONE,   MYARM_CPROFILER_MEASURE_DEPTH(2)), \
   MYARM_CPROFILER_FUNCTION(printf,  MYARM_CPROFILER_NAME_LOOKUP, MYARM_CPROFILER_FLAG_IGNORE, MYARM_CPROFILER_MEASURE_SELF)
/* now we include MyARM C Profiler */
#include "myarmcprofiler.h"