Tidy up output

Makefile

 all: mpistalls mpistalls-timed
 
-mpistalls: mpistalls.c mpiuse.c mpiuse.h atomic.h cycle.h
-	$(CC) -g -O0 -o mpistalls mpistalls.c mpiuse.c -I/usr/include/mpi -lmpi -lpthread
+mpistalls: mpistalls.c mpiuse.c mpiuse.h atomic.h cycle.h clocks.h clocks.c
+	$(CC) -g -O0 -Wall -o mpistalls mpistalls.c mpiuse.c clocks.c -I/usr/include/mpi -lmpi -lpthread
 
 mpistalls-timed: mpistalls-timed.c mpiuse.c mpiuse.h atomic.h cycle.h clocks.h clocks.c
-	$(CC) -g -O0 -o mpistalls-timed mpistalls-timed.c mpiuse.c clocks.c -I/usr/include/mpi -lmpi -lpthread
+	$(CC) -g -O0 -Wall -o mpistalls-timed mpistalls-timed.c mpiuse.c clocks.c -I/usr/include/mpi -lmpi -lpthread
 
 clean:
 	rm mpistalls mpistalls-timed

clocks.c

@@ -210,7 +210,7 @@ const char *clocks_getunit(void) { return clocks_units[clocks_units_index]; }
  *
  * Need to call clocks_set_cpufreq() to mark the start of execution.
  *
- * The time is return in the format [sssss.s].
+ * The time is return in the format [ssss.sss].
  *
  * @result the time since the start of the execution
  */
@@ -218,7 +218,7 @@ const char *clocks_get_timesincestart(void) {
 
   static char buffer[40];
 
-  sprintf(buffer, "[%07.1f]",
+  sprintf(buffer, "[%07.3f]",
           clocks_diff_ticks(getticks(), clocks_start_ticks) / 1000.0);
 
   return buffer;

error.h

 #include <mpi.h>
+#include "clocks.h"
 
 extern int myrank;
 
 /* Exit in error macro. */
-#define error(s, ...)                                            \
+#define error(s, ...)                                                   \
   ({                                                                    \
     fflush(stdout);                                                     \
-    fprintf(stderr, "%d/ %s:%s():%i: " s "\n", myrank, __FILE__, __FUNCTION__, \
-            __LINE__, ##__VA_ARGS__);                                   \
+    fprintf(stderr, "[%03i] %s %s:%s():%i: " s "\n", myrank,            \
+            clocks_get_timesincestart(),                                \
+            __FILE__, __FUNCTION__, __LINE__, ##__VA_ARGS__);           \
     MPI_Abort(MPI_COMM_WORLD, -1);                                      \
   })
 
 /* Print a message */
-#define message(s, ...)                                          \
+#define message(s, ...)                                                 \
   ({                                                                    \
-    printf("%d/ %s: " s "\n", myrank, __FUNCTION__, ##__VA_ARGS__);      \
+    printf("[%04i] %s %s: " s "\n", myrank,                             \
+           clocks_get_timesincestart(),__FUNCTION__, ##__VA_ARGS__);    \
   })

mpistalls-timed.c

@@ -21,6 +21,9 @@
 /* Global: Our rank for all to see. */
 int myrank = -1;
 
+/* Are we verbose. */
+static int verbose = 0;
+
 /* Integer types of send and recv tasks, must match log. */
 static const int task_type_send = 22;
 static const int task_type_recv = 23;
@@ -43,29 +46,34 @@ static int volatile nr_sends = 0;
 static int volatile ind_send = 0;
 static int volatile todo_send = 0;
 
-/* Delta tics that we do not wait for. XXX measure this. */
-const ticks looptics = 10000;
-
 /* CPU frequency of the machine that created the MPI log. */
 // XXX need to store this in the data file.
 static double clocks_cpufreq = 2194844448.0;
 
-/* Injection thread, initiates MPI_Isend and MPI_Irecv requests at various
- * times. */
+/**
+ * @brief Injection thread, initiates MPI_Isend and MPI_Irecv requests.
+ *
+ * The requests are initiated in the time order of the original log and an
+ * attempt to start these with the same interval gap is made.
+ */
 static void *inject_thread(void *arg) {
-  message("%d: injection thread starts", *((int *)arg));
+
+  if (verbose)
+    message("%d: injection thread starts", *((int *)arg));
   ticks starttics = getticks();
 
   /* Ticks of our last attempt. */
   ticks basetic = reqs_queue[0]->tic;
 
+  /* The time that once around this loop takes. We do not wait for injections
+   * that are closer in time than this value. */
+  ticks looptics = 0;
+
   while (ind_req < nr_reqs) {
     struct mpiuse_log_entry *log = reqs_queue[ind_req];
 
     /* Expect time between this request and the previous one. */
     ticks dt = log->tic - basetic;
-    double ddt = (double)log->tic - (double)basetic;
-    ticks oldbasetic = basetic;
     basetic = log->tic;
 
     /* Guess some time below which we should not attempt to wait, otherwise
@@ -113,26 +121,41 @@ static void *inject_thread(void *arg) {
     if (err != MPI_SUCCESS) error("Failed to activate send or recv");
 
     ind_req++;
+
+    /* Set looptics on the first pass. Assumes MPI_Isend and MPI_Irecv are
+     * equally timed. */
+    if (looptics == 0) {
+      looptics = starttics - getticks();
+      if (verbose)
+        message("injection loop took %.3f %s.", clocks_from_ticks(looptics),
+                clocks_getunit());
+    }
+  }
+
+  /* All done, thread exiting. */
+  if (verbose) {
+    message("%d injections completed, sends = %d, recvs = %d", ind_req,
+            nr_sends, nr_recvs);
+    message("remaining sends = %d, recvs = %d", todo_send, todo_recv);
   }
-  message("%d injections completed, sends = %d, recvs = %d", ind_req,
-          nr_sends, nr_recvs);
-  message("remaining sends = %d, recvs = %d", todo_send, todo_recv);
   message("took %.3f %s.", clocks_from_ticks(getticks() - starttics),
           clocks_getunit());
   atomic_dec(&injecting);
   return NULL;
 }
 
-/* Send thread, checks if MPI_Isend requests have completed. */
+/**
+ * @brief Send thread, checks if MPI_Isend requests have completed.
+ */
 static void *send_thread(void *arg) {
-  message("%d: send thread starts (%d)", *((int *)arg), injecting);
+
+  if (verbose)
+    message("%d: send thread starts (%d)", *((int *)arg), injecting);
   ticks starttics = getticks();
 
-  int res;
-  MPI_Status stat;
 
-  // Need a test that only exits when requests are all inserted and we have
-  // emptied our queue. */
+  /* We loop while new requests are being injected and then when we still have
+   * sends to complete. */
   size_t attempts = 0;
   while (injecting || (!injecting && todo_send > 0)) {
     int nsends = nr_sends;
@@ -140,13 +163,15 @@ static void *send_thread(void *arg) {
       struct mpiuse_log_entry *log = sends_queue[k];
       if (log != NULL) {
         attempts++;
+        int res;
+        MPI_Status stat;
         int err = MPI_Test(&log->req, &res, &stat);
         if (err != MPI_SUCCESS) {
           error("MPI_Test call failed");
         }
         if (res) {
+
           /* Done, clean up. */
-          //message("MPI_Test successful");
           free(log->data);
           sends_queue[k] = NULL;
           atomic_dec(&todo_send);
@@ -154,21 +179,27 @@ static void *send_thread(void *arg) {
       }
     }
   }
-  message("sends completed, required %zd attempts (left: %d)", attempts,
-          todo_send);
+
+  /* All done, thread exiting. */
+  if (verbose)
+    message("sends completed, required %zd attempts (left: %d)", attempts,
+            todo_send);
   message("took %.3f %s.", clocks_from_ticks(getticks() - starttics),
           clocks_getunit());
   return NULL;
 }
 
-/* Recv thread, checks if MPI_Irecv requests have completed. */
+/**
+ * @brief Recv thread, checks if MPI_Irecv requests have completed.
+ */
 static void *recv_thread(void *arg) {
-  message("%d: recv thread starts", *((int *)arg));
-  ticks starttics = getticks();
 
-  int res;
-  MPI_Status stat;
+  if (verbose)
+    message("%d: recv thread starts", *((int *)arg));
+  ticks starttics = getticks();
 
+  /* We loop while new requests are being injected and then when we still have
+   * recvs to complete. */
   size_t attempts = 0;
   while (injecting || (!injecting && todo_recv > 0)) {
     int nrecvs = nr_recvs;
@@ -176,13 +207,15 @@ static void *recv_thread(void *arg) {
       struct mpiuse_log_entry *log = recvs_queue[k];
       if (log != NULL) {
         attempts++;
+        int res;
+        MPI_Status stat;
         int err = MPI_Test(&log->req, &res, &stat);
         if (err != MPI_SUCCESS) {
           error("MPI_Test call failed");
         }
         if (res) {
+
           /* Done, clean up. */
-          //message("MPI_Test successful");
           free(log->data);
           recvs_queue[k] = NULL;
           atomic_dec(&todo_recv);
@@ -191,14 +224,18 @@ static void *recv_thread(void *arg) {
     }
   }
 
-  message("recvs completed, required %zd attempts (left: %d)", attempts,
-          todo_recv);
+  /* All done, thread exiting. */
+  if (verbose)
+    message("recvs completed, required %zd attempts (left: %d)", attempts,
+            todo_recv);
   message("took %.3f %s.", clocks_from_ticks(getticks() - starttics),
           clocks_getunit());
   return NULL;
 }
 
-/* Comparison function for logged times. */
+/**
+ * @brief Comparison function for logged times.
+ */
 static int cmp_logs(const void *p1, const void *p2) {
   struct mpiuse_log_entry *l1 = *(struct mpiuse_log_entry **)p1;
   struct mpiuse_log_entry *l2 = *(struct mpiuse_log_entry **)p2;
@@ -211,13 +248,15 @@ static int cmp_logs(const void *p1, const void *p2) {
   return 0;
 }
 
-/* Pick out the relevant logging data for our rank, i.e. all activations of
- * sends and recvs. */
+/**
+ * @brief Pick out the relevant logging data for our rank, i.e. all
+ * activations of sends and recvs. We ignore the original completions.
+ * The final list is sorted into increasing time of activation.
+ */
 static void pick_logs(void) {
   size_t nlogs = mpiuse_nr_logs();
-  int nranks = mpiuse_nr_ranks();
 
-  /* Duplicate of logs. XXX could loop twice to reduce memory use if needed. */
+  /* Duplicate of logs. */
   reqs_queue = (struct mpiuse_log_entry **)
     malloc(sizeof(struct mpiuse_log_entry *) * nlogs);
   nr_reqs= 0;
@@ -250,12 +289,16 @@ static void pick_logs(void) {
   qsort(reqs_queue, nr_reqs, sizeof(struct mpiuse_log_entry *), cmp_logs);
 }
 
+
+/**
+ * @brief main function.
+ */
 int main(int argc, char *argv[]) {
 
   /* First we read the SWIFT MPI logger output that defines the communcations
    * we will undertake and the time differences between injections into the
    * queues. */
-  mpiuse_log_restore("testdata/mpiuse_report-step1.dat");
+  mpiuse_log_restore("testdata/mpiuse_report-step1062.dat");
   int nranks = mpiuse_nr_ranks();
 
   /* Initiate MPI. */
@@ -286,9 +329,12 @@ int main(int argc, char *argv[]) {
   /* Each rank requires its own queue, so extract them. */
   pick_logs();
 
-  /* Start time. */
-  message("Start of MPI tests");
+  /* Time to start time. */
   clocks_set_cpufreq(0);
+  if (myrank == 0) {
+    message("Start of MPI tests");
+    message("==================");
+  }
 
   /* Make three threads, one for injecting tasks and two to check for
    * completions of the sends and recv independently. */
@@ -311,6 +357,7 @@ int main(int argc, char *argv[]) {
   res = MPI_Finalize();
   if (res != MPI_SUCCESS)
     error("call to MPI_Finalize failed with error %i.", res);
+  if (myrank == 0) message("Bye");
 
   return 0;
 }