Blob Blame Raw
From d905fd132a536e9149c91816704500c659e154f0 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Renaud=20M=C3=A9trich?= <rmetrich@redhat.com>
Date: Tue, 26 Nov 2019 16:32:03 +0100
Subject: [PATCH] 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.
---
 util/log.c | 30 +++++++++++++++---------------
 1 file changed, 15 insertions(+), 15 deletions(-)

diff --git a/util/log.c b/util/log.c
index c14b458..5b31854 100644
--- 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";
@@ -90,18 +90,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)
 		 * chroot and no longer be able to access dev/log and so on */
 		openlog(ident, LOG_NDELAY, LOG_DAEMON);
 		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)
@@ -239,9 +239,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;
 	}
 	if(log_now)
@@ -268,7 +268,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);
 }
 
 /**
-- 
2.21.0