[PATCHES] Logging to multiple debug backends

[Christof Schmitt]

On Mon, Mar 16, 2015 at 11:56:06AM +0100, Volker Lendecke wrote:
> On Sat, Mar 14, 2015 at 02:52:05PM +1100, Martin Schwenke wrote:
> > The debug code is very heavily used so I would prematurely
> > optimise.  :-)  Instead of using an array of all possible backends in
> > debug_set_backends() and debug_backends_log(), I would suggest using a
> > doubly-linked list, and inserting the backends in reverse-sorted order
> > of priority.  Then you only need to traverse the list as long as
> > msg_level <= log_level.  This makes debug_set_backends() more expensive
> > but makes debug_backends_log() cheaper.
> 
> If you *really* want to prematurely optimize, I would recommend splitting
> the array into two, just for cache locality. If you make it two arrays,
> one with full information and one with just what is required in the
> debug_backends_log for-loop, you should be able to squeeze 4 backends
> into 64 bytes. At that point I'd say the for-loop over all those 4
> backends comes at almost no cost. Most of it should be hidden behind
> loop unrolling and speculative execution. A linked list will very likely
> be much more expensive to chase through our 15 levels of cache these
> days. That together with the fact that we only enter debug_backends_log()
> when there is something to log, my gut feeling is that everything else
> will be much more expensive than walking 2 or 3 backends unnecessarily.

I started implementing a separate array, see the attached patch. So far
it compiles, but it is untested. Does that fit your idea?

If we agree that this is worthwhile, i will cleanup and squash the patch
and resubmit the patch series.

Christof
-------------- next part --------------
From 200186e312204b79a6a45e8e5edf3cd81f90d888 Mon Sep 17 00:00:00 2001
From: Christof Schmitt <cs at samba.org>
Date: Mon, 16 Mar 2015 13:50:33 -0700
Subject: [PATCH] introduce optimized array

---
 lib/util/debug.c |   71 ++++++++++++++++++++++++++++++++++++++++++++++++-----
 1 files changed, 64 insertions(+), 7 deletions(-)

diff --git a/lib/util/debug.c b/lib/util/debug.c
index e246945..9d6cf81 100644
--- a/lib/util/debug.c
+++ b/lib/util/debug.c
@@ -28,6 +28,7 @@
 #include "close_low_fd.h"
 #include "memory.h"
 #include "samba_util.h" /* LIST_SEP */
+#include "tsort.h"
 #include "debug.h"
 
 /* define what facility to use for syslog */
@@ -230,10 +231,10 @@ static void debug_gpfs_log(int msg_level,
 
 static struct debug_backend {
 	const char *name;
-	int log_level;
-	int new_log_level;
 	void (*reload)(bool enabled, bool prev_enabled, const char *prog_name);
 	void (*log)(int msg_level, const char *msg, const char *msg_no_nl);
+	int new_log_level;
+	int log_level;
 } debug_backends[] = {
 	{
 		.name = "file",
@@ -270,6 +271,18 @@ static struct debug_backend {
 #endif
 };
 
+/*
+ * Optimized array for debug_backends_do_log(). The minimum information
+ * is kept for calling the logging backend, for the data to fit in a
+ * cacheline when possible. Entries are also kept in descending order
+ * of log level, so that the loop in debug_backends_do_log() can exit
+ * early.
+ */
+static struct debug_backend_log {
+	void (*log)(int msg_level, const char *msg, const char *msg_no_nl);
+	int log_level;
+} debug_backends_log[ARRAY_SIZE(debug_backends)];
+
 static struct debug_backend *debug_find_backend(const char *name)
 {
 	int i;
@@ -307,6 +320,25 @@ static void debug_backend_parse_token(char *tok)
 }
 
 /*
+ * Comparison for sorting by decreasing log level.
+ */
+static int debug_backends_compare(const void *data1, const void *data2)
+{
+	const struct debug_backend *b1 = data1;
+	const struct debug_backend *b2 = data2;
+
+	if (b1->log_level > b2->log_level) {
+		return -1;
+	}
+
+	if (b1->log_level < b2->log_level) {
+		return 1;
+	}
+
+	return 0;
+}
+
+/*
  * parse string "backend1[:loglevel1] backend2[:loglevel2] ... " and
  * enable/disable backends accordingly
  */
@@ -342,6 +374,7 @@ static void debug_set_backends(const char *param)
 	 */
 	for (i = 0; i < ARRAY_SIZE(debug_backends); i++) {
 		struct debug_backend *b = &debug_backends[i];
+		struct debug_backend_log *bl = &debug_backends_log[i];
 
 		if (b->reload) {
 			bool enabled = b->new_log_level > -1;
@@ -350,10 +383,22 @@ static void debug_set_backends(const char *param)
 			b->reload(enabled, previously_enabled, state.prog_name);
 		}
 		b->log_level = b->new_log_level;
+
+		/*
+		 * Update optimized array
+		 */
+		bl->log = b->log;
+		bl->log_level = b->log_level;
 	}
+
+	/*
+	 * Sort optimized array again
+	 */
+	TYPESAFE_QSORT(debug_backends_log, ARRAY_SIZE(debug_backends_log),
+		       debug_backends_compare);
 }
 
-static void debug_backends_log(const char *msg, int msg_level)
+static void debug_backends_do_log(const char *msg, int msg_level)
 {
 	char msg_no_nl[FORMAT_BUFR_SIZE];
 	int len = strlen(msg);
@@ -370,10 +415,18 @@ static void debug_backends_log(const char *msg, int msg_level)
 	memcpy(msg_no_nl, msg, len);
 	msg_no_nl[len] = '\0';
 
-	for (i = 0; i < ARRAY_SIZE(debug_backends); i++) {
-		if (msg_level <= debug_backends[i].log_level) {
-			debug_backends[i].log(msg_level, msg, msg_no_nl);
+	for (i = 0; i < ARRAY_SIZE(debug_backends_log); i++) {
+		struct debug_backend_log *bl = &debug_backends_log[i];
+
+		if (msg_level > bl->log_level) {
+			/*
+			 * Array is sorted by decreasing log level,
+			 * all other entries can be skipped.
+			 */
+			break;
 		}
+
+		bl->log(msg_level, msg, msg_no_nl);
 	}
 }
 
@@ -733,6 +786,10 @@ static void debug_init(void)
 		debug_backends[i].log_level = -1;
 		debug_backends[i].new_log_level = -1;
 	}
+
+	for (i = 0; i < ARRAY_SIZE(debug_backends_log); i++) {
+		debug_backends_log[i].log_level = -1;
+	}
 }
 
 void debug_set_settings(struct debug_settings *settings,
@@ -1085,7 +1142,7 @@ static void Debug1(const char *msg)
 		}
 		break;
 	case DEBUG_FILE:
-		debug_backends_log(msg, current_msg_level);
+		debug_backends_do_log(msg, current_msg_level);
 		break;
 	};
 
-- 
1.7.1