Rework logging, don't format log messages if we wouldn't log them. Results in a noticable performance

improvement.

base/BLog.h

@@ -65,17 +65,21 @@ struct _BLog_global {
 extern struct _BLog_channel blog_channel_list[];
 extern struct _BLog_global blog_global;
 
+typedef void (*BLog_logfunc) (void *);
+
 static int BLogGlobal_GetChannelByName (const char *channel_name);
 
 static void BLog_Init (_BLog_log_func log_func, _BLog_free_func free_func);
 static void BLog_Free (void);
 static void BLog_SetChannelLoglevel (int channel, int loglevel);
+static int BLog_WouldLog (int channel, int level);
 static void BLog_AppendVarArg (const char *fmt, va_list vl);
 static void BLog_Append (const char *fmt, ...);
 static void BLog_Finish (int channel, int level);
-static void BLog_LogToChannelStr (int channel, int level, const char *msg);
 static void BLog_LogToChannelVarArg (int channel, int level, const char *fmt, va_list vl);
 static void BLog_LogToChannel (int channel, int level, const char *fmt, ...);
+static void BLog_LogViaFuncVarArg (BLog_logfunc func, void *arg, int channel, int level, const char *fmt, va_list vl);
+static void BLog_LogViaFunc (BLog_logfunc func, void *arg, int channel, int level, const char *fmt, ...);
 
 void BLog_InitStdout (void);
 
@@ -128,6 +132,15 @@ void BLog_SetChannelLoglevel (int channel, int loglevel)
     blog_global.channels[channel].loglevel = loglevel;
 }
 
+int BLog_WouldLog (int channel, int level)
+{
+    ASSERT(blog_global.initialized)
+    ASSERT(channel >= 0 && channel < BLOG_NUM_CHANNELS)
+    ASSERT(level >= BLOG_ERROR && level <= BLOG_DEBUG)
+    
+    return (level <= blog_global.channels[channel].loglevel);
+}
+
 void BLog_AppendVarArg (const char *fmt, va_list vl)
 {
     ASSERT(blog_global.initialized)
@@ -158,47 +171,90 @@ void BLog_Finish (int channel, int level)
     ASSERT(blog_global.initialized)
     ASSERT(channel >= 0 && channel < BLOG_NUM_CHANNELS)
     ASSERT(level >= BLOG_ERROR && level <= BLOG_DEBUG)
+    ASSERT(BLog_WouldLog(channel, level))
     
     ASSERT(blog_global.logbuf_pos >= 0 && blog_global.logbuf_pos < sizeof(blog_global.logbuf))
     ASSERT(blog_global.logbuf[blog_global.logbuf_pos] == '\0')
     
-    if (level <= blog_global.channels[channel].loglevel) {
-        blog_global.log_func(channel, level, blog_global.logbuf);
-    }
+    blog_global.log_func(channel, level, blog_global.logbuf);
     
     blog_global.logbuf_pos = 0;
     blog_global.logbuf[0] = '\0';
 }
 
-void BLog_LogToChannelStr (int channel, int level, const char *msg)
+void BLog_LogToChannelVarArg (int channel, int level, const char *fmt, va_list vl)
 {
     ASSERT(blog_global.initialized)
     ASSERT(channel >= 0 && channel < BLOG_NUM_CHANNELS)
     ASSERT(level >= BLOG_ERROR && level <= BLOG_DEBUG)
     
-    BLog_Append("%s", msg);
+    if (!BLog_WouldLog(channel, level)) {
+        blog_global.logbuf_pos = 0;
+        blog_global.logbuf[0] = '\0';
+        return;
+    }
+    
+    BLog_AppendVarArg(fmt, vl);
     BLog_Finish(channel, level);
 }
 
-void BLog_LogToChannelVarArg (int channel, int level, const char *fmt, va_list vl)
+void BLog_LogToChannel (int channel, int level, const char *fmt, ...)
+{
+    ASSERT(blog_global.initialized)
+    ASSERT(channel >= 0 && channel < BLOG_NUM_CHANNELS)
+    ASSERT(level >= BLOG_ERROR && level <= BLOG_DEBUG)
+    
+    if (!BLog_WouldLog(channel, level)) {
+        blog_global.logbuf_pos = 0;
+        blog_global.logbuf[0] = '\0';
+        return;
+    }
+    
+    va_list vl;
+    va_start(vl, fmt);
+    
+    BLog_AppendVarArg(fmt, vl);
+    BLog_Finish(channel, level);
+    
+    va_end(vl);
+}
+
+void BLog_LogViaFuncVarArg (BLog_logfunc func, void *arg, int channel, int level, const char *fmt, va_list vl)
 {
     ASSERT(blog_global.initialized)
     ASSERT(channel >= 0 && channel < BLOG_NUM_CHANNELS)
     ASSERT(level >= BLOG_ERROR && level <= BLOG_DEBUG)
     
+    if (!BLog_WouldLog(channel, level)) {
+        blog_global.logbuf_pos = 0;
+        blog_global.logbuf[0] = '\0';
+        return;
+    }
+    
+    func(arg);
     BLog_AppendVarArg(fmt, vl);
     BLog_Finish(channel, level);
 }
 
-void BLog_LogToChannel (int channel, int level, const char *fmt, ...)
+void BLog_LogViaFunc (BLog_logfunc func, void *arg, int channel, int level, const char *fmt, ...)
 {
     ASSERT(blog_global.initialized)
     ASSERT(channel >= 0 && channel < BLOG_NUM_CHANNELS)
     ASSERT(level >= BLOG_ERROR && level <= BLOG_DEBUG)
     
+    if (!BLog_WouldLog(channel, level)) {
+        blog_global.logbuf_pos = 0;
+        blog_global.logbuf[0] = '\0';
+        return;
+    }
+    
     va_list vl;
     va_start(vl, fmt);
-    BLog_LogToChannelVarArg(channel, level, fmt, vl);
+    
+    func(arg);
+    BLog_AppendVarArg(fmt, vl);
+    BLog_Finish(channel, level);
+    
     va_end(vl);
 }
 

client/DatagramPeerIO.c

@@ -33,7 +33,7 @@
 #define DATAGRAMPEERIO_MODE_CONNECT 1
 #define DATAGRAMPEERIO_MODE_BIND 2
 
-#define PeerLog(_o, ...) ((_o)->logfunc((_o)->user), BLog_LogToChannel(BLOG_CURRENT_CHANNEL, __VA_ARGS__))
+#define PeerLog(_o, ...) BLog_LogViaFunc((_o)->logfunc, (_o)->user, BLOG_CURRENT_CHANNEL, __VA_ARGS__)
 
 static void init_io (DatagramPeerIO *o);
 static void free_io (DatagramPeerIO *o);

client/FrameDecider.c

@@ -42,7 +42,7 @@
 #define DECIDE_STATE_FLOOD 3
 #define DECIDE_STATE_MULTICAST 4
 
-#define PeerLog(_o, ...) ((_o)->logfunc((_o)->user), BLog_LogToChannel(BLOG_CURRENT_CHANNEL, __VA_ARGS__))
+#define PeerLog(_o, ...) BLog_LogViaFunc((_o)->logfunc, (_o)->user, BLOG_CURRENT_CHANNEL, __VA_ARGS__)
 
 static int mac_comparator (void *user, uint8_t *mac1, uint8_t *mac2)
 {

client/PeerChat.c

@@ -33,7 +33,7 @@
 
 #include <generated/blog_channel_PeerChat.h>
 
-#define PeerLog(_o, ...) ((_o)->logfunc((_o)->user), BLog_LogToChannel(BLOG_CURRENT_CHANNEL, __VA_ARGS__))
+#define PeerLog(_o, ...) BLog_LogViaFunc((_o)->logfunc, (_o)->user, BLOG_CURRENT_CHANNEL, __VA_ARGS__)
 
 static void report_error (PeerChat *o)
 {

client/StreamPeerIO.c

@@ -48,7 +48,7 @@
 #define LISTEN_STATE_GOTCLIENT 1
 #define LISTEN_STATE_FINISHED 2
 
-#define PeerLog(_o, ...) ((_o)->logfunc((_o)->user), BLog_LogToChannel(BLOG_CURRENT_CHANNEL, __VA_ARGS__))
+#define PeerLog(_o, ...) BLog_LogViaFunc((_o)->logfunc, (_o)->user, BLOG_CURRENT_CHANNEL, __VA_ARGS__)
 
 static void decoder_handler_error (StreamPeerIO *pio);
 static void connector_handler (StreamPeerIO *pio, int is_error);

client/client.c

@@ -1514,11 +1514,9 @@ void peer_logfunc (struct peer_data *peer)
 
 void peer_log (struct peer_data *peer, int level, const char *fmt, ...)
 {
-    peer_logfunc(peer);
-    
     va_list vl;
     va_start(vl, fmt);
-    BLog_LogToChannelVarArg(BLOG_CURRENT_CHANNEL, level, fmt, vl);
+    BLog_LogViaFuncVarArg((BLog_logfunc)peer_logfunc, peer, BLOG_CURRENT_CHANNEL, level, fmt, vl);
     va_end(vl);
 }
 

lwip/custom/arch/cc.h

@@ -42,7 +42,7 @@
 
 #define PACK_STRUCT_STRUCT __attribute__((packed))
 
-#define LWIP_PLATFORM_DIAG(x) { BLog_Append x; BLog_Finish(BLOG_CHANNEL_lwip, BLOG_INFO); }
+#define LWIP_PLATFORM_DIAG(x) { if (BLog_WouldLog(BLOG_CHANNEL_lwip, BLOG_INFO)) { BLog_Append x; BLog_Finish(BLOG_CHANNEL_lwip, BLOG_INFO); } }
 #define LWIP_PLATFORM_ASSERT(x) { fprintf(stderr, "%s: lwip assertion failure: %s\n", __FUNCTION__, (x)); abort(); }
 
 #define U16_F PRIu16

ncd/NCDModule.c

@@ -363,12 +363,9 @@ void NCDModuleInst_Backend_Log (NCDModuleInst *n, int channel, int level, const
 {
     DebugObject_Access(&n->d_obj);
     
-    // call log handler to append log prefix
-    n->handler_log(n->user);
-    
     va_list vl;
     va_start(vl, fmt);
-    BLog_LogToChannelVarArg(channel, level, fmt, vl);
+    BLog_LogViaFuncVarArg(n->handler_log, n->user, channel, level, fmt, vl);
     va_end(vl);
 }
 

ncd/ncd.c

@@ -151,6 +151,7 @@ static void process_start_teminating (struct process *p);
 static void process_free_statements (struct process *p);
 static size_t process_rap (struct process *p);
 static void process_assert_pointers (struct process *p);
+static void process_logfunc (struct process *p);
 static void process_log (struct process *p, int level, const char *fmt, ...);
 static void process_schedule_work (struct process *p);
 static void process_work_job_handler (struct process *p);
@@ -160,6 +161,7 @@ static struct process_statement * process_find_statement (struct process *p, siz
 static int process_resolve_name (struct process *p, size_t pos, const char *name, struct process_statement **first_ps, const char **rest);
 static int process_resolve_variable (struct process *p, size_t pos, const char *varname, NCDValue *out);
 static struct process_statement * process_resolve_object (struct process *p, size_t pos, const char *objname);
+static void process_statement_logfunc (struct process_statement *ps);
 static void process_statement_log (struct process_statement *ps, int level, const char *fmt, ...);
 static void process_statement_set_error (struct process_statement *ps);
 static void process_statement_instance_handler_event (struct process_statement *ps, int event);
@@ -849,12 +851,16 @@ void process_assert_pointers (struct process *p)
     ASSERT(p->fp == fp)
 }
 
+void process_logfunc (struct process *p)
+{
+    BLog_Append("process %s: ", p->name);
+}
+
 void process_log (struct process *p, int level, const char *fmt, ...)
 {
     va_list vl;
     va_start(vl, fmt);
-    BLog_Append("process %s: ", p->name);
-    BLog_LogToChannelVarArg(BLOG_CURRENT_CHANNEL, level, fmt, vl);
+    BLog_LogViaFuncVarArg((BLog_logfunc)process_logfunc, p, BLOG_CURRENT_CHANNEL, level, fmt, vl);
     va_end(vl);
 }
 
@@ -1236,12 +1242,17 @@ struct process_statement * process_resolve_object (struct process *p, size_t pos
     return res_ps;
 }
 
+void process_statement_logfunc (struct process_statement *ps)
+{
+    process_logfunc(ps->p);
+    BLog_Append("statement %zu: ", ps->i);
+}
+
 void process_statement_log (struct process_statement *ps, int level, const char *fmt, ...)
 {
     va_list vl;
     va_start(vl, fmt);
-    BLog_Append("process %s: statement %zu: ", ps->p->name, ps->i);
-    BLog_LogToChannelVarArg(BLOG_CURRENT_CHANNEL, level, fmt, vl);
+    BLog_LogViaFuncVarArg((BLog_logfunc)process_statement_logfunc, ps, BLOG_CURRENT_CHANNEL, level, fmt, vl);
     va_end(vl);
 }
 
@@ -1389,7 +1400,8 @@ void process_statement_instance_handler_log (struct process_statement *ps)
 {
     ASSERT(ps->state != SSTATE_FORGOTTEN)
     
-    BLog_Append("process %s: statement %zu: module: ", ps->p->name, ps->i);
+    process_statement_logfunc(ps);
+    BLog_Append("module: ");
 }
 
 void process_moduleprocess_handler_die (struct process *p)

server/server.c

@@ -182,6 +182,9 @@ static void client_remove (struct client_data *client);
 // job to finish removal after clients are informed
 static void client_dying_job (struct client_data *client);
 
+// appends client log prefix
+static void client_logfunc (struct client_data *client);
+
 // passes a message to the logger, prepending about the client
 static void client_log (struct client_data *client, int level, const char *fmt, ...);
 
@@ -1136,18 +1139,23 @@ void client_dying_job (struct client_data *client)
     return;
 }
 
-void client_log (struct client_data *client, int level, const char *fmt, ...)
+void client_logfunc (struct client_data *client)
 {
-    va_list vl;
-    va_start(vl, fmt);
     char addr[BADDR_MAX_PRINT_LEN];
     BAddr_Print(&client->addr, addr);
+    
     BLog_Append("client %d (%s)", (int)client->id, addr);
     if (client->common_name) {
         BLog_Append(" (%s)", client->common_name);
     }
     BLog_Append(": ");
-    BLog_LogToChannelVarArg(BLOG_CURRENT_CHANNEL, level, fmt, vl);
+}
+
+void client_log (struct client_data *client, int level, const char *fmt, ...)
+{
+    va_list vl;
+    va_start(vl, fmt);
+    BLog_LogViaFuncVarArg((BLog_logfunc)client_logfunc, client, BLOG_CURRENT_CHANNEL, level, fmt, vl);
     va_end(vl);
 }
 

tun2socks/tun2socks.c

@@ -182,6 +182,7 @@ static void device_read_handler_send (void *unused, uint8_t *data, int data_len)
 static int process_device_udp_packet (uint8_t *data, int data_len);
 static err_t netif_init_func (struct netif *netif);
 static err_t netif_output_func (struct netif *netif, struct pbuf *p, ip_addr_t *ipaddr);
+static void client_logfunc (struct tcp_client *client);
 static void client_log (struct tcp_client *client, int level, const char *fmt, ...);
 static err_t listener_accept_func (void *arg, struct tcp_pcb *newpcb, err_t err);
 static void client_handle_freed_client (struct tcp_client *client, int was_abrt);
@@ -927,20 +928,21 @@ out:
     return ERR_OK;
 }
 
-void client_log (struct tcp_client *client, int level, const char *fmt, ...)
+void client_logfunc (struct tcp_client *client)
 {
-    va_list vl;
-    va_start(vl, fmt);
-    
     char local_addr_s[BADDR_MAX_PRINT_LEN];
     BAddr_Print(&client->local_addr, local_addr_s);
-    
     char remote_addr_s[BADDR_MAX_PRINT_LEN];
     BAddr_Print(&client->remote_addr, remote_addr_s);
     
     BLog_Append("%05d (%s %s): ", num_clients, local_addr_s, remote_addr_s);
-    BLog_LogToChannelVarArg(BLOG_CURRENT_CHANNEL, level, fmt, vl);
-    
+}
+
+void client_log (struct tcp_client *client, int level, const char *fmt, ...)
+{
+    va_list vl;
+    va_start(vl, fmt);
+    BLog_LogViaFuncVarArg((BLog_logfunc)client_logfunc, client, BLOG_CURRENT_CHANNEL, level, fmt, vl);
     va_end(vl);
 }
 

udpgw/udpgw.c

@@ -146,6 +146,7 @@ static int process_arguments (void);
 static void signal_handler (void *unused);
 static void listener_handler (BListener *listener);
 static void client_free (struct client *client);
+static void client_logfunc (struct client *client);
 static void client_log (struct client *client, int level, const char *fmt, ...);
 static void client_disconnect_timer_handler (struct client *client);
 static void client_connection_handler (struct client *client, int event);
@@ -153,6 +154,7 @@ static void client_decoder_handler_error (struct client *client);
 static void client_recv_if_handler_send (struct client *client, uint8_t *data, int data_len);
 static void connection_init (struct client *client, uint16_t conid, BAddr addr, const uint8_t *data, int data_len);
 static void connection_free (struct connection *con);
+static void connection_logfunc (struct connection *con);
 static void connection_log (struct connection *con, int level, const char *fmt, ...);
 static void connection_free_udp (struct connection *con);
 static void connection_first_job_handler (struct connection *con);
@@ -659,14 +661,19 @@ void client_free (struct client *client)
     free(client);
 }
 
-void client_log (struct client *client, int level, const char *fmt, ...)
+void client_logfunc (struct client *client)
 {
-    va_list vl;
-    va_start(vl, fmt);
     char addr[BADDR_MAX_PRINT_LEN];
     BAddr_Print(&client->addr, addr);
+    
     BLog_Append("client (%s): ", addr);
-    BLog_LogToChannelVarArg(BLOG_CURRENT_CHANNEL, level, fmt, vl);
+}
+
+void client_log (struct client *client, int level, const char *fmt, ...)
+{
+    va_list vl;
+    va_start(vl, fmt);
+    BLog_LogViaFuncVarArg((BLog_logfunc)client_logfunc, client, BLOG_CURRENT_CHANNEL, level, fmt, vl);
     va_end(vl);
 }
 
@@ -904,18 +911,22 @@ void connection_free (struct connection *con)
     free(con);
 }
 
-void connection_log (struct connection *con, int level, const char *fmt, ...)
+void connection_logfunc (struct connection *con)
 {
-    va_list vl;
-    va_start(vl, fmt);
-    char addr[BADDR_MAX_PRINT_LEN];
-    BAddr_Print(&con->client->addr, addr);
+    client_logfunc(con->client);
+    
     if (con->closing) {
-        BLog_Append("client (%s): old connection %"PRIu16": ", addr, con->conid);
+        BLog_Append("old connection %"PRIu16": ", con->conid);
     } else {
-        BLog_Append("client (%s): connection %"PRIu16": ", addr, con->conid);
+        BLog_Append("connection %"PRIu16": ", con->conid);
     }
-    BLog_LogToChannelVarArg(BLOG_CURRENT_CHANNEL, level, fmt, vl);
+}
+
+void connection_log (struct connection *con, int level, const char *fmt, ...)
+{
+    va_list vl;
+    va_start(vl, fmt);
+    BLog_LogViaFuncVarArg((BLog_logfunc)connection_logfunc, con, BLOG_CURRENT_CHANNEL, level, fmt, vl);
     va_end(vl);
 }