Profiling macro 'profile': docs and loglevel fix.R6282

Add comments and an example in navit.xml for the use of macro 'profile'.
Fix the profile logging to use log level debug.

3 files changed, 32 insertions, 1 deletions

diff --git a/navit/navit_shipped.xml b/navit/navit_shipped.xml
index 479e370c8..9ac4f0faf 100644
--- a/navit/navit_shipped.xml
+++ b/navit/navit_shipped.xml
@@ -21,6 +21,9 @@
 	<debug name="navit:do_draw" dbg_level="error"/>
 	<!-- This is here so one can copy&paste the contents of popup menus --> 
 	<debug name="navit:popup_printf_cb" dbg_level="debug"/>
+	<!-- Example for logging timing/profiling information. Note the prefix "profile:".
+	<debug name="profile:navit:do_draw" dbg_level="debug"/>
+	-->
 	<!-- segv: 1 - show backtrace with gdb and exit, 2 - stay in gdb -->
 	<debug name="segv" level="1"/>
 	<!-- timestamps 0/1 - prefix log messages with a timestamp -->
diff --git a/navit/profile.c b/navit/profile.c
index a79103132..564a63096 100644
--- a/navit/profile.c
+++ b/navit/profile.c
@@ -29,6 +29,30 @@
 
 #define PROFILE_LEVEL_MAX 9
 
+/**
+ * @brief Log timing information.
+ *
+ * @note Normally this function is called via the macro 'profile', which automatically fills in
+ * parameters 'module' and 'function'.
+ *
+ * Successive calls to this function will print the elapsed time between calls, using an
+ * internal timer. To start/reset the internal timer without printing a message, set parameter
+ * 'fmt' to NULL.
+ *
+ * To run multiple timers in parallel, the parameter 'level' can be used. Each invocation will
+ * print the elapsed time to the last invocation with the same level. As an exception, calling
+ * with 'fmt'=NULL wll reset all timers with a level greater or equal to the level parameter.
+ *
+ * Typically, profiling is started by calling profile(0, NULL). Then calls with various levels
+ * can be used to print different intermediate timings.
+ *
+ * @param level level of timer to use (0 to PROFILE_LEVEL_MAX).
+ * @param module name of current module (for logging)
+ * @param function name of current function (for logging)
+ * @param fmt format string Log message to print (as a printf format string), followed by required
+ * parameters as varargs. May be NULL; then no message is printed, and all timers with the
+ * same or higher level are reset.
+ */
 void
 profile_timer(int level, const char *module, const char *function, const char *fmt, ...)
 {
@@ -50,7 +74,7 @@ profile_timer(int level, const char *module, const char *function, const char *f
 	
 		sprintf(buffer, "profile:%s", module);
 		va_start(ap, fmt);
-		debug_vprintf(1, buffer, strlen(buffer), function, strlen(function), 1, fmt, ap); 
+		debug_vprintf(lvl_debug, buffer, strlen(buffer), function, strlen(function), 1, fmt, ap);
 		va_end(ap);
 		debug_printf(lvl_debug, buffer, strlen(buffer), function, strlen(function), 0, " %7.1f ms\n", msec);
 		gettimeofday(&last[level], NULL);
diff --git a/navit/profile.h b/navit/profile.h
index 5441221be..e6f900fce 100644
--- a/navit/profile.h
+++ b/navit/profile.h
@@ -29,6 +29,10 @@ extern "C" {
 #define profile_str2(x) #x
 #define profile_str1(x) profile_str2(x)
 #define profile_module profile_str1(MODULE)
+/*
+ * Macro for logging timing information.
+ * See function profile_timer for more information.
+ */
 #define profile(level,...) profile_timer(level,profile_module,__PRETTY_FUNCTION__,__VA_ARGS__)
 void profile_timer(int level, const char *module, const char *function, const char *fmt, ...);
 #ifdef __cplusplus