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