From d905fd132a536e9149c91816704500c659e154f0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Renaud=20M=C3=A9trich?= 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