Switch to filtering based on log source name instead of filename

Currently the log filter strings are used in a string comparison
against the source filename each time log message is emitted.
If no log filters at all are set, there's obviously no string
comparison to be done. If any single log filter is set though,
this imposes a compute burden on every logging call even if logs
from the file in question are disabled. This string comparison
must also be done while the logging mutex is held, which has
implications for concurrency when multiple threads are emitting
log messages.

This changes the log filtering to be done based on the virLogSource
object name. The virLogSource struct is extended to contain
'serial' and 'priority' fields. Any time the global log filter
rules are changed a global serial number is incremented. When a
log message is emitted, the serial in the virLogSource instance
is compared with the global serial number. If out of date, then
the 'priority' field in the virLogSource instance is updated based
on the new filter rules. The 'priority' field is checked to see
whether the log message should be sent to the log outputs.

The comparisons of the 'serial' and 'priority' fields are done
with no locks held. So in the common case each logging call has
an overhead of 2 integer comparisons, with no locks held. Only
if the decision is made to forward the message to the log output,
or if the 'serial' value is out of date do locks need to be
acquired.

Technically the comparisons of the 'serial' and 'priority' fields
should be done with locks held, or using atomic operations. Both
of these options have a notable performance impact, however, and
since all writes a protected by a global mutex, it is believed
that worst case behaviour where the fields are read concurrently
with being written would merely result in an mistaken emission
or dropping of the log message in question. This is an acceptable
tradeoff for the performance benefit of avoiding locking.

As a quick benchmark, a demo program that registers 500 file
descriptors with the event loop (eg equiv of 500 QEMU monitor
commands), creates pending read I/O on every FD, and then runs
virEventRunDefaultImpl() took 4.6 seconds to do 51200 iterations.
After this optimization it only takes 3.3 seconds, with the log
APIs no longer being a relevant factor in the running time.

Signed-off-by: Daniel P. Berrange <berrange@redhat.com>

diff --git a/src/util/virlog.c b/src/util/virlog.c
index 6a20b89a84ca09929a2d303e3f03286607b41b9c..21b82da6678a72eb01a3f5d9d6d63031094d2138 100644 (file)
--- a/src/util/virlog.c
+++ b/src/util/virlog.c
@@ -95,6 +95,7 @@ struct _virLogFilter {
 typedef struct _virLogFilter virLogFilter;
 typedef virLogFilter *virLogFilterPtr;
 
+static int virLogFiltersSerial = 1;
 static virLogFilterPtr virLogFilters = NULL;
 static int virLogNbFilters = 0;
 
@@ -514,6 +515,7 @@ virLogResetFilters(void)
         VIR_FREE(virLogFilters[i].match);
     VIR_FREE(virLogFilters);
     virLogNbFilters = 0;
+    virLogFiltersSerial++;
     return i;
 }
 
@@ -569,6 +571,7 @@ virLogDefineFilter(const char *match,
     virLogFilters[i].priority = priority;
     virLogFilters[i].flags = flags;
     virLogNbFilters++;
+    virLogFiltersSerial++;
 cleanup:
     virLogUnlock();
     if (ret < 0)
@@ -576,37 +579,6 @@ cleanup:
     return ret;
 }
 
-
-/**
- * virLogFiltersCheck:
- * @input: the input string
- *
- * Check the input of the message against the existing filters. Currently
- * the match is just a substring check of the category used as the input
- * string, a more subtle approach could be used instead
- *
- * Returns 0 if not matched or the new priority if found.
- */
-static int
-virLogFiltersCheck(const char *input,
-                   unsigned int *flags)
-{
-    int ret = 0;
-    size_t i;
-
-    virLogLock();
-    for (i = 0; i < virLogNbFilters; i++) {
-        if (strstr(input, virLogFilters[i].match)) {
-            ret = virLogFilters[i].priority;
-            *flags = virLogFilters[i].flags;
-            break;
-        }
-    }
-    virLogUnlock();
-    return ret;
-}
-
-
 /**
  * virLogResetOutputs:
  *
@@ -745,6 +717,30 @@ virLogVersionString(const char **rawmsg,
 }
 
 
+static void
+virLogSourceUpdate(virLogSourcePtr source)
+{
+    virLogLock();
+    if (source->serial < virLogFiltersSerial) {
+        unsigned int priority = virLogDefaultPriority;
+        unsigned int flags = 0;
+        size_t i;
+
+        for (i = 0; i < virLogNbFilters; i++) {
+            if (strstr(source->name, virLogFilters[i].match)) {
+                priority = virLogFilters[i].priority;
+                flags = virLogFilters[i].flags;
+                break;
+            }
+        }
+
+        source->priority = priority;
+        source->flags = flags;
+        source->serial = virLogFiltersSerial;
+    }
+    virLogUnlock();
+}
+
 /**
  * virLogMessage:
  * @source: where is that message coming from
@@ -805,31 +801,30 @@ virLogVMessage(virLogSourcePtr source,
     char *str = NULL;
     char *msg = NULL;
     char timestamp[VIR_TIME_STRING_BUFLEN];
-    int fprio, ret;
+    int ret;
     size_t i;
     int saved_errno = errno;
-    bool emit = true;
     unsigned int filterflags = 0;
 
     if (virLogInitialize() < 0)
         return;
 
     if (fmt == NULL)
-        goto cleanup;
+        return;
 
     /*
-     * check against list of specific logging patterns
+     * 3 intentionally non-thread safe variable reads.
+     * Since writes to the variable are serialized on
+     * virLogLock, worst case result is a log message
+     * is accidentally dropped or emitted, if another
+     * thread is updating log filter list concurrently
+     * with a log message emission.
      */
-    fprio = virLogFiltersCheck(filename, &filterflags);
-    if (fprio == 0) {
-        if (priority < virLogDefaultPriority)
-            emit = false;
-    } else if (priority < fprio) {
-        emit = false;
-    }
-
-    if (!emit)
+    if (source->serial < virLogFiltersSerial)
+        virLogSourceUpdate(source);
+    if (priority < source->priority)
         goto cleanup;
+    filterflags = source->flags;
 
     /*
      * serialize the error message, add level and timestamp

diff --git a/src/util/virlog.h b/src/util/virlog.h
index 3a4abd141d44b11e19b0632b8b2dbb094c31a5dc..c73867ae749c7f997917244880bae45816d4087b 100644 (file)
--- a/src/util/virlog.h
+++ b/src/util/virlog.h
@@ -49,6 +49,9 @@ typedef virLogSource *virLogSourcePtr;
 
 struct _virLogSource {
     const char *name;
+    unsigned int priority;
+    unsigned int serial;
+    unsigned int flags;
 };
 
 /*
@@ -59,6 +62,9 @@ struct _virLogSource {
 # define VIR_LOG_INIT(n)                                \
     static ATTRIBUTE_UNUSED virLogSource virLogSelf = { \
         .name = "" n "",                                \
+        .priority = VIR_LOG_ERROR,                      \
+        .serial = 0,                                    \
+        .flags = 0,                                     \
     };
 
 /*