Tag Archives: gcc

Logging with a bit more brain

I expect many of you will use the preprocessor macros of __LINE__ and __FILE__ for logging. It’s fairly standard practice, but if you don’t, then I’ll introduce you to it.

#define LOG(x...) log(__FILE__,__LINE__,x)

This will allow you to do, for example

LOG("Something went wrong\n");

and it will include the file and the line number in the log function as the first two parameters.

That’s fairly common. Now, what’s less common is a thing I worked out for more complex logging.
I needed to log a message which may appear very regularly, but I didn’t want to spam logfiles with millions of them, I only needed to see the first one. I thought that I’ll have to tag the log with some kind of hash value for checking when it was last used, or something like that, when I had a brainstorm. It could all be done in the preprocessor.

#define LOGO(x...) { static int loginst__LINE__=0; if (loginst__LINE__==0){ loginst__LINE__=1; log(__FILE__,__LINE__,x);}}

As you can see, the variable loginst_nnn will only be used once per file, so is unique (unless you use LOGO twice on one line, don’t do that. The macro definition has to be all on one line, obviously. I mention this because wordpress is likely to wrap it unless your screen is very wide.

That got me thinking, what else can I do with the preprocessor like this. And I came up with:

#define LOGN(n,x...) { static int loginst__LINE__=0; if (loginst__LINE__++==0){ log(__FILE__,__LINE__,x);} if (loginst__LINE__==w) loginst__LINE__=0;}

This one logs every nth occurence of the log message. I also came up with

#define LOGT(t,x...) { static time_t loginst__LINE__=0; if (loginst__LINE__<=time(NULL)){ log(__FILE__,__LINE__,x);loginst__LINE__=time(NULL)+t;}}

which only logs at most once every t seconds.

All in all, I was quite pleased with that. They’re simple, effective, and a LOT more efficient than some other solutions I’ve seen out there.

 

Profiling of basic glibc functions

There’s a lot of anecdotal evidence out there about what to do and what not to do. Standard wisdom says that malloc is expensive, for example, and realloc is even worse. But for all of the times I’ve seen people say this, I haven’t seen any concrete numbers.

So, let’s make some.

I intend to keep this post updated as a growing list of functions from glibc, to show how they compare to each other, and how efficient they are.

Method:
Loop a million times running each function once, and analysed using kcachegrind

Results

sprintf (100 bytes, 5 variables)     1,752
pthread_create                       1,115 
fclose                                 575
fopen                                  527
pthread_detach                         405
malloc                                 101
free                                    84
pthread_mutex_lock (always available)   31
pthread_mutex_init                      31
pthread_mutex_unlock                    29
gettimeofday                            12
pthread_mutex_destroy                   10
time                                     8
close                                    7
open                                     7

Getting gcc to warn you when you mess up stdargs

This article was originally published on the LGP Blog on Wednesday, January 20th, 2010

Sometimes, you may write functions in C that do things in the same way as printf, using stdargs.

An example of this would be something like this short debug function

int ptf(const char *fmt,...)
{
  va_list varlist;
  FILE *fp=fopen("/tmp/debug","a");
  va_start(varlist,fmt);
  vfprintf(fp,fmt,varlist);
  va_end(varlist);
  fclose(fp);
}

This function isn’t rocket science, it just simply appends your string into a file. It is a simple time saver utility.

However, using it can be a problem. You can do something like this

int x=1;
ptf("Error %s\n",x);

And gcc will say ’sure, no problem’.

But running the code will always crash. It tries to interpret the integer as a string.

This is the kind of thing that should be picked up on by the compiler. And in fact it can be, quite easily.

In your prototype for the function, you would have something like

extern int ptf(const char *,...);

This is pretty standard, and no surprises there. However, gcc has the capability to be given a hint as to how this function should be handled. You can instead prototype the function using

extern int ptf(const char *,...) __attribute__ ((format (printf, 1, 2)));

This tells gcc to treat the parameters 1 and 2 as the parameters to printf (which it knows how to check for errors). It will then check parameter 1 (the format string) against what is passed in starting at parameter 2 (the …). If an incorrect data type is used, this will now be detected and flagged up as a warning, in exactly the same way as an incorrect type used in a printf.

Variable length C macros

This article was originally published on the LGP Blog on Saturday, May 30th, 2009

Something that came up in porting X2 and X3 is that Visual Studio in Windows handles variable length macros, and as far as we could see, GCC didnt.

This means that in gcc, if you wanted to create a define that would do a job and report where it was called from, you would need to do something like:

void mydebug(const char *file,int line,const char *fmt,...)

#define DEBUGOUT1(x) mydebug(__FILE__,__LINE__,x)
#define DEBUGOUT2(x,y) mydebug(__FILE__,__LINE__,x,y)
#define DEBUGOUT3(x,y,z) mydebug(__FILE__,__LINE__,x,y,z)

and so on…

However, there is a solution which does the job, which we found after a fair amount of investigation. The recommended method would be

#define DEBUGOUT(x,y...) mydebug(__FILE__,__LINE__,x,y)

Which will work, but only if you actually add a second parameter to the DEBUGOUT call. Without, it will expand

DEBUGOUT(x)

to

mydebug(__FILE__,__LINE__,x,)

which will obviously fail to compile. To fix this, simply bear in mind that … in the macro just means everything else, so you can do

#define DEBUGOUT(x...) mydebug(__FILE__,__LINE__,x)

which then works with single and multiple values in macros, x becomes the fmt AND the … for the mydebug .