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