Date: Fri, 3 Oct 2014 10:46:02 -0700 From: Adrian Chadd <adrian@freebsd.org> To: Ian Lepore <ian@freebsd.org> Cc: "freebsd-hackers@freebsd.org" <freebsd-hackers@freebsd.org>, Paul Albrecht <palbrecht@glccom.com> Subject: Re: freebsd 10 kqueue timer regression Message-ID: <CAJ-Vmo=ApRriVD_tJ0Y6_p1RVkGtrinaHaxGX0Mb0GeXBGgKAQ@mail.gmail.com> In-Reply-To: <1412297389.12052.46.camel@revolution.hippie.lan> References: <8ABC0977-FB8F-45E7-ACCC-BFA92EE22E1C@glccom.com> <CAJ-VmokPNgckHiR0znp6p4u2NRO0aOR_eaOVaBWe7cWDp2_o5g@mail.gmail.com> <1412279608.12052.24.camel@revolution.hippie.lan> <201410021600.17740.jhb@freebsd.org> <1412288106.12052.39.camel@revolution.hippie.lan> <1412297389.12052.46.camel@revolution.hippie.lan>
next in thread | previous in thread | raw e-mail | index | archive | help
Hi,
You could compile in KTR and get a KTR trace of the individual callouts firing.
(Or, dtrace, if you prefer and it's working on your platform.)
That'll tell you what's being queued at what time and what interval,
then when it's firing. It should then explain why the tests are
failing.
I'll see about doing that today - I have a -HEAD box I've been using
for testing timers/callouts on and it should still have the relevant
KTR bits enabled.
-a
On 2 October 2014 17:49, Ian Lepore <ian@freebsd.org> wrote:
> On Thu, 2014-10-02 at 16:15 -0600, Ian Lepore wrote:
>> On Thu, 2014-10-02 at 16:00 -0400, John Baldwin wrote:
>> > On Thursday, October 02, 2014 3:53:28 pm Ian Lepore wrote:
>> > > On Thu, 2014-10-02 at 12:47 -0700, Adrian Chadd wrote:
>> > > > I'm confused; it's doing 50 loops of a 20msec timer, right? So that's
>> > 1000ms.
>> > >
>> > > Yes, so the entire loop should take 1000ms maybe + 1ms. Instead it
>> > > takes 1070. When I run it on an armv6 system running -current it takes
>> > > 1050. When I run it on my 8.4 desktop (pre-eventtimers) it takes 1013.
>> > >
>> > > -- Ian
>> >
>> > What if you set kern.eventtimer.periodic=1?
>> >
>>
>> Some interesting results...
>>
>> HZ 100 500 1000
>> ---------------------------------
>> periodic=0 1050 1050 1080
>> periodic=1 1110 1012 1049
>>
>>
>> The 1080 number was +/- 3ms, all the other numbers were +/- 1ms (except
>> for one outlier of 24363 at 100Hz non-periodic which I'm going to
>> pretend didn't happen).
>>
>> The 1050 numbers are probably each 20ms sleep actually taking 21ms, but
>> the old tvtohz code with -1 adjustments from the old email thread isn't
>> in play anymore. I don't know how to account for the other numbers at
>> all. There's all kinds of stuff I don't understand in the new code
>> involving tick thresholds and such.
>>
>> -- Ian
>>
>
> The attached patch seems to fix the problem in what I think is the most
> correct way: scheduling the callout with absolute times based on the
> time the current event was scheduled for plus the requested interval.
> The net effect should be metronomic events that do not drift (or phase
> shift if you prefer) over time, regardless of any latency involved in
> processing the events.
>
> This makes all the numbers in the tests I ran above come out 1000.
>
> It doesn't make me understand the strange results from the prior tests
> any better.
>
> -- Ian
>
>
> Index: sys/sys/event.h
> ===================================================================
> --- sys/sys/event.h (revision 272181)
> +++ sys/sys/event.h (working copy)
> @@ -221,6 +221,7 @@ struct knote {
> struct proc *p_proc; /* proc pointer */
> struct aiocblist *p_aio; /* AIO job pointer */
> struct aioliojob *p_lio; /* LIO job pointer */
> + sbintime_t *p_nexttime; /* next timer event fires at */
> void *p_v; /* generic other pointer */
> } kn_ptr;
> struct filterops *kn_fop;
> Index: sys/kern/kern_event.c
> ===================================================================
> --- sys/kern/kern_event.c (revision 272181)
> +++ sys/kern/kern_event.c (working copy)
> @@ -569,9 +569,10 @@ filt_timerexpire(void *knx)
>
> if ((kn->kn_flags & EV_ONESHOT) != EV_ONESHOT) {
> calloutp = (struct callout *)kn->kn_hook;
> - callout_reset_sbt_on(calloutp,
> - timer2sbintime(kn->kn_sdata, kn->kn_sfflags), 0,
> - filt_timerexpire, kn, PCPU_GET(cpuid), 0);
> + *kn->kn_ptr.p_nexttime += timer2sbintime(kn->kn_sdata,
> + kn->kn_sfflags);
> + callout_reset_sbt_on(calloutp, *kn->kn_ptr.p_nexttime, 0,
> + filt_timerexpire, kn, PCPU_GET(cpuid), C_ABSOLUTE);
> }
> }
>
> @@ -607,11 +608,13 @@ filt_timerattach(struct knote *kn)
>
> kn->kn_flags |= EV_CLEAR; /* automatically set */
> kn->kn_status &= ~KN_DETACHED; /* knlist_add clears it */
> + kn->kn_ptr.p_nexttime = malloc(sizeof(sbintime_t), M_KQUEUE, M_WAITOK);
> calloutp = malloc(sizeof(*calloutp), M_KQUEUE, M_WAITOK);
> callout_init(calloutp, CALLOUT_MPSAFE);
> kn->kn_hook = calloutp;
> - callout_reset_sbt_on(calloutp, to, 0,
> - filt_timerexpire, kn, PCPU_GET(cpuid), 0);
> + *kn->kn_ptr.p_nexttime = to + sbinuptime();
> + callout_reset_sbt_on(calloutp, *kn->kn_ptr.p_nexttime, 0,
> + filt_timerexpire, kn, PCPU_GET(cpuid), C_ABSOLUTE);
>
> return (0);
> }
> @@ -625,6 +628,7 @@ filt_timerdetach(struct knote *kn)
> calloutp = (struct callout *)kn->kn_hook;
> callout_drain(calloutp);
> free(calloutp, M_KQUEUE);
> + free(kn->kn_ptr.p_nexttime, M_KQUEUE);
> old = atomic_fetch_sub_explicit(&kq_ncallouts, 1, memory_order_relaxed);
> KASSERT(old > 0, ("Number of callouts cannot become negative"));
> kn->kn_status |= KN_DETACHED; /* knlist_remove sets it */
>
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CAJ-Vmo=ApRriVD_tJ0Y6_p1RVkGtrinaHaxGX0Mb0GeXBGgKAQ>