Trace rwlocks of netdata (#12785)

* with -DNETDATA_INTERNAL_CHECKS=1 enable rwlocks tracing

* fix strings alignment on terminal

* remove wrong addition

* removed formating warning; now counting active locks per thread; tracing is enabled with -DNETDATA_TRACE_RWLOCKS=1

* added the missing netdata_mutex_destroy()

* optimized clocks usage in locks

* added also main

* fixed formatting warning

* add compiler warning when compiling with -DNETDATA_TRACE_RWLOCKS=1

* cleanup and documentation

* fix for old variable

* >= not just > to allow proper comparisons

* dont print 0x twice and print the lock pointer on every line

* trace locks deeper

daemon/main.c

@@ -1087,8 +1087,9 @@ int main(int argc, char **argv) {
         if(i > 0)
             mallopt(M_ARENA_MAX, 1);
 #endif
-        test_clock_boottime();
-        test_clock_monotonic_coarse();
+
+        // initialize the system clocks
+        clocks_init();
 
         // prepare configuration environment variables for the plugins
 

libnetdata/avl/avl.c

@@ -372,9 +372,9 @@ void avl_destroy_lock(avl_tree_lock *tree) {
     int lock;
 
 #ifdef AVL_LOCK_WITH_MUTEX
-    lock = pthread_mutex_destroy(&tree->mutex);
+    lock = netdata_mutex_destroy(&tree->mutex);
 #else
-    lock = pthread_rwlock_destroy(&tree->rwlock);
+    lock = netdata_rwlock_destroy(&tree->rwlock);
 #endif
 
     if(lock != 0)

libnetdata/clocks/clocks.c

@@ -2,8 +2,10 @@
 
 #include "../libnetdata.h"
 
-static int clock_boottime_valid = 1;
-static int clock_monotonic_coarse_valid = 1;
+// defaults are for compatibility
+// call clocks_init() once, to optimize these default settings
+static clockid_t clock_boottime_to_use = CLOCK_MONOTONIC;
+static clockid_t clock_monotonic_to_use = CLOCK_MONOTONIC;
 
 #ifndef HAVE_CLOCK_GETTIME
 inline int clock_gettime(clockid_t clk_id, struct timespec *ts) {
@@ -18,19 +20,39 @@ inline int clock_gettime(clockid_t clk_id, struct timespec *ts) {
 }
 #endif
 
-void test_clock_boottime(void) {
+// When running a binary with CLOCK_MONOTONIC_COARSE defined on a system with a linux kernel older than Linux 2.6.32 the
+// clock_gettime(2) system call fails with EINVAL. In that case it must fall-back to CLOCK_MONOTONIC.
+
+static void test_clock_monotonic_coarse(void) {
     struct timespec ts;
-    if(clock_gettime(CLOCK_BOOTTIME, &ts) == -1 && errno == EINVAL)
-        clock_boottime_valid = 0;
+    if(clock_gettime(CLOCK_MONOTONIC_COARSE, &ts) == -1 && errno == EINVAL)
+        clock_monotonic_to_use = CLOCK_MONOTONIC;
+    else
+        clock_monotonic_to_use = CLOCK_MONOTONIC_COARSE;
 }
 
-void test_clock_monotonic_coarse(void) {
+// When running a binary with CLOCK_BOOTTIME defined on a system with a linux kernel older than Linux 2.6.39 the
+// clock_gettime(2) system call fails with EINVAL. In that case it must fall-back to CLOCK_MONOTONIC.
+
+static void test_clock_boottime(void) {
     struct timespec ts;
-    if(clock_gettime(CLOCK_MONOTONIC_COARSE, &ts) == -1 && errno == EINVAL)
-        clock_monotonic_coarse_valid = 0;
+    if(clock_gettime(CLOCK_BOOTTIME, &ts) == -1 && errno == EINVAL)
+        clock_boottime_to_use = clock_monotonic_to_use;
+    else
+        clock_boottime_to_use = CLOCK_BOOTTIME;
+}
+
+// perform any initializations required for clocks
+
+void clocks_init(void) {
+    // monotonic coarse has to be tested before boottime
+    test_clock_monotonic_coarse();
+
+    // boottime has to be tested after monotonic coarse
+    test_clock_boottime();
 }
 
-static inline time_t now_sec(clockid_t clk_id) {
+inline time_t now_sec(clockid_t clk_id) {
     struct timespec ts;
     if(unlikely(clock_gettime(clk_id, &ts) == -1)) {
         error("clock_gettime(%d, &timespec) failed.", clk_id);
@@ -39,7 +61,7 @@ static inline time_t now_sec(clockid_t clk_id) {
     return ts.tv_sec;
 }
 
-static inline usec_t now_usec(clockid_t clk_id) {
+inline usec_t now_usec(clockid_t clk_id) {
     struct timespec ts;
     if(unlikely(clock_gettime(clk_id, &ts) == -1)) {
         error("clock_gettime(%d, &timespec) failed.", clk_id);
@@ -48,7 +70,7 @@ static inline usec_t now_usec(clockid_t clk_id) {
     return (usec_t)ts.tv_sec * USEC_PER_SEC + (ts.tv_nsec % NSEC_PER_SEC) / NSEC_PER_USEC;
 }
 
-static inline int now_timeval(clockid_t clk_id, struct timeval *tv) {
+inline int now_timeval(clockid_t clk_id, struct timeval *tv) {
     struct timespec ts;
 
     if(unlikely(clock_gettime(clk_id, &ts) == -1)) {
@@ -76,15 +98,15 @@ inline int now_realtime_timeval(struct timeval *tv) {
 }
 
 inline time_t now_monotonic_sec(void) {
-    return now_sec(likely(clock_monotonic_coarse_valid) ? CLOCK_MONOTONIC_COARSE : CLOCK_MONOTONIC);
+    return now_sec(clock_monotonic_to_use);
 }
 
 inline usec_t now_monotonic_usec(void) {
-    return now_usec(likely(clock_monotonic_coarse_valid) ? CLOCK_MONOTONIC_COARSE : CLOCK_MONOTONIC);
+    return now_usec(clock_monotonic_to_use);
 }
 
 inline int now_monotonic_timeval(struct timeval *tv) {
-    return now_timeval(likely(clock_monotonic_coarse_valid) ? CLOCK_MONOTONIC_COARSE : CLOCK_MONOTONIC, tv);
+    return now_timeval(clock_monotonic_to_use, tv);
 }
 
 inline time_t now_monotonic_high_precision_sec(void) {
@@ -100,19 +122,15 @@ inline int now_monotonic_high_precision_timeval(struct timeval *tv) {
 }
 
 inline time_t now_boottime_sec(void) {
-    return now_sec(likely(clock_boottime_valid) ? CLOCK_BOOTTIME :
-                   likely(clock_monotonic_coarse_valid) ? CLOCK_MONOTONIC_COARSE : CLOCK_MONOTONIC);
+    return now_sec(clock_boottime_to_use);
 }
 
 inline usec_t now_boottime_usec(void) {
-    return now_usec(likely(clock_boottime_valid) ? CLOCK_BOOTTIME :
-                    likely(clock_monotonic_coarse_valid) ? CLOCK_MONOTONIC_COARSE : CLOCK_MONOTONIC);
+    return now_usec(clock_boottime_to_use);
 }
 
 inline int now_boottime_timeval(struct timeval *tv) {
-    return now_timeval(likely(clock_boottime_valid) ? CLOCK_BOOTTIME :
-                       likely(clock_monotonic_coarse_valid) ? CLOCK_MONOTONIC_COARSE : CLOCK_MONOTONIC,
-                       tv);
+    return now_timeval(clock_boottime_to_use, tv);
 }
 
 inline usec_t timeval_usec(struct timeval *tv) {
@@ -137,8 +155,7 @@ inline usec_t dt_usec(struct timeval *now, struct timeval *old) {
     return (ts1 > ts2) ? (ts1 - ts2) : (ts2 - ts1);
 }
 
-inline void heartbeat_init(heartbeat_t *hb)
-{
+inline void heartbeat_init(heartbeat_t *hb) {
     hb->monotonic = hb->realtime = 0ULL;
 }
 

libnetdata/clocks/clocks.h

@@ -133,7 +133,6 @@ extern int now_boottime_timeval(struct timeval *tv);
 extern time_t now_boottime_sec(void);
 extern usec_t now_boottime_usec(void);
 
-
 extern usec_t timeval_usec(struct timeval *tv);
 extern msec_t timeval_msec(struct timeval *tv);
 
@@ -152,17 +151,12 @@ extern usec_t heartbeat_monotonic_dt_to_now_usec(heartbeat_t *hb);
 
 extern int sleep_usec(usec_t usec);
 
-/*
- * When running a binary with CLOCK_BOOTTIME defined on a system with a linux kernel older than Linux 2.6.39 the
- * clock_gettime(2) system call fails with EINVAL. In that case it must fall-back to CLOCK_MONOTONIC.
- */
-void test_clock_boottime(void);
+extern void clocks_init(void);
 
-/*
- * When running a binary with CLOCK_MONOTONIC_COARSE defined on a system with a linux kernel older than Linux 2.6.32 the
- * clock_gettime(2) system call fails with EINVAL. In that case it must fall-back to CLOCK_MONOTONIC.
- */
-void test_clock_monotonic_coarse(void);
+// lower level functions - avoid using directly
+extern time_t now_sec(clockid_t clk_id);
+extern usec_t now_usec(clockid_t clk_id);
+extern int now_timeval(clockid_t clk_id, struct timeval *tv);
 
 extern collected_number uptime_msec(char *filename);
 

libnetdata/locks/README.md

@@ -2,4 +2,99 @@
 custom_edit_url: https://github.com/netdata/netdata/edit/master/libnetdata/locks/README.md
 -->
 
+## How to trace netdata locks
+
+To enable tracing rwlocks in netdata, compile netdata by setting `CFLAGS="-DNETDATA_TRACE_RWLOCKS=1"`, like this:
+
+```
+CFLAGS="-O1 -ggdb -DNETDATA_TRACE_RWLOCKS=1"  ./netdata-installer.sh
+```
+
+During compilation, the compiler will log:
+
+```
+libnetdata/locks/locks.c:105:2: warning: #warning NETDATA_TRACE_RWLOCKS ENABLED - EXPECT A LOT OF OUTPUT [-Wcpp]
+  105 | #warning NETDATA_TRACE_RWLOCKS ENABLED - EXPECT A LOT OF OUTPUT
+      |  ^~~~~~~
+```
+
+Once compiled, netdata will do the following:
+
+Every call to `netdata_rwlock_*()` is now measured in time.
+
+### logging of slow locks/unlocks
+
+If any call takes more than 10 usec, it will be logged like this:
+
+```
+RW_LOCK ON LOCK 0x0x7fbe1f2e5190: 4157038, 'ACLK_Query_2' (function build_context_param_list() 99@web/api/formatters/rrd2json.c) WAITED to UNLOCK for 29 usec.
+```
+
+The time can be changed by setting this `-DNETDATA_TRACE_RWLOCKS_WAIT_TIME_TO_IGNORE_USEC=20` (or whatever number) to the CFLAGS.
+
+### logging of long hold times
+
+If any lock is holded for more than 10000 usec, it will be logged like this:
+
+```
+RW_LOCK ON LOCK 0x0x55a20afc1b20: 4187198, 'ANALYTICS' (function analytics_gather_mutable_meta_data() 532@daemon/analytics.c) holded a 'R' for 13232 usec.
+```
+
+The time can be changed by setting this `-DNETDATA_TRACE_RWLOCKS_HOLD_TIME_TO_IGNORE_USEC=20000` (or whatever number) to the CFLAGS.
+
+### logging for probable pauses (predictive)
+
+The library maintains a linked-list of all the lock holders (one entry per thread).  For this linked-list a mutex is used. So every call to the r/w locks now also has  a mutex lock.
+
+If any call is expected to pause the caller (ie the caller is attempting a read lock while there is a write lock in place and vice versa), the library will log something like this:
+
+```
+RW_LOCK ON LOCK 0x0x5651c9fcce20: 4190039 'HEALTH' (function init_pending_foreach_alarms() 661@health/health.c) WANTS a 'W' lock (while holding 1 rwlocks and 1 mutexes).
+There are 7 readers and 0 writers are holding the lock:
+     => 1: RW_LOCK: process 4190091 'WEB_SERVER[static14]' (function web_client_api_request_v1_data() 526@web/api/web_api_v1.c) is having 1 'R' lock for 709847 usec.
+     => 2: RW_LOCK: process 4190079 'WEB_SERVER[static6]' (function web_client_api_request_v1_data() 526@web/api/web_api_v1.c) is having 1 'R' lock for 709869 usec.
+     => 3: RW_LOCK: process 4190084 'WEB_SERVER[static10]' (function web_client_api_request_v1_data() 526@web/api/web_api_v1.c) is having 1 'R' lock for 709948 usec.
+     => 4: RW_LOCK: process 4190076 'WEB_SERVER[static3]' (function web_client_api_request_v1_data() 526@web/api/web_api_v1.c) is having 1 'R' lock for 710190 usec.
+     => 5: RW_LOCK: process 4190092 'WEB_SERVER[static15]' (function web_client_api_request_v1_data() 526@web/api/web_api_v1.c) is having 1 'R' lock for 710195 usec.
+     => 6: RW_LOCK: process 4190077 'WEB_SERVER[static4]' (function web_client_api_request_v1_data() 526@web/api/web_api_v1.c) is having 1 'R' lock for 710208 usec.
+     => 7: RW_LOCK: process 4190044 'WEB_SERVER[static1]' (function web_client_api_request_v1_data() 526@web/api/web_api_v1.c) is having 1 'R' lock for 710221 usec.
+```
+
+And each of the above is paired with a `GOT` log, like this:
+
+```
+RW_LOCK ON LOCK 0x0x5651c9fcce20: 4190039 'HEALTH' (function init_pending_foreach_alarms() 661@health/health.c) GOT a 'W' lock (while holding 2 rwlocks and 1 mutexes).
+There are 0 readers and 1 writers are holding the lock:
+     => 1: RW_LOCK: process 4190039 'HEALTH' (function init_pending_foreach_alarms() 661@health/health.c) is having 1 'W' lock for 36 usec.
+```
+
+Keep in mind that the lock and log are not atomic. The list of callers is indicative (and sometimes just empty because the original holders of the lock, unlocked it until we had the chance to print their names).
+
+### POSIX compliance check
+
+The library may also log messages about POSIX unsupported cases, like this:
+
+```
+RW_LOCK FATAL ON LOCK 0x0x622000109290: 3609368 'PLUGIN[proc]' (function __rrdset_check_rdlock() 10@database/rrdset.c) attempts to acquire a 'W' lock.
+But it is not supported by POSIX because: ALREADY HAS THIS LOCK
+At this attempt, the task is holding 1 rwlocks and 1 mutexes.
+There are 1 readers and 0 writers are holding the lock requested now:
+     => 1: RW_LOCK: process 3609368 'PLUGIN[proc]' (function rrdset_done() 1398@database/rrdset.c) is having 1 'R' lock for 0 usec.
+```
+
+### nested read locks
+
+When compiled with `-DNETDATA_TRACE_RWLOCKS_LOG_NESTED=1` the library will also detect nested read locks and print them like this:
+
+```
+RW_LOCK ON LOCK 0x0x7ff6ea46d190: 4140225 'WEB_SERVER[static14]' (function rrdr_json_wrapper_begin() 34@web/api/formatters/json_wrapper.c) NESTED READ LOCK REQUEST a 'R' lock (while holding 1 rwlocks and 1 mutexes).
+There are 5 readers and 0 writers are holding the lock:
+   => 1: RW_LOCK: process 4140225 'WEB_SERVER[static14]' (function rrdr_lock_rrdset() 70@web/api/queries/rrdr.c) is having 1 'R' lock for 216667 usec.
+   => 2: RW_LOCK: process 4140211 'WEB_SERVER[static6]' (function rrdr_lock_rrdset() 70@web/api/queries/rrdr.c) is having 1 'R' lock for 220001 usec.
+   => 3: RW_LOCK: process 4140218 'WEB_SERVER[static8]' (function rrdr_lock_rrdset() 70@web/api/queries/rrdr.c) is having 1 'R' lock for 220001 usec.
+   => 4: RW_LOCK: process 4140224 'WEB_SERVER[static13]' (function rrdr_lock_rrdset() 70@web/api/queries/rrdr.c) is having 1 'R' lock for 220001 usec.
+   => 5: RW_LOCK: process 4140227 'WEB_SERVER[static16]' (function rrdr_lock_rrdset() 70@web/api/queries/rrdr.c) is having 1 'R' lock for 220001 usec.
+```
+
+