alarm: Make the debugging output useful
authorBarret Rhoden <brho@cs.berkeley.edu>
Mon, 17 Dec 2018 18:35:53 +0000 (13:35 -0500)
committerBarret Rhoden <brho@cs.berkeley.edu>
Tue, 18 Dec 2018 20:30:28 +0000 (15:30 -0500)
TSC ticks are great and all, but it really helps to have it in a more
decipherable scale, such as seconds/nsec since boot.

Signed-off-by: Barret Rhoden <brho@cs.berkeley.edu>
kern/drivers/dev/alarm.c
kern/src/alarm.c

index 7b31548..ccde970 100644 (file)
@@ -533,6 +533,7 @@ static int alarm_tapfd(struct chan *c, struct fd_tap *tap, int cmd)
 static char *alarm_chaninfo(struct chan *ch, char *ret, size_t ret_l)
 {
        struct proc_alarm *a;
+       struct timespec ts;
 
        switch (TYPE(ch->qid)) {
        case Qctl:
@@ -540,9 +541,13 @@ static char *alarm_chaninfo(struct chan *ch, char *ret, size_t ret_l)
        case Qperiod:
        case Qcount:
                a = QID2A(ch->qid);
-               snprintf(ret, ret_l, "Id %d, %s, expires %llu, period %llu, count %llu",
-                        a->id, SLIST_EMPTY(&a->fd_taps) ? "untapped" : "tapped",
-                        a->a_waiter.wake_up_time, a->period, a->count);
+               ts = tsc2timespec(a->a_waiter.wake_up_time);
+               snprintf(ret, ret_l,
+                        "Id %d, %s, expires [%7d.%09d] (%p), period %llu, count %llu",
+                        a->id,
+                        SLIST_EMPTY(&a->fd_taps) ? "untapped" : "tapped",
+                        ts.tv_sec, ts.tv_nsec, a->a_waiter.wake_up_time,
+                        a->period, a->count);
                break;
        default:
                return devchaninfo(ch, ret, ret_l);
index cc3008d..79aec94 100644 (file)
@@ -356,16 +356,25 @@ void set_pcpu_alarm_interrupt(struct timer_chain *tchain)
 void print_chain(struct timer_chain *tchain)
 {
        struct alarm_waiter *i;
+       struct timespec x = {0}, y = {0};
+
        spin_lock_irqsave(&tchain->lock);
-       printk("Chain %p is%s empty, early: %llu latest: %llu\n", tchain,
-              TAILQ_EMPTY(&tchain->waiters) ? "" : " not",
-              tchain->earliest_time,
-              tchain->latest_time);
+       if (TAILQ_EMPTY(&tchain->waiters)) {
+               printk("Chain %p is empty\n", tchain);
+               spin_unlock_irqsave(&tchain->lock);
+               return;
+       }
+       x = tsc2timespec(tchain->earliest_time);
+       y = tsc2timespec(tchain->latest_time);
+       printk("Chain %p:  earliest: [%7d.%09d] latest: [%7d.%09d]\n",
+              tchain, x.tv_sec, x.tv_nsec, y.tv_sec, y.tv_nsec);
        TAILQ_FOREACH(i, &tchain->waiters, next) {
                uintptr_t f = (uintptr_t)i->func;
 
-               printk("\tWaiter %p, time %llu, func %p (%s)\n", i,
-                      i->wake_up_time, f, get_fn_name(f));
+               x = tsc2timespec(i->wake_up_time);
+               printk("\tWaiter %p, time [%7d.%09d] (%p), func %p (%s)\n",
+                      i, x.tv_sec, x.tv_nsec, i->wake_up_time, f,
+                      get_fn_name(f));
        }
        spin_unlock_irqsave(&tchain->lock);
 }
@@ -374,7 +383,10 @@ void print_chain(struct timer_chain *tchain)
 void print_pcpu_chains(void)
 {
        struct timer_chain *pcpu_chain;
-       printk("PCPU Chains:  It is now %llu\n", read_tsc());
+       struct timespec ts;
+
+       ts = tsc2timespec(read_tsc());
+       printk("PCPU Chains:  It is now [%7d.%09d]\n", ts.tv_sec, ts.tv_nsec);
 
        for (int i = 0; i < num_cores; i++) {
                pcpu_chain = &per_cpu_info[i].tchain;