[pypy-commit] pypy stm-thread-2: Extend the last_abort_info with bits and pieces from the tx_descriptor

[arigo]

Author: Armin Rigo <arigo at tunes.org>
Branch: stm-thread-2
Changeset: r61618:e8d90c408313
Date: 2013-02-22 16:33 +0100
http://bitbucket.org/pypy/pypy/changeset/e8d90c408313/

Log:	Extend the last_abort_info with bits and pieces from the
	tx_descriptor as well as a timing of the real time lost in the
	aborted transaction.

diff --git a/rpython/translator/stm/src_stm/et.c b/rpython/translator/stm/src_stm/et.c
--- a/rpython/translator/stm/src_stm/et.c
+++ b/rpython/translator/stm/src_stm/et.c
@@ -10,6 +10,7 @@
 #include <string.h>
 #include <assert.h>
 #include <pthread.h>
+#include <time.h>
 
 #ifndef RPY_STM
 /* for tests, a few custom defines */
@@ -48,6 +49,7 @@
   unsigned long reads_size_limit_nonatomic;
   int active;    /* 0 = inactive, 1 = regular, 2 = inevitable */
   int readonly_updates;
+  struct timespec start_real_time;
   unsigned int num_commits;
   unsigned int num_aborts[ABORT_REASONS];
   unsigned int num_spinloops[SPINLOOP_REASONS];
@@ -370,13 +372,16 @@
   spinloop();
 }
 
-size_t _stm_decode_abort_info(struct tx_descriptor *d, char *output);
+size_t _stm_decode_abort_info(struct tx_descriptor *d, long long elapsed_time,
+                              int abort_reason, char *output);
 
 static void AbortTransaction(int num)
 {
   struct tx_descriptor *d = thread_descriptor;
   unsigned long limit;
   size_t size;
+  struct timespec now;
+  long long elapsed_time;
   assert(d->active);
   assert(!is_inevitable(d));
   assert(num < ABORT_REASONS);
@@ -384,13 +389,28 @@
 
   CancelLocks(d);
 
+  /* compute the elapsed time */
+  if (d->start_real_time.tv_nsec != -1 &&
+      clock_gettime(CLOCK_MONOTONIC, &now) >= 0) {
+    elapsed_time = now.tv_sec - d->start_real_time.tv_sec;
+    elapsed_time *= 1000000000;
+    elapsed_time += now.tv_nsec - d->start_real_time.tv_nsec;
+  }
+  else {
+    elapsed_time = -1;
+  }
+
   /* decode the 'abortinfo' and produce a human-readable summary in
      the string 'lastabortinfo' */
-  size = _stm_decode_abort_info(d, NULL);
+  size = _stm_decode_abort_info(d, elapsed_time, num, NULL);
   free(d->lastabortinfo);
   d->lastabortinfo = malloc(size);
   if (d->lastabortinfo != NULL)
-    _stm_decode_abort_info(d, d->lastabortinfo);
+    if (_stm_decode_abort_info(d, elapsed_time, num, d->lastabortinfo) != size)
+      {
+        fprintf(stderr, "during stm abort: object mutated unexpectedly\n");
+        abort();
+      }
 
   /* run the undo log in reverse order, cancelling the values set by
      stm_ThreadLocalRef_LLSet(). */
@@ -447,6 +467,9 @@
 
 static void init_transaction(struct tx_descriptor *d)
 {
+  if (clock_gettime(CLOCK_MONOTONIC, &d->start_real_time) < 0) {
+    d->start_real_time.tv_nsec = -1;
+  }
   assert(d->active == 0);
   assert(d->list_of_read_objects.size == 0);
   assert(d->gcroots.size == 0);
diff --git a/rpython/translator/stm/src_stm/rpyintf.c b/rpython/translator/stm/src_stm/rpyintf.c
--- a/rpython/translator/stm/src_stm/rpyintf.c
+++ b/rpython/translator/stm/src_stm/rpyintf.c
@@ -214,13 +214,16 @@
     gcptrlist_reduce_size(&d->abortinfo, newsize < 0 ? 0 : newsize);
 }
 
-size_t _stm_decode_abort_info(struct tx_descriptor *d, char *output)
+size_t _stm_decode_abort_info(struct tx_descriptor *d, long long elapsed_time,
+                              int abort_reason, char *output)
 {
     /* re-encodes the abort info as a single string.
        For convenience (no escaping needed, no limit on integer
        sizes, etc.) we follow the bittorrent format. */
     size_t totalsize = 0;
     long i;
+    char buffer[32];
+    size_t res_size;
 #define WRITE(c)   { totalsize++; if (output) *output++=(c); }
 #define WRITE_BUF(p, sz)  { totalsize += (sz);                          \
                             if (output) {                               \
@@ -228,12 +231,28 @@
                              }                                          \
                            }
     WRITE('l');
+    WRITE('l');
+    res_size = sprintf(buffer, "i%llde", (long long)elapsed_time);
+    WRITE_BUF(buffer, res_size);
+    res_size = sprintf(buffer, "i%de", (int)abort_reason);
+    WRITE_BUF(buffer, res_size);
+    res_size = sprintf(buffer, "i%lde", (long)(d->my_lock - LOCKED));
+    WRITE_BUF(buffer, res_size);
+    res_size = sprintf(buffer, "i%lde", (long)d->atomic);
+    WRITE_BUF(buffer, res_size);
+    res_size = sprintf(buffer, "i%de", (int)d->active);
+    WRITE_BUF(buffer, res_size);
+    res_size = sprintf(buffer, "i%lue", (unsigned long)d->count_reads);
+    WRITE_BUF(buffer, res_size);
+    res_size = sprintf(buffer, "i%lue",
+                       (unsigned long)d->reads_size_limit_nonatomic);
+    WRITE_BUF(buffer, res_size);
+    WRITE('e');
     for (i=0; i<d->abortinfo.size; i+=2) {
         char *object = (char *)stm_RepeatReadBarrier(d->abortinfo.items[i+0]);
         long *fieldoffsets = (long*)d->abortinfo.items[i+1];
         long kind, offset;
-        char buffer[32];
-        size_t res_size, rps_size;
+        size_t rps_size;
         RPyString *rps;
 
         while (1) {
diff --git a/rpython/translator/stm/test/test_ztranslated.py b/rpython/translator/stm/test/test_ztranslated.py
--- a/rpython/translator/stm/test/test_ztranslated.py
+++ b/rpython/translator/stm/test/test_ztranslated.py
@@ -143,7 +143,7 @@
                 globf.xy = 100 + retry_counter
 
         def check(_, retry_counter):
-            rstm.abort_info_push(globf, ('xy', '[', 'yx', ']'))
+            rstm.abort_info_push(globf, ('[', 'xy', ']', 'yx'))
             setxy(globf, retry_counter)
             if retry_counter < 3:
                 rstm.abort_and_retry()
@@ -163,4 +163,4 @@
             return 0
         t, cbuilder = self.compile(main)
         data = cbuilder.cmdexec('a b')
-        assert 'li102el10:hi there 3ee\n' in data
+        assert 'li102ee10:hi there 3e\n' in data