From owner-freebsd-hackers@FreeBSD.ORG Fri Oct 3 17:46:05 2014 Return-Path: Delivered-To: freebsd-hackers@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 2008DF68; Fri, 3 Oct 2014 17:46:05 +0000 (UTC) Received: from mail-wi0-x236.google.com (mail-wi0-x236.google.com [IPv6:2a00:1450:400c:c05::236]) (using TLSv1 with cipher ECDHE-RSA-RC4-SHA (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 4DF60DB1; Fri, 3 Oct 2014 17:46:04 +0000 (UTC) Received: by mail-wi0-f182.google.com with SMTP id n3so2867738wiv.9 for ; Fri, 03 Oct 2014 10:46:02 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:sender:in-reply-to:references:date:message-id:subject :from:to:cc:content-type; bh=f6N5mVYeKcMB575ZygYSumWjMXlzTtDPCTU2vtQyugQ=; b=oj3r3twB+TpiX1NW4zmzKJTheHxe0oH0NIgmpnh69yD14MSHpdNdy0FEqGVmJdb328 yDtwPuFHIBENPWD9C94NK5w26OyL5mU5nGhgKuuYqFovN+DyW/z1dufrIdQqf8UqB5pi n02WdgTTP4Ip8JLnXCYnjH2cieBZGpYX7WT6iOeD+bDf8oMg9ec4ejIRTuH9WMf3keB6 0wZt/ijL3xafbaF6crOcrW7VlvTsXzRdUnyzNaw36cTj9uJTEjlbrA+HXVGNFzP7S6QC 6Cwrgo6MDJ0nIJLKnZKP3Wzi+BCJGdgurl3tt9l6dkEOQddp5ifCUhxy2NeM8E6D9qYh igYQ== MIME-Version: 1.0 X-Received: by 10.194.177.226 with SMTP id ct2mr9663735wjc.20.1412358362621; Fri, 03 Oct 2014 10:46:02 -0700 (PDT) Sender: adrian.chadd@gmail.com Received: by 10.216.106.136 with HTTP; Fri, 3 Oct 2014 10:46:02 -0700 (PDT) In-Reply-To: <1412297389.12052.46.camel@revolution.hippie.lan> References: <8ABC0977-FB8F-45E7-ACCC-BFA92EE22E1C@glccom.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> Date: Fri, 3 Oct 2014 10:46:02 -0700 X-Google-Sender-Auth: vFmIDKZ133v5fmGxd_e9mBJH7vQ Message-ID: Subject: Re: freebsd 10 kqueue timer regression From: Adrian Chadd To: Ian Lepore Content-Type: text/plain; charset=UTF-8 Cc: "freebsd-hackers@freebsd.org" , Paul Albrecht X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.18-1 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 03 Oct 2014 17:46:05 -0000 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 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 */ >