[XTF,benchmark,v1,3/4] time: provide measurement template

Commit Message

Norbert Manthey March 23, 2020, 1:37 p.m. UTC

The added function measure_performance allows to measure the run time
of a function, by computing the average time it takes to call that
function a given number of retries. The measured total time is returned
in nano seconds. Furthermore, the value is printed via printk in a
fixed format, to allow processing the output further.

This format is, where average-time provides ns with ps granularity:

perf test_name <average-time> ns

Signed-off-by: Norbert Manthey <[e-mail]>

---
 common/time.c      | 76 ++++++++++++++++++++++++++++++++++++++++++++++
 include/xtf/time.h | 15 +++++++++
 2 files changed, 91 insertions(+)

Patch

diff --git a/common/time.c b/common/time.c
--- a/common/time.c
+++ b/common/time.c
@@ -192,6 +192,82 @@  void msleep(uint64_t t)
     mspin_sleep(t);
 }
 
+unsigned long cycles2nsec(uint64_t cycles)
+{
+    return scale_delta(cycles,
+            shared_info.vcpu_info[0].time.tsc_to_system_mul,
+            shared_info.vcpu_info[0].time.tsc_shift);
+}
+
+unsigned long measure_performance(const char* test_name,
+                                  const char* function_name,
+                                  function_under_test_t call,
+                                  unsigned long measure_seconds,
+                                  unsigned long callibration_calls,
+                                  int print_times)
+{
+    unsigned long start, end;  // time stamps for before and after the execution
+    unsigned long calibration_ns, total_measured_ns, avg_ns, avg_ps_fraction;
+    unsigned long counter;
+    unsigned long measure_calls;
+    int rc = 0;
+
+
+    /* Calibrate by measuring time for given amount of callibration calls*/
+    printk("Calibrate %s by calling %lu times\n", function_name,
+                                                  callibration_calls);
+    start = rdtscp();
+    for(counter = 0; counter < callibration_calls; ++ counter)
+    {
+        rc = call();
+    }
+    end = rdtscp();
+
+    /* Calculate the total number in nano seconds */
+    calibration_ns = cycles2nsec(end - start);
+
+    /* Calculate number of calls for about measure_seconds based on
+       (callibration_calls / calibration_ns) equals
+       (measure_calls / (measure_seconds * 1000 * 1000 * 1000)) */
+    measure_calls = ((measure_seconds * 1000UL * 1000UL * 1000UL)
+                     / calibration_ns) * callibration_calls;
+
+    printk("Measure %s by calling %lu times\n", function_name, measure_calls);
+
+    /* Perform all calls, measure start and end time */
+    start = rdtscp();
+    for(counter = 0; counter < measure_calls; ++ counter)
+    {
+        rc = call();
+    }
+    end = rdtscp();
+
+    /* Calculate the total number in nano seconds */
+    total_measured_ns = cycles2nsec(end - start);
+    avg_ns = total_measured_ns / measure_calls;
+    avg_ps_fraction = (total_measured_ns / (measure_calls/1000)) % 1000;
+
+    if(print_times)
+    {
+        /* Show the result of the last query */
+        printk("%s's last return value: %d\n", function_name, rc);
+
+        /* Print average time and total time */
+        printk("Avg %s call time: avg: %ld.%s%ld ns total: %ld ns\n",
+               function_name, avg_ns,
+               avg_ps_fraction < 10 ? "00" : (avg_ps_fraction < 100 ? "0" : ""),
+               avg_ps_fraction, total_measured_ns);
+
+        /* Print performance value */
+        printk("perf %s %ld.%s%ld ns\n", test_name, avg_ns,
+               avg_ps_fraction < 10 ? "00" : (avg_ps_fraction < 100 ? "0" : ""),
+               avg_ps_fraction);
+    }
+
+    /* Return average run time in pico seconds */
+    return avg_ns * 1000 + avg_ps_fraction;
+}
+
 /*
  * Local variables:
  * mode: C
diff --git a/include/xtf/time.h b/include/xtf/time.h
--- a/include/xtf/time.h
+++ b/include/xtf/time.h
@@ -53,6 +53,21 @@  int gettimeofday(struct timeval *tp);
 /* This returns the current epoch time */
 #define NOW() current_time()
 
+unsigned long cycles2nsec(uint64_t cycles);
+
+/* Signature of a function to be called for measurement */
+typedef int (*function_under_test_t)(void);
+
+/* Measure the time it takes to call the passed function. Measure for a given
+   amount of time after calibrating for a given amount of calls. Returns the
+   average run time of the measure call in pico seconds. */
+unsigned long measure_performance(const char* test_name,
+                                  const char* function_name,
+                                  function_under_test_t call,
+                                  unsigned long measure_seconds,
+                                  unsigned long callibration_calls,
+                                  int print_times);
+
 #endif /* XTF_TIME_H */
 
 /*