From 4709656009fc8ff74a1d6a8193c6683d39075d84 Mon Sep 17 00:00:00 2001 From: riastradh Date: Mon, 1 May 2023 09:03:19 +0000 Subject: [PATCH] xen_clock(4): Sprinkle dtrace probes. --- sys/arch/xen/xen/xen_clock.c | 89 +++++++++++++++++++++++++++++++----- 1 file changed, 78 insertions(+), 11 deletions(-) diff --git a/sys/arch/xen/xen/xen_clock.c b/sys/arch/xen/xen/xen_clock.c index 3b8aee7e21c5..acc2a30b0aa6 100644 --- a/sys/arch/xen/xen/xen_clock.c +++ b/sys/arch/xen/xen/xen_clock.c @@ -1,4 +1,4 @@ -/* $NetBSD: xen_clock.c,v 1.8 2020/11/30 17:05:02 bouyer Exp $ */ +/* $NetBSD: xen_clock.c,v 1.9 2023/05/01 09:03:19 riastradh Exp $ */ /*- * Copyright (c) 2017, 2018 The NetBSD Foundation, Inc. @@ -36,7 +36,7 @@ #endif #include -__KERNEL_RCSID(0, "$NetBSD: xen_clock.c,v 1.8 2020/11/30 17:05:02 bouyer Exp $"); +__KERNEL_RCSID(0, "$NetBSD: xen_clock.c,v 1.9 2023/05/01 09:03:19 riastradh Exp $"); #include #include @@ -49,6 +49,7 @@ __KERNEL_RCSID(0, "$NetBSD: xen_clock.c,v 1.8 2020/11/30 17:05:02 bouyer Exp $") #include #include #include +#include #include #include #include @@ -75,6 +76,50 @@ static uint64_t xen_global_systime_ns(void); static unsigned xen_get_timecount(struct timecounter *); static int xen_timer_handler(void *, struct clockframe *); +/* + * dtrace probes + */ +SDT_PROBE_DEFINE7(sdt, xen, clock, tsc__backward, + "uint64_t"/*raw_systime_ns*/, + "uint64_t"/*tsc_timestamp*/, + "uint64_t"/*tsc_to_system_mul*/, + "int"/*tsc_shift*/, + "uint64_t"/*delta_ns*/, + "uint64_t"/*tsc*/, + "uint64_t"/*systime_ns*/); +SDT_PROBE_DEFINE7(sdt, xen, clock, tsc__delta__negative, + "uint64_t"/*raw_systime_ns*/, + "uint64_t"/*tsc_timestamp*/, + "uint64_t"/*tsc_to_system_mul*/, + "int"/*tsc_shift*/, + "uint64_t"/*delta_ns*/, + "uint64_t"/*tsc*/, + "uint64_t"/*systime_ns*/); +SDT_PROBE_DEFINE7(sdt, xen, clock, systime__wraparound, + "uint64_t"/*raw_systime_ns*/, + "uint64_t"/*tsc_timestamp*/, + "uint64_t"/*tsc_to_system_mul*/, + "int"/*tsc_shift*/, + "uint64_t"/*delta_ns*/, + "uint64_t"/*tsc*/, + "uint64_t"/*systime_ns*/); +SDT_PROBE_DEFINE7(sdt, xen, clock, systime__backward, + "uint64_t"/*raw_systime_ns*/, + "uint64_t"/*tsc_timestamp*/, + "uint64_t"/*tsc_to_system_mul*/, + "int"/*tsc_shift*/, + "uint64_t"/*delta_ns*/, + "uint64_t"/*tsc*/, + "uint64_t"/*systime_ns*/); + +SDT_PROBE_DEFINE2(sdt, xen, hardclock, systime__backward, + "uint64_t"/*last_systime_ns*/, + "uint64_t"/*this_systime_ns*/); +SDT_PROBE_DEFINE3(sdt, xen, hardclock, missed, + "uint64_t"/*last_systime_ns*/, + "uint64_t"/*this_systime_ns*/, + "uint64_t"/*remaining_ns*/); + /* * xen timecounter: * @@ -277,7 +322,11 @@ xen_vcputime_systime_ns(void) * Notify the console that the CPU's tsc appeared to * run behind Xen's idea of it, and pretend it hadn't. */ -#if XEN_CLOCK_DEBUG /* XXX dtrace hook */ + SDT_PROBE7(sdt, xen, clock, tsc__backward, + raw_systime_ns, tsc_timestamp, + tsc_to_system_mul, tsc_shift, /*delta_ns*/0, tsc, + /*systime_ns*/raw_systime_ns); +#if XEN_CLOCK_DEBUG device_printf(ci->ci_dev, "xen cpu tsc %"PRIu64 " ran backwards from timestamp %"PRIu64 " by %"PRIu64"\n", @@ -301,9 +350,13 @@ xen_vcputime_systime_ns(void) * This doesn't make sense but I include it out of paranoia. */ if (__predict_false((int64_t)delta_ns < 0)) { -#if XEN_CLOCK_DEBUG /* XXX dtrace hook */ - device_printf(ci->ci_dev, "xen tsc delta in ns went negative: %"PRId64"\n", - delta_ns); + SDT_PROBE7(sdt, xen, clock, tsc__delta__negative, + raw_systime_ns, tsc_timestamp, + tsc_to_system_mul, tsc_shift, delta_ns, tsc, + /*systime_ns*/raw_systime_ns); +#if XEN_CLOCK_DEBUG + device_printf(ci->ci_dev, "xen tsc delta in ns went negative:" + " %"PRId64"\n", delta_ns); #endif ci->ci_xen_tsc_delta_negative_evcnt.ev_count++; delta_ns = 0; @@ -322,7 +375,11 @@ xen_vcputime_systime_ns(void) * (2^64 ns is approximately half a millennium.) */ if (__predict_false(systime_ns < raw_systime_ns)) { -#if XEN_CLOCK_DEBUG /* XXX dtrace hook */ + SDT_PROBE7(sdt, xen, clock, systime__wraparound, + raw_systime_ns, tsc_timestamp, + tsc_to_system_mul, tsc_shift, delta_ns, tsc, + systime_ns); +#if XEN_CLOCK_DEBUG printf("xen raw systime + tsc delta wrapped around:" " %"PRIu64" + %"PRIu64" = %"PRIu64"\n", raw_systime_ns, delta_ns, systime_ns); @@ -336,7 +393,11 @@ xen_vcputime_systime_ns(void) * forward. This seems to happen pretty regularly under load. */ if (__predict_false(ci->ci_xen_last_systime_ns > systime_ns)) { -#if XEN_CLOCK_DEBUG /* XXX dtrace hook */ + SDT_PROBE7(sdt, xen, clock, systime__backward, + raw_systime_ns, tsc_timestamp, + tsc_to_system_mul, tsc_shift, delta_ns, tsc, + systime_ns); +#if XEN_CLOCK_DEBUG printf("xen raw systime + tsc delta went backwards:" " %"PRIu64" > %"PRIu64"\n", ci->ci_xen_last_systime_ns, systime_ns); @@ -692,8 +753,11 @@ again: last = ci->ci_xen_hardclock_systime_ns; now = xen_vcputime_systime_ns(); if (now < last) { -#if XEN_CLOCK_DEBUG /* XXX dtrace hook */ - device_printf(ci->ci_dev, "xen systime ran backwards in hardclock %"PRIu64"ns\n", + SDT_PROBE2(sdt, xen, hardclock, systime__backward, + last, now); +#if XEN_CLOCK_DEBUG + device_printf(ci->ci_dev, "xen systime ran backwards" + " in hardclock %"PRIu64"ns\n", last - now); #endif ci->ci_xen_systime_backwards_hardclock_evcnt.ev_count++; @@ -710,8 +774,11 @@ again: ci->ci_xen_hardclock_systime_ns += NS_PER_TICK; delta -= NS_PER_TICK; hardclock(frame); - if (__predict_false(delta >= NS_PER_TICK)) + if (__predict_false(delta >= NS_PER_TICK)) { + SDT_PROBE3(sdt, xen, hardclock, missed, + last, now, delta); ci->ci_xen_missed_hardclock_evcnt.ev_count++; + } } /*