From owner-freebsd-hackers@FreeBSD.ORG Wed Dec 4 17:05:17 2013 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 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 9B7A4347; Wed, 4 Dec 2013 17:05:17 +0000 (UTC) Received: from mail-qa0-x233.google.com (mail-qa0-x233.google.com [IPv6:2607:f8b0:400d:c00::233]) (using TLSv1 with cipher ECDHE-RSA-RC4-SHA (128/128 bits)) (No client certificate requested) by mx1.freebsd.org (Postfix) with ESMTPS id 4501A1FD3; Wed, 4 Dec 2013 17:05:17 +0000 (UTC) Received: by mail-qa0-f51.google.com with SMTP id o15so6862646qap.17 for ; Wed, 04 Dec 2013 09:05:16 -0800 (PST) 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=Y6P9t8oqGWiXeTjh6fuooLYEhp2aj6vjgkWJ7F+XcsI=; b=xeSHpRWbd1BM7dHTFfSfu8Sy4Tiahqg7RLNrNUhemi7ImM6xZ74V7rmJX82Ty3aaI/ /cx8tASCXXzfLjZ6F6O184tPKmkm9phzAkjkjvpOX2xNGwVbCmOyBlHgtYNvSK1G9CxT JT6D595mVHrIU5zPuBy7ae5v+uDXthzwz3tTzZb6PoR6Jk195ZukbWmO/ICnmh2LLyaY JsyNenllUddBwVOJgIoj+pGmdqzbcFscZ35/9yI0wn3dBQ/S+REfP61lYU7LO6I8NTJg XRuwwllV0YCyb2pTLr0YEjT8GpNKqKhP8Vir6RaVHYKVrF6Pw+RY6+tPfm8PIqcLi/9e KfhQ== MIME-Version: 1.0 X-Received: by 10.224.80.129 with SMTP id t1mr97796636qak.95.1386176716404; Wed, 04 Dec 2013 09:05:16 -0800 (PST) Sender: adrian.chadd@gmail.com Received: by 10.224.53.200 with HTTP; Wed, 4 Dec 2013 09:05:16 -0800 (PST) In-Reply-To: References: <5295A261.2060403@FreeBSD.org> <529F4409.9080403@FreeBSD.org> Date: Wed, 4 Dec 2013 09:05:16 -0800 X-Google-Sender-Auth: 0n7vqjT76FDl3C4F6Gc8anyCD-c Message-ID: Subject: Re: 9.1 callout behavior From: Adrian Chadd To: Bret Ketchum Content-Type: text/plain; charset=ISO-8859-1 Cc: "freebsd-hackers@freebsd.org" , Alexander Motin X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.17 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 04 Dec 2013 17:05:17 -0000 Hi, What C states are you allowing the system to go into? sysctl dev.cpu -a On 4 December 2013 08:09, Bret Ketchum wrote: > Dec 4 16:10:42 Aldagautr kernel: Whoops(0) 1335665250 - 1335664940 = 310 > (125039:208) > Dec 4 16:10:42 Aldagautr kernel: 3532533380201277 - 3532533110189730 = 100 > Dec 4 16:10:46 Aldagautr kernel: Whoops(0) 1335669705 - 1335669450 = 255 > (125081:209) > Dec 4 16:10:46 Aldagautr kernel: 3532544993171592 - 3532544723156886 = 100 > Dec 4 16:10:46 Aldagautr kernel: Ouch(0) 1335669805 - 1335669705 = 100 > (125081:210) > Dec 4 16:10:46 Aldagautr kernel: 3532545106580358 - 3532544993171592 = 42 > Dec 4 16:10:51 Aldagautr kernel: Whoops(0) 1335674622 - 1335674406 = 216 > (125127:211) > Dec 4 16:10:51 Aldagautr kernel: 3532557637551168 - 3532557529541286 = 40 > Dec 4 16:10:51 Aldagautr kernel: Ouch(0) 1335674722 - 1335674622 = 100 > (125127:212) > Dec 4 16:10:51 Aldagautr kernel: 3532557856241106 - 3532557637551168 = 80 > Dec 4 16:10:51 Aldagautr kernel: Whoops(0) 1335675136 - 1335675023 = 113 > (125130:213) > Dec 4 16:10:51 Aldagautr kernel: 3532558941667944 - 3532558671656559 = 100 > Dec 4 16:11:02 Aldagautr kernel: Whoops(0) 1335685785 - 1335685544 = 241 > (125234:214) > Dec 4 16:11:02 Aldagautr kernel: 3532587178907223 - 3532587033073221 = 54 > > Not that with kern.eventtimer.periodic set to 1 the problem goes away. > > > On Wed, Dec 4, 2013 at 9:02 AM, Alexander Motin wrote: >> >> On 04.12.2013 14:49, Bret Ketchum wrote: >>> >>> See attached. I've tightened up the definition of inconsistent >>> callout calls. A "Whoops" message indicates the callout function was >>> called either side of a 10ms window than what was expected. "Ouch" >>> indicates the cyclecounter does not agree with the expected period given >>> the same 10ms fudge factor. >> >> >> I have this module running on two of my tests systems with stable/9 >> (2xE5645 and i7-3770) and half hour later I see no any of related messages >> on consoles. Could you share what exactly do you have there logged? >> >>> On Wed, Nov 27, 2013 at 3:28 AM, Bret Ketchum >> > wrote: >>> >>> Alexander, >>> >>> In this scenario, global ticks should have increased by 100 >>> every interval. When the wheels go off the truck, global ticks will >>> be 800+ yet only a fraction of usual number of clock cycles have >>> increased. >>> >>> I'll try to cook up an kernel module which will reproduce. >>> >>> >>> On Wed, Nov 27, 2013 at 1:42 AM, Alexander Motin >> > wrote: >>> >>> Hi, Brett, >>> >>> Could you tell more about "ticks has increased 8x"? Tickless >>> mode it is somewhat tricky algorithm to track global ticks >>> counter, but it should not jump that big. Jumps there could >>> easily trigger wrong callout behavior in 9 (in 10 callout code >>> was rewritten and no longer depend on ticks). >>> >>> >>> On 21.11.2013 22:19, Adrian Chadd wrote: >>> >>> It sounds like you may have found an interesting test case. >>> >>> Mav, any ideas? >>> >>> On 21 November 2013 05:20, Bret Ketchum >> > wrote: >>> >>> I've a callout which runs every 100ms and does a >>> bit of accounting >>> using the global ticks variable. This one-shot callout >>> was called fairly >>> consistently in 8.1, every 100ms give or take a few >>> thousand clocks. I've >>> recently upgraded to 9.1 and for the most part the >>> period is consistent. >>> However, periodically the callout function is executed >>> anywhere between 5ms >>> to 20ms after the callout was reset and the function >>> returned while global >>> ticks has increased 8x. The hardware has not changed >>> (using the same >>> timecounter configuration): >>> >>> CPU: Intel(R) Xeon(R) CPU E5-2640 0 @ 2.50GHz >>> (2500.05-MHz K8-class CPU) >>> >>> kern.timecounter.hardware: TSC-low >>> kern.timecounter.tick: 1 >>> kern.timecounter.invariant___tsc: 1 >>> >>> kern.timecounter.smp_tsc: 1 >>> >>> And default eventtimer configuration: >>> >>> kern.eventtimer.singlemul: 2 >>> kern.eventtimer.idletick: 0 >>> kern.eventtimer.activetick: 1 >>> kern.eventtimer.timer: LAPIC >>> kern.eventtimer.periodic: 0 >>> >>> If tickless mode is disabled the inconsistency >>> goes away. Is the >>> premature expiration of the callout expected? Is the >>> jump in global ticks >>> typical (say from 100 ticks to 800 ticks in 1.5ms)? >>> >>> Bret >>> _________________________________________________ >>> freebsd-hackers@freebsd.org >>> mailing list >>> >>> http://lists.freebsd.org/__mailman/listinfo/freebsd-__hackers >>> >>> >>> >>> To unsubscribe, send any mail to >>> "freebsd-hackers-unsubscribe@__freebsd.org >>> " >>> >>> >>> >>> -- >>> Alexander Motin >>> >>> >>> >> >> >> -- >> Alexander Motin > >