Changed log lock from 'quick' to 'basic' because this is an I/O lock.

We cannot use a 'quick' lock (i.e. lock spinning on the CPU) for the log
lock because it can wait a lot on I/Os. Using a 'quick' lock leads to
eating the CPU for no good reason.

Example of 'pidstat' output when using various locks for log_lock:

- 'quick' lock and slow log file system (tail -f on the log file on XFS on RHEL 8)

04:15:11 PM   UID      TGID       TID    %usr %system    %CPU CPU  Command
04:15:21 PM   998     16431         -  100.00    4.20  100.00   2  unbound
04:15:21 PM   998         -     16431   31.00    1.00   32.00   2  |__unbound
04:15:21 PM   998         -     16432   31.30    0.80   32.10   0  |__unbound
04:15:21 PM   998         -     16433   30.20    1.40   31.60   1  |__unbound
04:15:21 PM   998         -     16434   30.70    1.00   31.70   3  |__unbound

- 'quick' lock and log file system being fast

04:15:40 PM   UID      TGID       TID    %usr %system   %CPU CPU  Command
04:15:50 PM   998     16431         -   10.00    1.60  11.60   1  unbound
04:15:50 PM   998         -     16431    2.50    0.50   3.00   1  |__unbound
04:15:50 PM   998         -     16432    2.30    0.40   2.70   3  |__unbound
04:15:50 PM   998         -     16433    2.70    0.30   3.00   0  |__unbound
04:15:50 PM   998         -     16434    2.60    0.40   3.00   2  |__unbound

- 'basic' lock (this commit) and slow log file system (tail -f on the log file on XFS on RHEL 8)

04:29:48 PM   UID      TGID       TID    %usr %system   %CPU CPU  Command
04:29:58 PM   998     11632         -    7.10   14.10  21.20   3  unbound
04:29:58 PM   998         -     11632    1.70    3.20   4.90   3  |__unbound
04:29:58 PM   998         -     11633    1.60    3.30   4.90   1  |__unbound
04:29:58 PM   998         -     11634    2.00    4.10   6.10   1  |__unbound
04:29:58 PM   998         -     11635    1.90    3.50   5.40   1  |__unbound

We can see in the above example, when 'basic' lock is used, that CPU
isn't consumed when log file system is slow.

Another reproducer scenario: put the log file on a NFS share with 'sync'
option.

diff --git a/util/log.c b/util/log.c
index 376a2590b9eab6509cd5b8da8e3d869c11897174..8499d8c0a8a77ea6e573145939306a031ca84a91 100644 (file)
--- a/util/log.c
+++ b/util/log.c
@@ -70,7 +70,7 @@ static int key_created = 0;
 static ub_thread_key_type logkey;
 #ifndef THREADS_DISABLED
 /** pthread mutex to protect FILE* */
-static lock_quick_type log_lock;
+static lock_basic_type log_lock;
 #endif
 /** the identity of this executable/process */
 static const char* ident="unbound";
@@ -88,18 +88,18 @@ log_init(const char* filename, int use_syslog, const char* chrootdir)
        if(!key_created) {
                key_created = 1;
                ub_thread_key_create(&logkey, NULL);
-               lock_quick_init(&log_lock);
+               lock_basic_init(&log_lock);
        }
-       lock_quick_lock(&log_lock);
+       lock_basic_lock(&log_lock);
        if(logfile 
 #if defined(HAVE_SYSLOG_H) || defined(UB_ON_WINDOWS)
        || logging_to_syslog
 #endif
        ) {
-               lock_quick_unlock(&log_lock); /* verbose() needs the lock */
+               lock_basic_unlock(&log_lock); /* verbose() needs the lock */
                verbose(VERB_QUERY, "switching log to %s", 
                        use_syslog?"syslog":(filename&&filename[0]?filename:"stderr"));
-               lock_quick_lock(&log_lock);
+               lock_basic_lock(&log_lock);
        }
        if(logfile && logfile != stderr) {
                FILE* cl = logfile;
@@ -119,7 +119,7 @@ log_init(const char* filename, int use_syslog, const char* chrootdir)
                 * --with-syslog-facility=LOCAL[0-7] can override it */
                openlog(ident, LOG_NDELAY, UB_SYSLOG_FACILITY);
                logging_to_syslog = 1;
-               lock_quick_unlock(&log_lock);
+               lock_basic_unlock(&log_lock);
                return;
        }
 #elif defined(UB_ON_WINDOWS)
@@ -128,13 +128,13 @@ log_init(const char* filename, int use_syslog, const char* chrootdir)
        }
        if(use_syslog) {
                logging_to_syslog = 1;
-               lock_quick_unlock(&log_lock);
+               lock_basic_unlock(&log_lock);
                return;
        }
 #endif /* HAVE_SYSLOG_H */
        if(!filename || !filename[0]) {
                logfile = stderr;
-               lock_quick_unlock(&log_lock);
+               lock_basic_unlock(&log_lock);
                return;
        }
        /* open the file for logging */
@@ -143,7 +143,7 @@ log_init(const char* filename, int use_syslog, const char* chrootdir)
                filename += strlen(chrootdir);
        f = fopen(filename, "a");
        if(!f) {
-               lock_quick_unlock(&log_lock);
+               lock_basic_unlock(&log_lock);
                log_err("Could not open logfile %s: %s", filename, 
                        strerror(errno));
                return;
@@ -153,14 +153,14 @@ log_init(const char* filename, int use_syslog, const char* chrootdir)
        setvbuf(f, NULL, (int)_IOLBF, 0);
 #endif
        logfile = f;
-       lock_quick_unlock(&log_lock);
+       lock_basic_unlock(&log_lock);
 }
 
 void log_file(FILE *f)
 {
-       lock_quick_lock(&log_lock);
+       lock_basic_lock(&log_lock);
        logfile = f;
-       lock_quick_unlock(&log_lock);
+       lock_basic_unlock(&log_lock);
 }
 
 void log_thread_set(int* num)
@@ -245,9 +245,9 @@ log_vmsg(int pri, const char* type,
                return;
        }
 #endif /* HAVE_SYSLOG_H */
-       lock_quick_lock(&log_lock);
+       lock_basic_lock(&log_lock);
        if(!logfile) {
-               lock_quick_unlock(&log_lock);
+               lock_basic_unlock(&log_lock);
                return;
        }
        now = (time_t)time(NULL);
@@ -272,7 +272,7 @@ log_vmsg(int pri, const char* type,
        /* line buffering does not work on windows */
        fflush(logfile);
 #endif
-       lock_quick_unlock(&log_lock);
+       lock_basic_unlock(&log_lock);
 }
 
 /**