Incoherent-slow test

Signed-off-by: Mark Hannum <mhannum72@gmail.com>

bdb/rep.c

@@ -2299,6 +2299,9 @@ static inline int should_copy_seqnum(bdb_state_type *bdb_state, seqnum_type *seq
     return 1;
 }
 
+/* Added for testing- allows us to test slow-replicant-check and inactive-timeout separately */
+int gbl_incoherent_slow_inactive_timeout = 1;
+
 static void got_new_seqnum_from_node(bdb_state_type *bdb_state,
                                      seqnum_type *seqnum, char *host,
                                      struct interned_string *hostinterned,
@@ -2426,8 +2429,8 @@ static void got_new_seqnum_from_node(bdb_state_type *bdb_state,
      * give nodes a chance to dig themselves out if there's no activity (eg: if
      * they went incoherent because of a
      * read spike, but there's nomore reads or writes). */
-    if (change_coherency &&
-        h->coherent_state == STATE_INCOHERENT_SLOW) {
+    if (change_coherency && h->coherent_state == STATE_INCOHERENT_SLOW && gbl_incoherent_slow_inactive_timeout) {
+        int print_message = 0;
         Pthread_mutex_lock(&slow_node_check_lk);
         if ((comdb2_time_epochms() - last_slow_node_check_time) >
                 bdb_state->attr->slowrep_inactive_timeout &&
@@ -2436,9 +2439,14 @@ static void got_new_seqnum_from_node(bdb_state_type *bdb_state,
             if (h->coherent_state == STATE_INCOHERENT_SLOW) {
                 set_coherent_state(bdb_state, hostinterned, STATE_INCOHERENT, __func__,
                                    __LINE__);
+                print_message = 1;
             }
             Pthread_mutex_unlock(&bdb_state->coherent_state_lock);
             last_slow_node_check_time = comdb2_time_epochms();
+            if (print_message) {
+                logmsg(LOGMSG_USER, "Set %s from INCOHERENT_SLOW to INCOHERENT on inactive timeout\n",
+                       hostinterned->str);
+            }
         }
         Pthread_mutex_unlock(&slow_node_check_lk);
     }
@@ -2648,7 +2656,7 @@ static void bdb_slow_replicant_check(bdb_state_type *bdb_state,
     int numnodes;
     struct interned_string *hosts[REPMAX];
     int print_message;
-    int made_incoherent_slow = 0;
+    int made_incoherent_slow = 0, mystate;
 
     numnodes =
         net_get_all_commissioned_nodes_interned(bdb_state->repinfo->netinfo, hosts);
@@ -2706,16 +2714,17 @@ static void bdb_slow_replicant_check(bdb_state_type *bdb_state,
                     h->last_downgrade_time = gettimeofday_ms();
                     made_incoherent_slow = 1;
                 }
+                mystate = h->coherent_state;
             }
         }
         Pthread_mutex_unlock(&(bdb_state->coherent_state_lock));
     }
 
     if (print_message) {
-        logmsg(LOGMSG_USER, "replication time for %s (%.2fms) is much worse than "
-                        "second-worst node %s (%.2fms)\n",
-                worst_node->str, worst_time, second_worst_node->str,
-                second_worst_time);
+        logmsg(LOGMSG_USER,
+               "replication time for %s (%.2fms) is much worse than "
+               "second-worst node %s (%.2fms) state is %s\n",
+               worst_node->str, worst_time, second_worst_node->str, second_worst_time, coherent_state_to_str(mystate));
     }
 
     /* TODO: if we ever disable make_slow_replicants_incoherent and have
@@ -2730,22 +2739,34 @@ static void bdb_slow_replicant_check(bdb_state_type *bdb_state,
             struct interned_string *host = hosts[i];
             struct hostinfo *h = retrieve_hostinfo(host);
             double avg = averager_avg(h->time_minute);
+            int print_stillslow = 0;
             print_message = 0;
 
             Pthread_mutex_lock(&(bdb_state->coherent_state_lock));
-            if (h->coherent_state == STATE_INCOHERENT_SLOW &&
-                (avg < (worst_time * bdb_state->attr->slowrep_incoherent_factor +
-                  bdb_state->attr->slowrep_incoherent_mintime))) {
-                print_message = 1;
-                set_coherent_state(bdb_state, host, STATE_INCOHERENT, __func__,
-                                   __LINE__);
+            if (h->coherent_state == STATE_INCOHERENT_SLOW) {
+                if (avg < (worst_time * bdb_state->attr->slowrep_incoherent_factor +
+                           bdb_state->attr->slowrep_incoherent_mintime)) {
+                    print_message = 1;
+                    set_coherent_state(bdb_state, host, STATE_INCOHERENT, __func__, __LINE__);
+                } else {
+                    print_stillslow = 1;
+                }
             }
             Pthread_mutex_unlock(&(bdb_state->coherent_state_lock));
-            if (print_message)
+            if (print_message) {
                 logmsg(LOGMSG_USER,
                        "replication time for %s (%.2fms) is within "
                        "bounds of second-worst node %s (%.2fms)\n",
                        host->str, avg, worst_node->str, worst_time);
+            }
+            if (print_stillslow) {
+                double window = worst_time * bdb_state->attr->slowrep_incoherent_factor +
+                                bdb_state->attr->slowrep_incoherent_mintime;
+                logmsg(LOGMSG_USER,
+                       "replication time for %s (%.2fms) still slow, greater than %.2fms "
+                       "the required threshold for second-worst node %s (%.2fms)\n",
+                       host->str, avg, window, worst_node->str, worst_time);
+            }
         }
     }
 }

berkdb/rep/rep_record.c

@@ -3743,16 +3743,21 @@ gap_check:		max_lsn_dbtp = NULL;
 
 			do {
 				extern int gbl_slow_rep_process_txn_maxms;
+				extern int gbl_slow_rep_process_txn_minms;
 				extern int gbl_slow_rep_process_txn_freq;
 
 				if (gbl_slow_rep_process_txn_maxms) {
 					if (!gbl_slow_rep_process_txn_freq ||
 						!(rand() %
 						gbl_slow_rep_process_txn_freq))
 					{
-						poll(0, 0,
-							rand() %
-							gbl_slow_rep_process_txn_maxms);
+                        if (gbl_slow_rep_process_txn_maxms <= gbl_slow_rep_process_txn_minms) {
+                            gbl_slow_rep_process_txn_maxms = gbl_slow_rep_process_txn_minms + 1;
+                        }
+                        int range = gbl_slow_rep_process_txn_maxms - gbl_slow_rep_process_txn_minms;
+                        int polltime = gbl_slow_rep_process_txn_minms + (rand() % range);
+                        logmsg(LOGMSG_DEBUG, "%s polling an additional %d ms\n", __func__, polltime);
+						poll(0, 0, polltime);
 					}
 				}
 

db/comdb2.c

@@ -737,6 +737,7 @@ int gbl_lock_get_list_start = 0;
 int gbl_dump_locks_on_repwait = 0;
 
 int gbl_slow_rep_process_txn_maxms = 0;
+int gbl_slow_rep_process_txn_minms = 0;
 int gbl_slow_rep_process_txn_freq = 0;
 int gbl_check_page_in_recovery = 0;
 int gbl_cmptxn_inherit_locks = 1;

db/db_tunables.c

@@ -111,6 +111,7 @@ extern int gbl_return_long_column_names;
 extern int gbl_round_robin_stripes;
 extern int skip_clear_queue_extents;
 extern int gbl_slow_rep_process_txn_freq;
+extern int gbl_slow_rep_process_txn_minms;
 extern int gbl_slow_rep_process_txn_maxms;
 extern int gbl_sqlite_sorter_mem;
 extern int gbl_sqlite_use_temptable_for_rowset;
@@ -196,6 +197,7 @@ extern int gbl_verbose_fills;
 extern int gbl_getlock_latencyms;
 extern int gbl_last_locked_seqnum;
 extern int gbl_set_coherent_state_trace;
+extern int gbl_incoherent_slow_inactive_timeout;
 extern int gbl_force_incoherent;
 extern int gbl_ignore_coherency;
 extern int gbl_skip_catchup_logic;

db/db_tunables.h

@@ -1094,8 +1094,9 @@ REGISTER_TUNABLE("slow_rep_process_txn_freq", NULL, TUNABLE_INTEGER,
 REGISTER_TUNABLE("slow_rep_process_txn_maxms", NULL, TUNABLE_INTEGER,
                  &gbl_slow_rep_process_txn_maxms, READONLY, NULL, NULL, NULL,
                  NULL);
-REGISTER_TUNABLE("slowwrite", NULL, TUNABLE_INTEGER, &__slow_write_ns, READONLY,
-                 NULL, NULL, NULL, NULL);
+REGISTER_TUNABLE("slow_rep_process_txn_minms", NULL, TUNABLE_INTEGER, &gbl_slow_rep_process_txn_minms, READONLY, NULL,
+                 NULL, NULL, NULL);
+REGISTER_TUNABLE("slowwrite", NULL, TUNABLE_INTEGER, &__slow_write_ns, READONLY, NULL, NULL, NULL, NULL);
 REGISTER_TUNABLE("sort_nulls_with_header",
                  "Using record headers in key sorting. (Default: on)",
                  TUNABLE_BOOLEAN, &gbl_sort_nulls_correctly, READONLY | NOARG,
@@ -1594,14 +1595,12 @@ REGISTER_TUNABLE("commit_delay_trace", "Verbose commit-delays.  (Default: off)",
 REGISTER_TUNABLE("commit_lsn_map", "Maintain a map of transaction commit LSNs. (Default: on)",
                  TUNABLE_BOOLEAN, &gbl_commit_lsn_map,
                  NOARG, NULL, NULL, NULL, NULL);
-REGISTER_TUNABLE("set_coherent_state_trace",
-                 "Verbose coherency trace.  (Default: off)", TUNABLE_BOOLEAN,
-                 &gbl_set_coherent_state_trace, EXPERIMENTAL | INTERNAL, NULL,
-                 NULL, NULL, NULL);
-REGISTER_TUNABLE("finish_fill_threshold",
-                 "Fill to end if end is less than this.  (Default: 60000000)",
-                 TUNABLE_INTEGER, &gbl_finish_fill_threshold,
-                 EXPERIMENTAL | INTERNAL, NULL, NULL, NULL, NULL);
+REGISTER_TUNABLE("incoherent_slow_inactive_timeout", "Periodically reset slow-nodes to incoherent.  (Default: on)",
+                 TUNABLE_BOOLEAN, &gbl_incoherent_slow_inactive_timeout, 0, NULL, NULL, NULL, NULL);
+REGISTER_TUNABLE("set_coherent_state_trace", "Verbose coherency trace.  (Default: off)", TUNABLE_BOOLEAN,
+                 &gbl_set_coherent_state_trace, EXPERIMENTAL | INTERNAL, NULL, NULL, NULL, NULL);
+REGISTER_TUNABLE("finish_fill_threshold", "Fill to end if end is less than this.  (Default: 60000000)", TUNABLE_INTEGER,
+                 &gbl_finish_fill_threshold, EXPERIMENTAL | INTERNAL, NULL, NULL, NULL, NULL);
 REGISTER_TUNABLE("req_delay_count_threshold",
                  "Request commit-delay if falling "
                  "behind this many times.  (Default: 5)",

db/process_message.c

@@ -3550,6 +3550,17 @@ int process_command(struct dbenv *dbenv, char *line, int lline, int st)
                 gbl_slow_rep_process_txn_maxms);
     }
 
+    else if (tokcmp(tok, ltok, "slow_rep_process_txn_minms") == 0) {
+        extern int gbl_slow_rep_process_txn_minms;
+        tok = segtok(line, lline, &st, &ltok);
+        if (ltok == 0) {
+            logmsg(LOGMSG_ERROR, "Expected value for slow_rep_process_txn_minms\n");
+            return 0;
+        }
+        gbl_slow_rep_process_txn_minms = toknum(tok, ltok);
+        logmsg(LOGMSG_USER, "slow_rep_process_txn_minms set to %d ms\n", gbl_slow_rep_process_txn_minms);
+    }
+
     else if (tokcmp(tok, ltok, "slow_rep_process_txn_freq") == 0) {
         extern int gbl_slow_rep_process_txn_freq;
         tok = segtok(line, lline, &st, &ltok);

tests/incoherent_slow.test/Makefile

@@ -0,0 +1,8 @@
+ifeq ($(TESTSROOTDIR),)
+  include ../testcase.mk
+else
+  include $(TESTSROOTDIR)/testcase.mk
+endif
+ifeq ($(TEST_TIMEOUT),)
+	export TEST_TIMEOUT=10m
+endif

tests/incoherent_slow.test/README

@@ -0,0 +1 @@
+Verify that the paths into and out-of incoherent-slow state operate correctly

tests/incoherent_slow.test/lrl.options

@@ -0,0 +1,9 @@
+make_slow_replicants_incoherent 1
+
+logmsg level debug
+
+allow_readonly_runtime_mod 1
+
+set_coherent_state_trace 1
+
+slowrep_incoherent_factor 50