upstream/unbound
1
0
Fork 0
mirror of https://github.com/NLnetLabs/unbound.git synced 2025-12-27 18:20:02 -05:00
Code Issues Projects Releases Packages Wiki Activity Actions

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

Browse source 
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.
This commit is contained in:
Renaud Métrich 2019-11-26 16:32:03 +01:00
parent f82f971997
commit d63cb99649
1 changed files with 15 additions and 15 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

30
util/log.c
View file

@ -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);
}
/**