Overhead measurement

2 files changed, 112 insertions, 24 deletions

diff --git a/bin/rwrnlp.c b/bin/rwrnlp.c
index c3221d8..07e3899 100644
--- a/bin/rwrnlp.c
+++ b/bin/rwrnlp.c
@@ -297,21 +297,21 @@ static int job(struct thread_context *ctx, double program_end)
                 loop_for(ncs_length, program_end + 1);
 
         if(ctx->type == read_req){
-            printf("%d:%d read locking...\n", __sync_fetch_and_add(&events,1), gettid());
+            //printf("%d:%d read locking...\n", __sync_fetch_and_add(&events,1), gettid());
             rwrnlp_read_lock(&rw_lock, ctx->resources, ctx->processor);
-            printf("%d:%d read CS...\n", __sync_fetch_and_add(&events, 1), gettid());
+            //printf("%d:%d read CS...\n", __sync_fetch_and_add(&events, 1), gettid());
             loop_for(ctx->cs_length*S_PER_MS, program_end + 1);
-            printf("%d:%d read unlocking...\n", __sync_fetch_and_add(&events,1), gettid());
+            //printf("%d:%d read unlocking...\n", __sync_fetch_and_add(&events,1), gettid());
             rwrnlp_read_unlock(&rw_lock, ctx->processor);
-            printf("%d:%d ncs...\n", __sync_fetch_and_add(&events,1), gettid());
+            //printf("%d:%d ncs...\n", __sync_fetch_and_add(&events,1), gettid());
         }else{
-            printf("%d:%d write locking %lu\n", __sync_fetch_and_add(&events,1), gettid(), ctx->resources);
+            //printf("%d:%d write locking %lu\n", __sync_fetch_and_add(&events,1), gettid(), ctx->resources);
             rwrnlp_write_lock(&rw_lock, ctx->resources, ctx->processor);
-            printf("%d:%d write CS...\n", __sync_fetch_and_add(&events,1), gettid());
+            //printf("%d:%d write CS...\n", __sync_fetch_and_add(&events,1), gettid());
             loop_for(ctx->cs_length*S_PER_MS, program_end + 1);
-            printf("%d:%d write unlocking...\n", __sync_fetch_and_add(&events,1), gettid());
+            //printf("%d:%d write unlocking...\n", __sync_fetch_and_add(&events,1), gettid());
             rwrnlp_write_unlock(&rw_lock, ctx->processor);
-            printf("%d:%d ncs...\n", __sync_fetch_and_add(&events,1), gettid());
+            //printf("%d:%d ncs...\n", __sync_fetch_and_add(&events,1), gettid());
         }
 
 
diff --git a/src/spinlocks.c b/src/spinlocks.c
index 9847aac..9b04702 100644
--- a/src/spinlocks.c
+++ b/src/spinlocks.c
@@ -1,14 +1,32 @@
 #include <stdlib.h>
 #include <stdio.h>
 #include <string.h>
+#include <time.h>
 
 #include "litmus.h"
 #include "spinlocks.h"
 
 #define NR_RESOURCES sizeof(resource_mask_t)*8
 
+#define MEASURE TRUE
+
 int events;
 
+#if MEASURE==TRUE
+static inline long diff_ns(const struct timespec *s, const struct timespec *e)
+{
+        const int64_t ns_in_s = 1000000000LL;
+        struct timespec temp = *e;
+        temp.tv_sec -= s->tv_sec;
+        temp.tv_nsec -= s->tv_nsec;
+        if (temp.tv_nsec < 0) {
+                --temp.tv_sec;
+                temp.tv_nsec += ns_in_s;
+        }
+        return temp.tv_sec * ns_in_s + temp.tv_nsec;
+}
+#endif
+
 void spin_init(spinlock_t *lock){
     lock->serving = 0;
     lock->next_ticket = 0;
@@ -16,8 +34,8 @@ void spin_init(spinlock_t *lock){
 
 void spin_lock(spinlock_t *lock){
     int ticket = __sync_fetch_and_add(&(lock->next_ticket), 1);
-    printf("%d:%d waiting for ticket %d serving %d\n",
-            __sync_fetch_and_add(&events,1), gettid(), ticket, lock->serving);
+//    printf("%d:%d waiting for ticket %d serving %d\n",
+//            __sync_fetch_and_add(&events,1), gettid(), ticket, lock->serving);
     while(lock->serving != ticket);
 }
 
@@ -50,6 +68,11 @@ void rwrnlp_init(rwrnlp *lock)
 void rwrnlp_read_lock(rwrnlp *lock, resource_mask_t resources, int processor)
 {
     request *req;
+#if MEASURE==TRUE
+    long overhead = 0;
+    struct timespec now, last;
+        clock_gettime(CLOCK_MONOTONIC, &last);
+#endif
     
     enter_np();
 
@@ -59,7 +82,7 @@ void rwrnlp_read_lock(rwrnlp *lock, resource_mask_t resources, int processor)
     req->status    = waiting;
     lock->enter[processor]+=1;
 
-    printf("%d:%d rwrnlp_read_lock %lu\n",__sync_fetch_and_add(&events,1), gettid(), req->resources);
+//    printf("%d:%d rwrnlp_read_lock %lu\n",__sync_fetch_and_add(&events,1), gettid(), req->resources);
 
     spin_lock(lock->state);
     if((req->resources & lock->unavailable) == 0){
@@ -68,14 +91,35 @@ void rwrnlp_read_lock(rwrnlp *lock, resource_mask_t resources, int processor)
     spin_unlock(lock->state);
 
     if(req->status != acquired){
-        printf("%d:%d waiting to become entitled\n",__sync_fetch_and_add(&events,1), gettid());
+//        printf("%d:%d waiting to become entitled\n",__sync_fetch_and_add(&events,1), gettid());
+#if MEASURE==TRUE
+        clock_gettime(CLOCK_MONOTONIC, &now);
+        overhead += diff_ns(&last,&now);
+#endif
+
         while((req->resources & lock->wentitled) != 0);
+#if MEASURE==TRUE
+        clock_gettime(CLOCK_MONOTONIC, &last);
+#endif
         req->status = entitled;
-        printf("%d:%d waiting to acquire\n", __sync_fetch_and_add(&events,1), gettid());
+#if MEASURE==TRUE
+        clock_gettime(CLOCK_MONOTONIC, &now);
+        overhead += diff_ns(&last, &now);
+#endif
+
+//        printf("%d:%d waiting to acquire\n", __sync_fetch_and_add(&events,1), gettid());
         while((req->resources & lock->wlocked) != 0);
     }
+#if MEASURE==TRUE
+    else{
+        //acquire, but measure overheads
+        clock_gettime(CLOCK_MONOTONIC, &now);
+        overhead += diff_ns(&last, &now);
+    }
+    printf("read lock overhead: %ld\n", overhead);
+#endif
     
-    printf("%d:%d reader satisfied\n", __sync_fetch_and_add(&events,1), gettid());
+//    printf("%d:%d reader satisfied\n", __sync_fetch_and_add(&events,1), gettid());
 }
 
 void rwrnlp_write_lock(rwrnlp *lock, resource_mask_t resources, int processor)
@@ -83,10 +127,15 @@ void rwrnlp_write_lock(rwrnlp *lock, resource_mask_t resources, int processor)
     int r,i,start,end;
     request *req, *contender;
     resource_mask_t tmp = resources;
+#if MEASURE==TRUE
+    struct timespec now, last;
+    long overhead = 0;
+    clock_gettime(CLOCK_MONOTONIC, &last);
+#endif
 
     enter_np();
 
-    printf("%d:%d rwrnlp_write_lock\n", __sync_fetch_and_add(&events,1), gettid());
+//    printf("%d:%d rwrnlp_write_lock\n", __sync_fetch_and_add(&events,1), gettid());
 
     req = &lock->requests[processor];
 
@@ -110,8 +159,15 @@ void rwrnlp_write_lock(rwrnlp *lock, resource_mask_t resources, int processor)
     r = ffsl(tmp);
     while(r != 0){
         r = r-1;
-        printf("%d:%d write waiting to become head of %d\n", __sync_fetch_and_add(&events,1), gettid(), r);
+//        printf("%d:%d write waiting to become head of %d\n", __sync_fetch_and_add(&events,1), gettid(), r);
+#if MEASURE==TRUE
+        clock_gettime(CLOCK_MONOTONIC, &now);
+        overhead += diff_ns(&last, &now);
+#endif
         while(lock->wqueue[r][lock->whead[r]] != req);
+#if MEASURE==TRUE
+        clock_gettime(CLOCK_MONOTONIC, &last);
+#endif
         tmp &= ~(1<<r);
         r = ffsl(tmp);
     }
@@ -132,8 +188,16 @@ void rwrnlp_write_lock(rwrnlp *lock, resource_mask_t resources, int processor)
                (contender->resources & req->resources) == 0)
                 continue;
 
-            printf("%d:%d waiting for reader on processor %d\n", __sync_fetch_and_add(&events,1), gettid(), i);
+//            printf("%d:%d waiting for reader on processor %d\n", __sync_fetch_and_add(&events,1), gettid(), i);
+
+#if MEASURE==TRUE
+            clock_gettime(CLOCK_MONOTONIC, &now);
+            overhead += diff_ns(&last, &now);
+#endif
             while(lock->leave[i] < start);
+#if MEASURE==TRUE
+            clock_gettime(CLOCK_MONOTONIC, &last);
+#endif
         }
     }
 
@@ -142,23 +206,43 @@ void rwrnlp_write_lock(rwrnlp *lock, resource_mask_t resources, int processor)
     lock->wlocked |= req->resources;
     spin_unlock(lock->state);
 
-    printf("%d:%d writer satisfied\n", __sync_fetch_and_add(&events,1), gettid());
+//    printf("%d:%d writer satisfied\n", __sync_fetch_and_add(&events,1), gettid());
+#if MEASURE==TRUE
+    clock_gettime(CLOCK_MONOTONIC, &now);
+    overhead += diff_ns(&last, &now);
+    printf("write lock overhead: %ld\n", overhead);
+#endif
 }
 
 void rwrnlp_read_unlock(rwrnlp *lock, int processor)
 {
+#if MEASURE==TRUE
+    struct timespec now, last;
+    clock_gettime(CLOCK_MONOTONIC, &last);
+#endif
     lock->leave[processor] += 1;
-    printf("%d:%d rwrnlp_read_unlock\n", __sync_fetch_and_add(&events,1), gettid());
+//    printf("%d:%d rwrnlp_read_unlock\n", __sync_fetch_and_add(&events,1), gettid());
     exit_np();
+
+#if MEASURE==TRUE
+    clock_gettime(CLOCK_MONOTONIC, &now);
+    printf("read unlock overhead: %ld\n", diff_ns(&last, &now));
+#endif
 }
 
 void rwrnlp_write_unlock(rwrnlp *lock, int processor)
 {
     int r;
-    request *req = &lock->requests[processor];
-    resource_mask_t tmp = req->resources;
+    request *req;
+    resource_mask_t tmp;
+#if MEASURE==TRUE
+    struct timespec now, last;
+    clock_gettime(CLOCK_MONOTONIC, &last);
+#endif
+    req= &lock->requests[processor];
+    tmp = req->resources;
 
-    printf("%d:%d rwrnlp_write_unlock\n", __sync_fetch_and_add(&events,1), gettid());
+//    printf("%d:%d rwrnlp_write_unlock\n", __sync_fetch_and_add(&events,1), gettid());
 
     lock->leave[processor] += 1;
 
@@ -174,7 +258,11 @@ void rwrnlp_write_unlock(rwrnlp *lock, int processor)
     lock->unavailable &= ~(req->resources);
     spin_unlock(lock->state);
     
-    printf("%d:%d write unlocked %lu\n", __sync_fetch_and_add(&events,1), gettid(), req->resources);
-    printf("unavailable %lu\nwentitled %lu\nwlocked %lu\n", lock->unavailable, lock->wentitled, lock->wlocked);
+//    printf("%d:%d write unlocked %lu\n", __sync_fetch_and_add(&events,1), gettid(), req->resources);
+//    printf("unavailable %lu\nwentitled %lu\nwlocked %lu\n", lock->unavailable, lock->wentitled, lock->wlocked);
     exit_np();
+#if MEASURE==TRUE
+    clock_gettime(CLOCK_MONOTONIC, &now);
+    printf("write unlock overhead: %ld\n", diff_ns(&last, &now));
+#endif
 }