X on tracking pagefault latency

e.g. it is

	.. on_pagefault_start   0.954 µs
	.. vma_on_pagefault_pre 0.954 µs
	.. ramh_alloc_page_pre  0.954 µs
	.. ramh_alloc_page      169.992 µs
	.. vma_on_pagefault     172.853 µs
	.. vma_on_pagefault_pre 172.853 µs
	.. vma_on_pagefault     174.046 µs
	.. on_pagefault_end     174.046 µs
	.. whole:               171.900 µs

so almost all in ramh_alloc_page.

bigfile/pagefault.c

@@ -37,6 +37,7 @@
 #include <errno.h>
 #include <stdint.h>
 
+#include "../t/t_utils.h"
 
 /* "before us" previously installed SIGSEGV sigaction */
 static struct sigaction prev_segv_act;
@@ -45,6 +46,10 @@ static int    segv_act_installed;
 static int faulted_by(const struct ucontext *uc);
 
 
+volatile double t_on_pagefault_start, t_on_pagefault_end;
+volatile double t_vma_on_pagefault_pre[10], t_vma_on_pagefault[10];
+volatile int    n_vma_on_pagefault;
+
 /* SIGSEGV handler */
 static void on_pagefault(int sig, siginfo_t *si, void *_uc)
 {
@@ -55,6 +60,9 @@ static void on_pagefault(int sig, siginfo_t *si, void *_uc)
     BUG_ON(sig != SIGSEGV);
     BUG_ON(si->si_signo != SIGSEGV);
 
+    //t_on_pagefault_start = microtime();
+    trace("on_pagefault_start");
+
     /* determine what client wants - read or write */
     write = faulted_by(uc);
 
@@ -93,6 +101,8 @@ static void on_pagefault(int sig, siginfo_t *si, void *_uc)
     BUG_ON(in_on_pagefault);
     ++in_on_pagefault;
 
+    n_vma_on_pagefault = 0;
+
     /* vma_on_pagefault() can tell us to retry handling the fault, e.g. after a
      * page has been loaded. Loop until pagefault is handled */
     while (1) {
@@ -106,10 +116,17 @@ static void on_pagefault(int sig, siginfo_t *si, void *_uc)
             goto dont_handle;  /* fault outside registered file slices */
         }
 
+        //t_vma_on_pagefault_pre[n_vma_on_pagefault] = microtime();
+        trace("vma_on_pagefault_pre");
+
         /* now, since we found faulting address in registered memory areas, we know
          * we should serve this pagefault. */
         vmres = vma_on_pagefault(vma, (uintptr_t)si->si_addr, write);
 
+        //t_vma_on_pagefault[n_vma_on_pagefault] = microtime();
+        trace("vma_on_pagefault");
+        n_vma_on_pagefault++;
+
         /* see if pagefault handled or should be retried */
         if (vmres == VM_HANDLED)
             break;
@@ -123,6 +140,9 @@ static void on_pagefault(int sig, siginfo_t *si, void *_uc)
     virt_unlock();
     errno = save_errno;
 
+    //t_on_pagefault_end = microtime();
+    trace("on_pagefault_end");
+
     return;
 
 

bigfile/ram.c

@@ -29,6 +29,7 @@
 #include <wendelin/utils.h>
 #include <wendelin/bug.h>
 
+#include "../t/t_utils.h"
 
 /* ramh_ops */
 
@@ -37,6 +38,8 @@ Page *ramh_alloc_page(RAMH *ramh, pgoff_t pgoffset_hint)
     struct Page *page;
     pgoff_t ramh_pgoffset;
 
+    trace("ramh_alloc_page_pre");
+
     // XXX ok to malloc, or better do more structured allocations?
     page = zalloc(sizeof(*page));
     if (!page)
@@ -56,6 +59,7 @@ Page *ramh_alloc_page(RAMH *ramh, pgoff_t pgoffset_hint)
     INIT_LIST_HEAD(&page->in_dirty);	/* initially not in dirty list */
     page->refcnt = 0;
 
+    trace("ramh_alloc_page");
     return page;
 }
 

bigfile/tests/bench_0virtmem.py

@@ -100,6 +100,17 @@ def bench_pagefault_py(b):
     del f   # f.close()
 
 
+def bench_iter(b):
+    for _ in xrange(b.N):
+        pass
+
+def f():
+    pass
+
+def bench_call(b):
+    for _ in xrange(b.N):
+        f()
+
 # compute hash via mmaping the file at OS-level
 def _bench_file_mmapread(hasher, expect):
     fd = os.open(tmpf.name, O_RDONLY)

bigfile/tests/bench_virtmem.c

@@ -35,6 +35,7 @@
 struct BigFile_ZeroTrack {
     BigFile;
     blk_t last_load;
+    double t_last_load;
 };
 typedef struct BigFile_ZeroTrack BigFile_ZeroTrack;
 
@@ -47,6 +48,7 @@ int zero_loadblk(BigFile *file0, blk_t blk, void *buf)
     // Nothing to do here - the memory buf obtained from OS comes pre-cleared
     // XXX reenable once/if memory comes uninitialized here
     file->last_load = blk;
+    file->t_last_load = microtime();
     return 0;
 }
 
@@ -56,14 +58,22 @@ static const struct bigfile_ops filez_ops = {
     .release    = NULL, // XXX
 };
 
+extern volatile double t_on_pagefault_start, t_on_pagefault_end;
+extern volatile double t_vma_on_pagefault_pre[10], t_vma_on_pagefault[10];
+extern volatile int    n_vma_on_pagefault;
+
 /* benchmark the time it takes for virtmem to handle pagefault with noop loadblk */
 void bench_pagefault() {
     RAM *ram;
-    BigFileH fh_struct, *fh = &fh_struct;
-    VMA vma_struct, *vma = &vma_struct;
-    pgoff_t p, npage = 10000;
+    //BigFileH fh_struct, *fh = &fh_struct;
+    //VMA vma_struct, *vma = &vma_struct;
+    BigFileH *fh = malloc(sizeof(*fh));
+    VMA *vma = malloc(sizeof(*vma));
+    //pgoff_t p, npage = 10000;
+    pgoff_t p, npage = 1500;
     size_t PS;
     int err;
+    int i;
 
     double Tstart, Tend;
 
@@ -90,24 +100,38 @@ void bench_pagefault() {
 
     // access first byte of every page
     for (p = 0; p < npage; p++) {
+        trace_reset();
+        double t = microtime();
+#define Dus(tt) (((tt) - t) * 1E6)
         b(vma, p * PS);
         if (f.last_load != p)
             fail("accessed page #%ld but last loadblk was for block #%ld", p, f.last_load);
+        printf("\n");
+#if 0
+        printf(".. onpagefault_start:\t%.3lf µs\n", Dus(t_on_pagefault_start));
+        printf(".. #vma_on_pagefault:\t%d\n", n_vma_on_pagefault);
+        for (i = 0; i < n_vma_on_pagefault; i++)
+            printf(".. vma_on_pagefault[%d]:\t%.3lf (<- %.3lf)\n", i,
+                    Dus(t_vma_on_pagefault[i]), Dus(t_vma_on_pagefault_pre[i]));
+        printf(".. onpagefault_end:\t%.3lf µs\n", Dus(t_on_pagefault_end));
+#endif
+        for (i = 0; i < tracev_len; i++)
+            printf(".. %s\t%.3lf µs\n", tracev[i].name, Dus(tracev[i].t));
+        printf(".. whole:\t\t%.3lf µs\n", Dus(f.t_last_load));
     }
 
     Tend = microtime();
 
     printf("BenchmarkPagefaultC\t%ld\t%.3lf µs/op\n", npage, (Tend - Tstart) * 1E6 / npage);
 
-    vma_unmap(vma);
-    fileh_close(fh);
-    ram_close(ram);
-
+//    vma_unmap(vma);
+//    fileh_close(fh);
+//    ram_close(ram);
 }
 
 int main()
 {
-    int i, nrun=3;
+    int i, nrun=1;
     tap_fail_callback = abort;  // XXX to catch failure immediately
 
     for (i=0; i<nrun; i++)

bigfile/virtmem.c

@@ -37,6 +37,8 @@
 #include <stdio.h>
 #include <unistd.h>
 
+#include "../t/t_utils.h"
+
 static size_t   page_size(const Page *page);
 static void     page_drop_memory(Page *page);
 static void    *vma_page_addr(VMA *vma, Page *page);
@@ -787,6 +789,7 @@ static int __ram_reclaim(RAM *ram)
     int batch = RECLAIM_BATCH, scanned = 0;
 
     TRACE("RAM_RECLAIM\n");
+    trace("ram_reclaim");
     hlru = lru_list->next;
 
     while (batch && hlru != lru_list) {

t/t_utils.c

@@ -171,3 +171,19 @@ double microtime() {
 
         return tv.tv_sec + 1E-6 * tv.tv_usec;
 }
+
+struct trace_event tracev[100];
+int tracev_len;
+
+void trace_reset() {
+    tracev_len = 0;
+}
+
+void trace(const char *event_name) {
+    BUG_ON(tracev_len >= ARRAY_SIZE(tracev));
+
+    tracev[tracev_len].name = event_name;
+    tracev[tracev_len].t    = microtime();
+
+    tracev_len++;
+}

t/t_utils.h

@@ -46,4 +46,15 @@ RAMLimited *ram_limited_new(RAM *backend, size_t alloc_max);
 /* current time as float */
 double microtime();
 
+// trace events
+struct trace_event {
+    const char *name;
+    double      t;
+};
+
+extern struct trace_event tracev[100];
+extern int tracev_len;
+void trace_reset();
+void trace(const char *event_name);
+
 #endif