mdbx-test: rework progess inticator.

Change-Id: Iaf3f7823ab7a0fe9f00607eb803390669c37005f

test/chrono.h

@@ -15,7 +15,6 @@
 #pragma once
 
 #include "base.h"
-#include "log.h"
 #include "utils.h"
 
 namespace chrono {

test/config.cc

@@ -427,6 +427,8 @@ void dump(const char *title) {
   log_verbose("failfast: %s\n", global::config::failfast ? "Yes" : "No");
   log_verbose("progress indicator: %s\n",
               global::config::progress_indicator ? "Yes" : "No");
+  log_verbose("console mode: %s\n",
+              global::config::console_mode ? "Yes" : "No");
 }
 
 } /* namespace config */
@@ -454,26 +456,31 @@ const std::string actor_config::serialize(const char *prefix) const {
 
   checksum.push(params.pathname_db);
   result.append(params.pathname_db);
-  result.append("|");
+  result.push_back('|');
 
   checksum.push(params.pathname_log);
   result.append(params.pathname_log);
-  result.append("|");
+  result.push_back('|');
 
   static_assert(std::is_pod<actor_params_pod>::value,
                 "actor_params_pod should by POD");
   result.append(data2hex(static_cast<const actor_params_pod *>(&params),
                          sizeof(actor_params_pod), checksum));
-  result.append("|");
+  result.push_back('|');
 
   static_assert(std::is_pod<actor_config_pod>::value,
                 "actor_config_pod should by POD");
   result.append(data2hex(static_cast<const actor_config_pod *>(this),
                          sizeof(actor_config_pod), checksum));
-  result.append("|");
+  result.push_back('|');
+  result.push_back(global::config::progress_indicator ? 'Y' : 'N');
+  checksum.push(global::config::progress_indicator);
+  result.push_back(global::config::console_mode ? 'Y' : 'N');
+  checksum.push(global::config::console_mode);
+  result.push_back('|');
 
   result.append(osal_serialize(checksum));
-  result.append("|");
+  result.push_back('|');
 
   result.append(std::to_string(checksum.value));
   return result;
@@ -537,6 +544,20 @@ bool actor_config::deserialize(const char *str, actor_config &config) {
     TRACE("<< actor_config::deserialize: slash-5\n");
     return false;
   }
+  if ((str[0] == 'Y' || str[0] == 'N') && (str[1] == 'Y' || str[1] == 'N')) {
+    global::config::progress_indicator = str[0] == 'Y';
+    checksum.push(global::config::progress_indicator);
+    global::config::console_mode = str[1] == 'Y';
+    checksum.push(global::config::console_mode);
+    str = slash + 1;
+
+    slash = strchr(str, '|');
+    if (!slash) {
+      TRACE("<< actor_config::deserialize: slash-6\n");
+      return false;
+    }
+  }
+
   if (!config.osal_deserialize(str, slash, checksum)) {
     TRACE("<< actor_config::deserialize: osal\n");
     return false;

test/log.cc

@@ -241,6 +241,56 @@ void local_suffix::pop() {
 
 local_suffix::~local_suffix() { suffix.erase(trim_pos); }
 
+void progress_canary(bool active) {
+  static chrono::time progress_timestamp;
+  chrono::time now = chrono::now_motonic();
+
+  if (now.fixedpoint - progress_timestamp.fixedpoint <
+      chrono::from_ms(42).fixedpoint)
+    return;
+
+  if (osal_progress_push(active)) {
+    progress_timestamp = now;
+    return;
+  }
+
+  if (progress_timestamp.fixedpoint == 0) {
+    putc('>', stderr);
+    progress_timestamp = now;
+  } else if (global::config::console_mode) {
+    if (active) {
+      static int last_point = -1;
+      int point = (now.fixedpoint >> 29) & 3;
+      if (point != last_point) {
+        progress_timestamp = now;
+        fprintf(stderr, "%c\b", "-\\|/"[last_point = point]);
+      }
+    } else if (now.fixedpoint - progress_timestamp.fixedpoint >
+               chrono::from_seconds(2).fixedpoint) {
+      progress_timestamp = now;
+      fprintf(stderr, "%c\b", "@*"[now.utc & 1]);
+    }
+  } else {
+    static int count;
+    if (active && now.fixedpoint - progress_timestamp.fixedpoint >
+                      chrono::from_seconds(1).fixedpoint) {
+      putc('.', stderr);
+      progress_timestamp = now;
+      ++count;
+    } else if (now.fixedpoint - progress_timestamp.fixedpoint >
+               chrono::from_seconds(5).fixedpoint) {
+      putc("@*"[now.utc & 1], stderr);
+      progress_timestamp = now;
+      ++count;
+    }
+    if (count == 60) {
+      count = 0;
+      putc('\n', stderr);
+    }
+  }
+  fflush(stderr);
+}
+
 } // namespace logging
 
 void log_extra(const char *msg, ...) {

test/log.h

@@ -15,6 +15,7 @@
 #pragma once
 
 #include "base.h"
+#include "chrono.h"
 
 void __noreturn usage(void);
 void __noreturn __printf_args(1, 2) failure(const char *fmt, ...);
@@ -54,6 +55,8 @@ bool __printf_args(2, 3)
 bool feed_ap(const char *format, va_list ap);
 bool __printf_args(1, 2) feed(const char *format, ...);
 
+void progress_canary(bool active);
+
 class local_suffix {
 protected:
   size_t trim_pos;

test/main.cc

@@ -82,7 +82,8 @@ void actor_params::set_defaults(const std::string &tmpdir) {
   global::config::cleanup_before = true;
   global::config::cleanup_after = true;
   global::config::failfast = true;
-  global::config::progress_indicator = osal_istty(STDERR_FILENO);
+  global::config::progress_indicator = true;
+  global::config::console_mode = osal_istty(STDERR_FILENO);
 }
 
 namespace global {
@@ -103,6 +104,7 @@ bool cleanup_before;
 bool cleanup_after;
 bool failfast;
 bool progress_indicator;
+bool console_mode;
 } /* namespace config */
 
 } /* namespace global */
@@ -364,6 +366,9 @@ int main(int argc, char *const argv[]) {
     if (config::parse_option(argc, argv, narg, "progress",
                              global::config::progress_indicator))
       continue;
+    if (config::parse_option(argc, argv, narg, "console",
+                             global::config::console_mode))
+      continue;
 
     if (*argv[narg] != '-')
       testcase_setup(argv[narg], params, last_space_id);

test/osal-unix.cc

@@ -149,21 +149,64 @@ bool actor_config::osal_deserialize(const char *str, const char *end,
 
 //-----------------------------------------------------------------------------
 
+static pid_t overlord_pid;
+
+static volatile sig_atomic_t sigusr1_head, sigusr2_head;
+static void handler_SIGUSR(int signum) {
+  switch (signum) {
+  case SIGUSR1:
+    sigusr1_head += 1;
+    return;
+  case SIGUSR2:
+    sigusr2_head += 1;
+    return;
+  default:
+    abort();
+  }
+}
+
+bool osal_progress_push(bool active) {
+  if (overlord_pid) {
+    if (kill(overlord_pid, active ? SIGUSR1 : SIGUSR2))
+      failure_perror("osal_progress_push: kill(overload)", errno);
+    return true;
+  }
+
+  return false;
+}
+
+//-----------------------------------------------------------------------------
+
 static std::unordered_map<pid_t, actor_status> childs;
 
-static void handler_SIGCHLD(int unused) { (void)unused; }
+static void handler_SIGCHLD(int signum) { (void)signum; }
 
 mdbx_pid_t osal_getpid(void) { return getpid(); }
 
 int osal_delay(unsigned seconds) { return sleep(seconds) ? errno : 0; }
 
 int osal_actor_start(const actor_config &config, mdbx_pid_t &pid) {
-  if (childs.empty())
+  if (childs.empty()) {
-    signal(SIGCHLD, handler_SIGCHLD);
+    struct sigaction act;
+    memset(&act, 0, sizeof(act));
+    act.sa_handler = handler_SIGCHLD;
+    sigaction(SIGCHLD, &act, nullptr);
+    act.sa_handler = handler_SIGUSR;
+    sigaction(SIGUSR1, &act, nullptr);
+    sigaction(SIGUSR2, &act, nullptr);
+
+    sigset_t mask;
+    sigemptyset(&mask);
+    sigaddset(&mask, SIGCHLD);
+    sigaddset(&mask, SIGUSR1);
+    sigaddset(&mask, SIGUSR2);
+    sigprocmask(SIG_UNBLOCK, &mask, nullptr);
+  }
 
   pid = fork();
 
   if (pid == 0) {
+    overlord_pid = getppid();
     const bool result = test_execute(config);
     exit(result ? EXIT_SUCCESS : EXIT_FAILURE);
   }
@@ -217,6 +260,16 @@ retry:
     return 0;
   }
 
+  static sig_atomic_t sigusr1_tail, sigusr2_tail;
+  if (sigusr1_tail != sigusr1_head) {
+    sigusr1_tail = sigusr1_head;
+    logging::progress_canary(true);
+  }
+  if (sigusr2_tail != sigusr2_head) {
+    sigusr2_tail = sigusr2_head;
+    logging::progress_canary(false);
+  }
+
   if (pid == 0) {
     /* child still running */
     if (ts.tv_sec == 0 && ts.tv_nsec == 0)

test/osal-windows.cc

@@ -16,6 +16,7 @@
 
 static std::unordered_map<unsigned, HANDLE> events;
 static HANDLE hBarrierSemaphore, hBarrierEvent;
+static HANDLE hProgressActiveEvent, hProgressPassiveEvent;
 
 static int waitstatus2errcode(DWORD result) {
   switch (result) {
@@ -85,6 +86,16 @@ void osal_setup(const std::vector<actor_config> &actors) {
   if (!hBarrierEvent)
     failure_perror("CreateEvent(BarrierEvent)", GetLastError());
   hBarrierEvent = make_inheritable(hBarrierEvent);
+
+  hProgressActiveEvent = CreateEvent(NULL, FALSE, FALSE, NULL);
+  if (!hProgressActiveEvent)
+    failure_perror("CreateEvent(ProgressActiveEvent)", GetLastError());
+  hProgressActiveEvent = make_inheritable(hProgressActiveEvent);
+
+  hProgressPassiveEvent = CreateEvent(NULL, FALSE, FALSE, NULL);
+  if (!hProgressPassiveEvent)
+    failure_perror("CreateEvent(ProgressPassiveEvent)", GetLastError());
+  hProgressPassiveEvent = make_inheritable(hProgressPassiveEvent);
 }
 
 void osal_broadcast(unsigned id) {
@@ -112,6 +123,8 @@ const std::string
 actor_config::osal_serialize(simple_checksum &checksum) const {
   checksum.push(hBarrierSemaphore);
   checksum.push(hBarrierEvent);
+  checksum.push(hProgressActiveEvent);
+  checksum.push(hProgressPassiveEvent);
 
   HANDLE hWait = INVALID_HANDLE_VALUE;
   if (wait4id) {
@@ -125,8 +138,8 @@ actor_config::osal_serialize(simple_checksum &checksum) const {
     checksum.push(hSignal);
   }
 
-  return format("%p.%p.%p.%p", hBarrierSemaphore, hBarrierEvent, hWait,
+  return format("%p.%p.%p.%p.%p.%p", hBarrierSemaphore, hBarrierEvent, hWait,
-                hSignal);
+                hSignal, hProgressActiveEvent, hProgressPassiveEvent);
 }
 
 bool actor_config::osal_deserialize(const char *str, const char *end,
@@ -137,17 +150,22 @@ bool actor_config::osal_deserialize(const char *str, const char *end,
 
   assert(hBarrierSemaphore == 0);
   assert(hBarrierEvent == 0);
+  assert(hProgressActiveEvent == 0);
+  assert(hProgressPassiveEvent == 0);
   assert(events.empty());
 
   HANDLE hWait, hSignal;
-  if (sscanf_s(copy.c_str(), "%p.%p.%p.%p", &hBarrierSemaphore, &hBarrierEvent,
+  if (sscanf_s(copy.c_str(), "%p.%p.%p.%p.%p.%p", &hBarrierSemaphore,
-               &hWait, &hSignal) != 4) {
+               &hBarrierEvent, &hWait, &hSignal, &hProgressActiveEvent,
+               &hProgressPassiveEvent) != 6) {
     TRACE("<< osal_deserialize: failed\n");
     return false;
   }
 
   checksum.push(hBarrierSemaphore);
   checksum.push(hBarrierEvent);
+  checksum.push(hProgressActiveEvent);
+  checksum.push(hProgressPassiveEvent);
 
   if (wait4id) {
     checksum.push(hWait);
@@ -168,6 +186,17 @@ bool actor_config::osal_deserialize(const char *str, const char *end,
 typedef std::pair<HANDLE, actor_status> child;
 static std::unordered_map<mdbx_pid_t, child> childs;
 
+bool osal_progress_push(bool active) {
+  if (childs.empty()) {
+    if (!SetEvent(active ? hProgressActiveEvent : hProgressPassiveEvent))
+      failure_perror("osal_progress_push: SetEvent(overlord.progress)",
+                     GetLastError());
+    return true;
+  }
+
+  return false;
+}
+
 static void ArgvQuote(std::string &CommandLine, const std::string &Argument,
                       bool Force = false)
 
@@ -344,17 +373,29 @@ void osal_killall_actors(void) {
 
 int osal_actor_poll(mdbx_pid_t &pid, unsigned timeout) {
   std::vector<HANDLE> handles;
-  handles.reserve(childs.size());
+  handles.reserve(childs.size() + 2);
+  handles.push_back(hProgressActiveEvent);
+  handles.push_back(hProgressPassiveEvent);
   for (const auto &pair : childs)
     if (pair.second.second <= as_running)
       handles.push_back(pair.second.first);
 
+loop:
   DWORD rc =
       MsgWaitForMultipleObjectsEx((DWORD)handles.size(), &handles[0],
                                   (timeout > 60) ? 60 * 1000 : timeout * 1000,
                                   QS_ALLINPUT | QS_ALLPOSTMESSAGE, 0);
 
-  if (rc >= WAIT_OBJECT_0 && rc < WAIT_OBJECT_0 + handles.size()) {
+  if (rc == WAIT_OBJECT_0) {
+    logging::progress_canary(true);
+    goto loop;
+  }
+  if (rc == WAIT_OBJECT_0 + 1) {
+    logging::progress_canary(false);
+    goto loop;
+  }
+
+  if (rc >= WAIT_OBJECT_0 + 2 && rc < WAIT_OBJECT_0 + handles.size()) {
     pid = 0;
     for (const auto &pair : childs)
       if (pair.second.first == handles[rc - WAIT_OBJECT_0]) {

test/osal.h

@@ -26,6 +26,8 @@ void osal_killall_actors(void);
 int osal_actor_poll(mdbx_pid_t &pid, unsigned timeout);
 void osal_wait4barrier(void);
 
+bool osal_progress_push(bool active);
+
 mdbx_pid_t osal_getpid(void);
 int osal_delay(unsigned seconds);
 void osal_udelay(unsigned us);

test/test.cc

@@ -307,21 +307,9 @@ bool testcase::wait4start() {
 }
 
 void testcase::kick_progress(bool active) const {
-  chrono::time now = chrono::now_motonic();
+  if (!global::config::progress_indicator)
-  if (active) {
+    return;
-    static int last_point = -1;
+  logging::progress_canary(active);
-    int point = (now.fixedpoint >> 29) & 3;
-    if (point != last_point) {
-      last.progress_timestamp = now;
-      fprintf(stderr, "%c\b", "-\\|/"[last_point = point]);
-      fflush(stderr);
-    }
-  } else if (now.fixedpoint - last.progress_timestamp.fixedpoint >
-             chrono::from_seconds(2).fixedpoint) {
-    last.progress_timestamp = now;
-    fprintf(stderr, "%c\b", "@*"[now.utc & 1]);
-    fflush(stderr);
-  }
 }
 
 void testcase::report(size_t nops_done) {
@@ -333,8 +321,7 @@ void testcase::report(size_t nops_done) {
   log_debug("== complete +%" PRIuPTR " iteration, total %" PRIuPTR " done",
             nops_done, nops_completed);
 
-  if (global::config::progress_indicator)
+  kick_progress(true);
-    kick_progress(true);
 
   if (config.signal_nops && !signalled &&
       config.signal_nops <= nops_completed) {
@@ -389,7 +376,7 @@ bool testcase::should_continue(bool check_timeout_only) const {
       nops_completed >= config.params.test_nops)
     result = false;
 
-  if (result && global::config::progress_indicator)
+  if (result)
     kick_progress(false);
 
   return result;

test/test.h

@@ -49,6 +49,7 @@ extern bool cleanup_before;
 extern bool cleanup_after;
 extern bool failfast;
 extern bool progress_indicator;
+extern bool console_mode;
 } /* namespace config */
 
 } /* namespace global */
@@ -95,7 +96,6 @@ protected:
 
   struct {
     mdbx_canary canary;
-    mutable chrono::time progress_timestamp;
   } last;
 
   static int oom_callback(MDBX_env *env, mdbx_pid_t pid, mdbx_tid_t tid,
@@ -115,7 +115,6 @@ protected:
   void txn_inject_writefault(MDBX_txn *txn);
   void fetch_canary();
   void update_canary(uint64_t increment);
-  void kick_progress(bool active) const;
   void checkdata(const char *step, MDBX_dbi handle, MDBX_val key2check,
                  MDBX_val expected_valued);
 
@@ -155,6 +154,7 @@ public:
   virtual bool run() { return true; }
   virtual bool teardown();
   virtual ~testcase() {}
+  void kick_progress(bool active) const;
 };
 
 class testcase_ttl : public testcase {