Push log message formatting to subscribers

This avoids allocating memory and formatting debug messages when none
of the subscribers care about them.

include/vlc_messages.h

@@ -56,12 +56,10 @@ enum msg_item_type
  */
 typedef struct
 {
-    unsigned    i_type;  /**< Message type, see @ref msg_item_type */
     uintptr_t   i_object_id; /**< Emitter (temporaly) unique object ID or 0 */
     const char *psz_object_type; /**< Emitter object type name */
     const char *psz_module; /**< Emitter module (source code) */
     const char *psz_header; /**< Additional header (used by VLM media) */
-    char       *psz_msg; /**< Message text */
 } msg_item_t;
 
 /**
@@ -91,7 +89,8 @@ VLC_API void vlc_vaLog(vlc_object_t *, int,
  * Message logging callback signature.
  * Accepts one private data pointer, the message, and an overrun counter.
  */
-typedef void (*msg_callback_t) (void *, const msg_item_t *);
+typedef void (*msg_callback_t) (void *, int, const msg_item_t *,
+                                const char *, va_list);
 
 VLC_API msg_subscription_t *vlc_Subscribe(msg_callback_t, void *) VLC_USED;
 VLC_API void vlc_Unsubscribe(msg_subscription_t *);

modules/gui/ncurses.c

@@ -192,7 +192,12 @@ struct intf_sys_t
     int             i_box_idx;          // selected line
 
     msg_subscription_t  *p_sub;         // message bank subscription
-    msg_item_t          *msgs[50];      // ring buffer
+    struct
+    {
+        int              type;
+        msg_item_t      *item;
+        char            *msg;
+    } msgs[50];      // ring buffer
     int                 i_msgs;
     int                 i_verbosity;
     vlc_mutex_t         msg_lock;
@@ -1064,12 +1069,13 @@ static int DrawMessages(intf_thread_t *p_intf)
     i = p_sys->i_msgs;
     for(;;)
     {
-        msg_item_t *msg = p_sys->msgs[i];
+        msg_item_t *msg = p_sys->msgs[i].item;
         if (msg)
         {
             if (p_sys->b_color)
-                color_set(msg->i_type + C_INFO, NULL);
-            MainBoxWrite(p_sys, l++, "[%s] %s", msg->psz_module, msg->psz_msg);
+                color_set(p_sys->msgs[i].type + C_INFO, NULL);
+            MainBoxWrite(p_sys, l++, "[%s] %s", msg->psz_module,
+                         p_sys->msgs[i].msg);
         }
 
         if (++i == sizeof p_sys->msgs / sizeof *p_sys->msgs)
@@ -1813,11 +1819,9 @@ static void HandleKey(intf_thread_t *p_intf)
 static msg_item_t *msg_Copy (const msg_item_t *msg)
 {
     msg_item_t *copy = (msg_item_t *)xmalloc (sizeof (*copy));
-    copy->i_type = msg->i_type;
     copy->i_object_id = msg->i_object_id;
     copy->psz_object_type = msg->psz_object_type;
     copy->psz_module = strdup (msg->psz_module);
-    copy->psz_msg = strdup (msg->psz_msg);
     copy->psz_header = msg->psz_header ? strdup (msg->psz_header) : NULL;
     return copy;
 }
@@ -1826,25 +1830,30 @@ static void msg_Free (msg_item_t *msg)
 {
     free ((char *)msg->psz_module);
     free ((char *)msg->psz_header);
-    free (msg->psz_msg);
     free (msg);
 }
 
-static void MsgCallback(void *data, const msg_item_t *msg)
+static void MsgCallback(void *data, int type, const msg_item_t *msg,
+                        const char *format, va_list ap)
 {
     intf_sys_t *p_sys = data;
+    char *text;
 
     if (p_sys->i_verbosity < 0
-     || p_sys->i_verbosity < (msg->i_type - VLC_MSG_ERR))
+     || p_sys->i_verbosity < (type - VLC_MSG_ERR)
+     || vasprintf(&text, format, ap) == -1)
         return;
 
     vlc_mutex_lock(&p_sys->msg_lock);
 
-    if (p_sys->msgs[p_sys->i_msgs])
-        msg_Free(p_sys->msgs[p_sys->i_msgs]);
-    p_sys->msgs[p_sys->i_msgs++] = msg_Copy(msg);
+    p_sys->msgs[p_sys->i_msgs].type = type;
+    if (p_sys->msgs[p_sys->i_msgs].item != NULL)
+        msg_Free(p_sys->msgs[p_sys->i_msgs].item);
+    p_sys->msgs[p_sys->i_msgs].item = msg_Copy(msg);
+    free(p_sys->msgs[p_sys->i_msgs].msg);
+    p_sys->msgs[p_sys->i_msgs].msg = text;
 
-    if (p_sys->i_msgs == (sizeof p_sys->msgs / sizeof *p_sys->msgs))
+    if (++p_sys->i_msgs == (sizeof p_sys->msgs / sizeof *p_sys->msgs))
         p_sys->i_msgs = 0;
 
     vlc_mutex_unlock(&p_sys->msg_lock);
@@ -1965,8 +1974,10 @@ static void Close(vlc_object_t *p_this)
     vlc_mutex_destroy(&p_sys->msg_lock);
     vlc_mutex_destroy(&p_sys->pl_lock);
     for(unsigned i = 0; i < sizeof p_sys->msgs / sizeof *p_sys->msgs; i++)
-        if (p_sys->msgs[i])
-            msg_Free(p_sys->msgs[i]);
-
+    {
+        if (p_sys->msgs[i].item)
+            msg_Free(p_sys->msgs[i].item);
+        free(p_sys->msgs[i].msg);
+    }
     free(p_sys);
 }

modules/gui/qt4/dialogs/messages.cpp

@@ -48,7 +48,7 @@ enum {
 class MsgEvent : public QEvent
 {
 public:
-    MsgEvent( const msg_item_t * );
+    MsgEvent( int, const msg_item_t *, const char * );
 
     int priority;
     uintptr_t object_id;
@@ -58,14 +58,14 @@ public:
     QString text;
 };
 
-MsgEvent::MsgEvent( const msg_item_t *msg )
+MsgEvent::MsgEvent( int type, const msg_item_t *msg, const char *text )
     : QEvent( (QEvent::Type)MsgEvent_Type ),
-      priority( msg->i_type ),
+      priority( type ),
       object_id( msg->i_object_id ),
       object_type( qfu(msg->psz_object_type) ),
       header( qfu(msg->psz_header) ),
       module( qfu(msg->psz_module) ),
-      text( qfu(msg->psz_msg) )
+      text( qfu(text) )
 {
 }
 
@@ -299,15 +299,19 @@ void MessagesDialog::tabChanged( int i )
     updateButton->setVisible( i == 1 );
 }
 
-void MessagesDialog::MsgCallback( void *self, const msg_item_t *item )
+void MessagesDialog::MsgCallback( void *self, int type, const msg_item_t *item,
+                                  const char *format, va_list ap )
 {
     MessagesDialog *dialog = (MessagesDialog *)self;
+    char *str;
     int verbosity = vlc_atomic_get( &dialog->verbosity );
 
-    if( verbosity < 0 || verbosity < (item->i_type - VLC_MSG_ERR) )
+    if( verbosity < 0 || verbosity < (type - VLC_MSG_ERR)
+     || unlikely(vasprintf( &str, format, ap ) == -1) )
         return;
 
     int canc = vlc_savecancel();
-    QApplication::postEvent( dialog, new MsgEvent( item ) );
+    QApplication::postEvent( dialog, new MsgEvent( type, item, str ) );
     vlc_restorecancel( canc );
+    free( str );
 }

modules/gui/qt4/dialogs/messages.hpp

@@ -27,6 +27,7 @@
 #include "util/qvlcframe.hpp"
 #include "util/singleton.hpp"
 #include "ui/messages_panel.h"
+#include <stdarg.h>
 
 class QTabWidget;
 class QPushButton;
@@ -53,7 +54,8 @@ private:
     void sinkMessage( const MsgEvent * );
 
     vlc_atomic_t verbosity;
-    static void MsgCallback( void *, const msg_item_t * );
+    static void MsgCallback( void *, int, const msg_item_t *, const char *,
+                             va_list );
 
     QStringList filter;
     bool filterDefault;

modules/misc/logger.c

@@ -35,6 +35,7 @@
 #include <vlc_fs.h>
 #include <vlc_charset.h>
 
+#include <stdarg.h>
 #include <assert.h>
 
 #define MODE_TEXT 0
@@ -88,11 +89,11 @@ struct intf_sys_t
 static int  Open    ( vlc_object_t * );
 static void Close   ( vlc_object_t * );
 
-static void Overflow (void *p_sys, const msg_item_t *p_item);
-static void TextPrint         ( const msg_item_t *, FILE * );
-static void HtmlPrint         ( const msg_item_t *, FILE * );
+static void Overflow (void *, int, const msg_item_t *, const char *, va_list);
+static void TextPrint (FILE *, int, const msg_item_t *, const char *);
+static void HtmlPrint (FILE *, int, const msg_item_t *, const char *);
 #ifdef HAVE_SYSLOG_H
-static void SyslogPrint       ( const msg_item_t *);
+static void SyslogPrint (int, const msg_item_t *, const char *);
 #endif
 
 /*****************************************************************************
@@ -359,49 +360,42 @@ static void Close( vlc_object_t *p_this )
 /**
  * Log a message
  */
-static void Overflow (void *opaque, const msg_item_t *p_item)
+static void Overflow (void *opaque, int type, const msg_item_t *p_item,
+                      const char *format, va_list ap)
 {
     intf_thread_t *p_intf = opaque;
     intf_sys_t *p_sys = p_intf->p_sys;
+    char *str;
 
+    /* TODO: cache value... */
     int verbosity = var_InheritInteger( p_intf, "log-verbose" );
     if (verbosity == -1)
         verbosity = var_InheritInteger( p_intf, "verbose" );
 
-    switch( p_item->i_type )
-    {
-        case VLC_MSG_INFO:
-        case VLC_MSG_ERR:
-            if( verbosity < 0 ) return;
-            break;
-        case VLC_MSG_WARN:
-            if( verbosity < 1 ) return;
-            break;
-        case VLC_MSG_DBG:
-            if( verbosity < 2 ) return;
-            break;
-    }
-
+    if( verbosity < 0 || verbosity < (type - VLC_MSG_ERR)
+     || vasprintf( &str, format, ap) == -1 )
+        return;
 
     int canc = vlc_savecancel();
 
     switch( p_sys->i_mode )
     {
         case MODE_HTML:
-            HtmlPrint( p_item, p_sys->p_file );
+            HtmlPrint( p_sys->p_file, type, p_item, str );
             break;
 #ifdef HAVE_SYSLOG_H
         case MODE_SYSLOG:
-            SyslogPrint( p_item );
+            SyslogPrint( type, p_item, str );
             break;
 #endif
         case MODE_TEXT:
         default:
-            TextPrint( p_item, p_sys->p_file );
+            TextPrint( p_sys->p_file, type, p_item, str );
             break;
     }
 
     vlc_restorecancel( canc );
+    free( str );
 }
 
 static const char ppsz_type[4][11] = {
@@ -411,29 +405,31 @@ static const char ppsz_type[4][11] = {
     " debug: ",
 };
 
-static void TextPrint( const msg_item_t *p_msg, FILE *p_file )
+static void TextPrint( FILE *stream, int type, const msg_item_t *item,
+                       const char *str )
 {
-    utf8_fprintf( p_file, "%s%s%s\n", p_msg->psz_module,
-                  ppsz_type[p_msg->i_type], p_msg->psz_msg );
+    utf8_fprintf( stream, "%s%s%s\n", item->psz_module,
+                  ppsz_type[type], str );
 }
 
 #ifdef HAVE_SYSLOG_H
-static void SyslogPrint( const msg_item_t *p_msg )
+static void SyslogPrint( int type, const msg_item_t *item, const char *str )
 {
     static const int i_prio[4] = { LOG_INFO, LOG_ERR, LOG_WARNING, LOG_DEBUG };
-    int i_priority = i_prio[p_msg->i_type];
+    int i_priority = i_prio[type];
 
-    if( p_msg->psz_header )
-        syslog( i_priority, "[%s] %s%s%s", p_msg->psz_header,
-                p_msg->psz_module, ppsz_type[p_msg->i_type], p_msg->psz_msg );
+    if( item->psz_header != NULL )
+        syslog( i_priority, "[%s] %s%s%s", item->psz_header,
+                item->psz_module, ppsz_type[type], str );
     else
         syslog( i_priority, "%s%s%s",
-                p_msg->psz_module, ppsz_type[p_msg->i_type], p_msg->psz_msg );
+                item->psz_module, ppsz_type[type], str );
  
 }
 #endif
 
-static void HtmlPrint( const msg_item_t *p_msg, FILE *p_file )
+static void HtmlPrint( FILE *stream, int type, const msg_item_t *item,
+                       const char *str )
 {
     static const char ppsz_color[4][30] = {
         "<span style=\"color: #ffffff\">",
@@ -442,7 +438,6 @@ static void HtmlPrint( const msg_item_t *p_msg, FILE *p_file )
         "<span style=\"color: #aaaaaa\">",
     };
 
-    fprintf( p_file, "%s%s%s%s</span>\n", p_msg->psz_module,
-             ppsz_type[p_msg->i_type], ppsz_color[p_msg->i_type],
-             p_msg->psz_msg );
+    fprintf( stream, "%s%s%s%s</span>\n", item->psz_module,
+             ppsz_type[type], ppsz_color[type], str );
 }

src/misc/messages.c

@@ -129,8 +129,9 @@ void vlc_Log (vlc_object_t *obj, int type, const char *module,
     va_end (args);
 }
 
-static void PrintColorMsg (void *, const msg_item_t *);
-static void PrintMsg (void *, const msg_item_t *);
+static void PrintColorMsg (void *, int, const msg_item_t *,
+                           const char *, va_list);
+static void PrintMsg (void *, int, const msg_item_t *, const char *, va_list);
 
 /**
  * Emit a log message. This function is the variable argument list equivalent
@@ -204,24 +205,12 @@ void vlc_vaLog (vlc_object_t *obj, int type, const char *module,
     }
 #endif
 
-    /* Convert message to string  */
-    static const char nomemstr[] = "<not enough memory to format message>";
-    char *str;
-
-    if (unlikely(vasprintf (&str, format, args) == -1))
-        str = (char *)nomemstr;
-
-    uselocale (locale);
-    freelocale (c);
-
     /* Fill message information fields */
     msg_item_t msg;
 
-    msg.i_type = type;
     msg.i_object_id = (uintptr_t)obj;
     msg.psz_object_type = obj->psz_object_type;
     msg.psz_module = module;
-    msg.psz_msg = str;
     msg.psz_header = NULL;
 
     for (vlc_object_t *o = obj; o != NULL; o = o->p_parent)
@@ -234,18 +223,26 @@ void vlc_vaLog (vlc_object_t *obj, int type, const char *module,
     /* Pass message to subscribers */
     libvlc_priv_t *priv = libvlc_priv (obj->p_libvlc);
 
+    va_list ap;
+
+    va_copy (ap, args);
     if (priv->b_color)
-        PrintColorMsg (&priv->i_verbose, &msg);
+        PrintColorMsg (&priv->i_verbose, type, &msg, format, ap);
     else
-        PrintMsg (&priv->i_verbose, &msg);
+        PrintMsg (&priv->i_verbose, type, &msg, format, ap);
+    va_end (ap);
 
     vlc_rwlock_rdlock (&msg_lock);
     for (msg_subscription_t *sub = msg_head; sub != NULL; sub = sub->next)
-        sub->func (sub->opaque, &msg);
+    {
+        va_copy (ap, args);
+        sub->func (sub->opaque, type, &msg, format, ap);
+        va_end (ap);
+    }
     vlc_rwlock_unlock (&msg_lock);
 
-    if (likely(str != (char *)nomemstr))
-        free (str);
+    uselocale (locale);
+    freelocale (c);
 }
 
 static const char msg_type[4][9] = { "", " error", " warning", " debug" };
@@ -257,11 +254,11 @@ static const char msg_type[4][9] = { "", " error", " warning", " debug" };
 #define GRAY    "\033[0m"
 static const char msg_color[4][8] = { WHITE, RED, YELLOW, GRAY };
 
-static void PrintColorMsg (void *d, const msg_item_t *p_item)
+static void PrintColorMsg (void *d, int type, const msg_item_t *p_item,
+                           const char *format, va_list ap)
 {
     const int *pverbose = d;
     FILE *stream = stderr;
-    int type = p_item->i_type;
 
     if (*pverbose < 0 || *pverbose < (type - VLC_MSG_ERR))
         return;
@@ -272,9 +269,10 @@ static void PrintColorMsg (void *d, const msg_item_t *p_item)
     fprintf (stream, "["GREEN"%p"GRAY"] ", (void *)p_item->i_object_id);
     if (p_item->psz_header != NULL)
         utf8_fprintf (stream, "[%s] ", p_item->psz_header);
-    utf8_fprintf (stream, "%s %s%s: %s%s"GRAY"\n", p_item->psz_module,
-                  p_item->psz_object_type, msg_type[type], msg_color[type],
-                  p_item->psz_msg);
+    utf8_fprintf (stream, "%s %s%s: %s", p_item->psz_module,
+                  p_item->psz_object_type, msg_type[type], msg_color[type]);
+    utf8_vfprintf (stream, format, ap);
+    fputs (GRAY"\n", stream);
 #if defined (WIN32) || defined (__OS2__)
     fflush (stream);
 #endif
@@ -282,11 +280,11 @@ static void PrintColorMsg (void *d, const msg_item_t *p_item)
     vlc_restorecancel (canc);
 }
 
-static void PrintMsg (void *d, const msg_item_t *p_item)
+static void PrintMsg (void *d, int type, const msg_item_t *p_item,
+                      const char *format, va_list ap)
 {
     const int *pverbose = d;
     FILE *stream = stderr;
-    int type = p_item->i_type;
 
     if (*pverbose < 0 || *pverbose < (type - VLC_MSG_ERR))
         return;
@@ -297,8 +295,10 @@ static void PrintMsg (void *d, const msg_item_t *p_item)
     fprintf (stream, "[%p] ", (void *)p_item->i_object_id);
     if (p_item->psz_header != NULL)
         utf8_fprintf (stream, "[%s] ", p_item->psz_header);
-    utf8_fprintf (stream, "%s %s%s: %s\n", p_item->psz_module,
-                  p_item->psz_object_type, msg_type[type], p_item->psz_msg);
+    utf8_fprintf (stream, "%s %s%s: ", p_item->psz_module,
+                  p_item->psz_object_type, msg_type[type]);
+    utf8_vfprintf (stream, format, ap);
+    fputc_unlocked ('\n', stream);
 #if defined (WIN32) || defined (__OS2__)
     fflush (stream);
 #endif