Simple tag based log and timing helper macros and functions.

Motivation

FreeCAD Base::Console() is capable of outputting to different targets, and has some basic enable/disable control of different types of logs. There is, however, no easy way to use logging facility for various FC modules. This set of helper macros and function is aimed to provide a unified logging (and timing) interface. The interface is mainly designed for C++ code. Python code can also take some advantage of log level control interface. The developer can now leave their logging code permanently active in the source code without impact on performance, and the log can be easily turned on/off dynamically using Python console for debugging purpose, even in release build.

Sample Usage

A set of macros is provided to ease the usage of tag based log. All the macros are defined in <Base/Console.h>. At the beginning of your C++ source, you need to initialize the log level of your chosen tag using,

FC_LOG_LEVEL_INIT(tag)

It makes sense to use the same tag in multiple files for easy log level control. Please check Customization if You want more than one tag inside the same source file.

Predefined log levels are,

#define FC_LOGLEVEL_ERR 0
#define FC_LOGLEVEL_WARN 1
#define FC_LOGLEVEL_MSG 2
#define FC_LOGLEVEL_LOG 3
#define FC_LOGLEVEL_TRACE 4

Bigger log level integer values have lower priorities. There is a special log level,

#define FC_LOGLEVEL_DEFAULT -1

Actually, any negative log level behave the same, which is for tags that are not previously configured by user. The actual log level applied is controlled by Base::Console().SetDefaultLogLevel(). Python developers/end-users can configure the default log level by calling

FreeCAD.setLogLevel('Default',level)

FreeCAD.setLogLevel('DebugDefault',level)

where level is either a string of value Error, Warning, Message, Log, Trace or an integer value. By default, on release build, the default log level is FC_LOGLEVEL_MSG, and on debug build, FC_LOGLEVEL_LOG.

Python code can call FreeCAD.setLogLevel(tag,level) to configure any other tag log levels, and FreeCAD.getLogLevel(tag), which outputs only integer log level.

You can fine tune how the log is output by passing extra parameters to #FC_LOG_LEVEL_INIT(). All the extra parameters are boolean value, which are shown blew along with their default values.

FC_LOG_LEVEL_INIT(tag, print_tag=true, print_src=0,

print_time=false, add_eol=true, refresh=false)

You can dynamically modify the log style as well, by changing these variables before the actual log output macro. See Customization for more details

FC_LOG_INSTANCE.refresh = true; // print time for each log, default false.
 
// print file and line number, default 0, if set to 2 then print python
// source from current call frame.
FC_LOG_INSTANCE.print_src = 1;
 
FC_LOG_INSTANCE.print_tag = false; // do not print tag, default true
FC_LOG_INSTANCE.add_eol = false; // do not add eol
FC_LOG_INSTANCE.refresh = true; // refresh GUI after each log

Be careful with 'refresh' option. Its current implementation calls QCoreApplication::sendPostedEvent() which may cause some unexpected behavior, especially when called inside a destructor.

The actual logging macros are

FC_ERR(msg)
FC_WARN(msg)
FC_MSG(msg)
FC_LOG(msg)
FC_TRACE(msg)

The logging macros correspond to existing Base::Console() output functions, and FC_TRACE uses Base::Console().Log(), same as FC_LOG. These macros checks the log level defined in FC_LOG_LEVEL_INIT to decide whether to print log or not. msg here shall be a C++ streaming expression. End of line will be automatically appended by default.

FC_ERR("error: " << code << ". exiting")

Timing Helpers

This set of macros is for helping C++ code to time lengthy operations. Examples:

void operation() {
     FC_TIME_INIT(t);
 
     //do stuff
 
     FC_TIME_LOG(t,"operation done.");
}

This will output in console something like,

operation done. time: 1.12s

Every time you call FC_TIME_LOG it will calculate the time duration between this call and the last FC_TIME_LOG or FC_TIME_INIT. Time variable t will then be updated to the current time. You can also use FC_TIME_MSG, FC_TIME_TRACE similar to FC_MSG and FC_TRACE.

To time operation in multiple stages,

void operation() {
     FC_TIME_INIT2(t,t1);
 
     //do stage 1
 
     FC_TIME_LOG(t1,"stage1");
 
     //do stage 2
 
     FC_TIME_LOG(t1,"stage2");
 
     // do other stuff
 
     FC_TIME_LOG(t,"total");
}

Will output something like,

stage1 time: 1.2s
stage2 time: 2.3s
total time: 4.0s

To time operation in multiple functions,

class Timing {
     FC_DURATION_DECLARE(d1)
     FC_DURATION_DECLARE(d1_1)
     FC_DURATION_DECLARE(d1_2)
     FC_DURATION_DECLARE(d2);
 
     Timing() {
         FC_DURATION_INIT(d1);
         FC_DURATION_INIT(d1_1);
         FC_DURATION_INIT(d1_2);
         FC_DURATION_INIT(d2);
     }
};
 
void operation1(Timing &timing) {
 
     FC_TIME_INIT(t);
 
     for(...) {
         FC_TIME_INIT(t1);
 
         //do setp 1
 
         FC_DURATION_PLUS(timing.d1_1,t1);
 
         // do step 2
 
         FC_DURATION_PLUS(timing.d1_2,t1);
     }
 
     // do other stuff
 
     FC_DRUATION_PLUS(timing.d1, t);
}
 
void operation2(Timing &timing) {
 
     FC_TIME_INIT(t);
 
     // do stuff
 
     FC_DRUATION_PLUS(timing.d2, t);
}
 
void operation() {
 
     Timing timing;
 
     FC_TIME_INIT(t);
 
     for(...) {
         operation1(timing);
 
         // do other stuff
 
         operation2(timing);
     }
 
     FC_DURATION_LOG(timing.d1_1,"operation 1 step 1");
     FC_DURATION_LOG(timing.d1_2,"operation 1 step 2");
     FC_DURATION_LOG(timing.d1,"operation 1");
     FC_DURATION_LOG(timing.d2,"operation 2");
     FC_TIME_LOG(t,"operation total");
}

You can also use FC_DURATION_MSG, FC_DURATION_TRACE as usual.

If you use only macros provided here to do timing, the entire timing code can be compiled out by defining FC_LOG_NO_TIMING before including App/Console.h.

Customization

Most of the logging facilities are exposed through macros. This section briefs how they are implemented under the hood in case you want customization. A new function GetLogLevel(tag) is added to Base::Console() to let C++ developer query a log level for an arbitrary string tag. The function returns a pointer to an integer representing the log level. Python developer or end-user can set/get the same tag based log level using FreeCAD.setLogLevel/getLogLevel. Any change to the log level is reflected through the pointer returned by Base::Console().GetLogLevel(). What FC_LOG_LEVEL_INIT(tag) does is to define a class Base::LogLevel, and then a file static instance of that class to store the pointer to the desired tag log level. The class and instance name is predefined. Various log macros will check that instance to query log level. If you some how want to have more than one tag inside the same source file, use the following macros to define a second instance of name instance_name

_FC_LOG_LEVEL_INIT(instance_name,tag)

Then, define a second set of logging macros as

#define MY_MSG(_msg) _FC_PRINT(instance_name,FC_LOGLEVEL_MSG,Message,_msg)
#define MY_WARN(_msg) _FC_PRINT(instance_name,FC_LOGLEVEL_WARN,Warning,_msg)
#define MY_ERR(_msg) _FC_PRINT(instance_name,FC_LOGLEVEL_ERR,Error,_msg)
#define MY_LOG(_msg) _FC_PRINT(instance_name,FC_LOGLEVEL_LOG,Log,_msg)
#define MY_TRACE(_msg) _FC_PRINT(instance_name,FC_LOGLEVEL_TRACE,Log,_msg)

Note, replace instance_name with your actual desired name.

You can also define your own log levels the same way. Macro #_FC_PRINT(_instance,_l,_func,_msg) checks to see if the log shall proceed, where _instance is the static loglevel instance name (default is FC_LOG_INSTANCE), and _l is the log level constant to be checked, _func is the Base::Console() function to print the log.