Date: Fri, 06 Dec 2013 13:43:37 +0200 From: Alexander Motin <mav@FreeBSD.org> To: Bret Ketchum <bcketchum@gmail.com>, Adrian Chadd <adrian@freebsd.org> Cc: "freebsd-hackers@freebsd.org" <freebsd-hackers@freebsd.org> Subject: Re: 9.1 callout behavior Message-ID: <52A1B869.6080407@FreeBSD.org> In-Reply-To: <CAGm6yaSQBVXEQ=8NNLjQ0-1q5jxpBeQT2GCUhhCa4_qqiPX=pQ@mail.gmail.com> References: <CAGm6yaTEFECTYVb94A13TaXMPSLtKLpTbw4iNdgd8SuNF1QDaA@mail.gmail.com> <CAJ-Vmokrchy4pXLvZ21sCV09fQUdYKeUYCEH1U1NdfDBxhyJQg@mail.gmail.com> <5295A261.2060403@FreeBSD.org> <CAGm6yaRAPoiVXuv3HgvJCHBTUYGokLyRLb_n0MQEyRp%2BcJUrqA@mail.gmail.com> <CAGm6yaRRcS1e5b_uo4wq=ArSMxFuuTkrKTgOTcQC9nbLnYi6Yw@mail.gmail.com> <529F4409.9080403@FreeBSD.org> <CAGm6yaRFQZ69gQ_Jv0JG5-ru=XtROV5mz7kONC46LRYoe1XTVg@mail.gmail.com> <CAJ-VmonJg-Lsbijc1PnqKt%2BAfmjLxkQpXbKQ4R90bWq7QoXkJQ@mail.gmail.com> <CAGm6yaT=6b6AxDxgivP1jUBmNG1Ynrh58tvhhtZ-qW%2BMKpbj3w@mail.gmail.com> <CAGm6yaSQBVXEQ=8NNLjQ0-1q5jxpBeQT2GCUhhCa4_qqiPX=pQ@mail.gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
On 06.12.2013 13:41, Bret Ketchum wrote: > Any luck in recreating? Nope. I've tried with and without deep C-states enabled and still no any error messages on console. > On Wed, Dec 4, 2013 at 11:14 AM, Bret Ketchum <bcketchum@gmail.com > <mailto:bcketchum@gmail.com>> wrote: > > dev.cpu.0.%desc: ACPI CPU > dev.cpu.0.%driver: cpu > dev.cpu.0.%location: handle=\_PR_.CPU1 > dev.cpu.0.%pnpinfo: _HID=none _UID=0 > dev.cpu.0.%parent: acpi0 > dev.cpu.0.freq_levels: 2700/-1 2362/-1 2025/-1 1687/-1 1350/-1 > 1012/-1 675/-1 337/-1 > dev.cpu.0.cx_supported: C1/1 C2/41 > dev.cpu.0.cx_lowest: C1 > dev.cpu.0.cx_usage: 100.00% 0.00% last 17444us > dev.cpu.1.%desc: ACPI CPU > dev.cpu.1.%driver: cpu > dev.cpu.1.%location: handle=\_PR_.CPU2 > dev.cpu.1.%pnpinfo: _HID=none _UID=0 > dev.cpu.1.%parent: acpi0 > dev.cpu.1.cx_supported: C1/1 C2/41 > dev.cpu.1.cx_lowest: C1 > dev.cpu.1.cx_usage: 100.00% 0.00% last 111391us > dev.cpu.2.%desc: ACPI CPU > dev.cpu.2.%driver: cpu > dev.cpu.2.%location: handle=\_PR_.CPU3 > dev.cpu.2.%pnpinfo: _HID=none _UID=0 > dev.cpu.2.%parent: acpi0 > dev.cpu.2.cx_supported: C1/1 C2/41 > dev.cpu.2.cx_lowest: C1 > dev.cpu.2.cx_usage: 100.00% 0.00% last 84732us > dev.cpu.3.%desc: ACPI CPU > dev.cpu.3.%driver: cpu > dev.cpu.3.%location: handle=\_PR_.CPU4 > dev.cpu.3.%pnpinfo: _HID=none _UID=0 > dev.cpu.3.%parent: acpi0 > dev.cpu.3.cx_supported: C1/1 C2/41 > dev.cpu.3.cx_lowest: C1 > dev.cpu.3.cx_usage: 100.00% 0.00% last 98118us > dev.cpu.4.%desc: ACPI CPU > dev.cpu.4.%driver: cpu > dev.cpu.4.%location: handle=\_PR_.CPU5 > dev.cpu.4.%pnpinfo: _HID=none _UID=0 > dev.cpu.4.%parent: acpi0 > dev.cpu.4.cx_supported: C1/1 C2/41 > dev.cpu.4.cx_lowest: C1 > dev.cpu.4.cx_usage: 100.00% 0.00% last 20991us > dev.cpu.5.%desc: ACPI CPU > dev.cpu.5.%driver: cpu > dev.cpu.5.%location: handle=\_PR_.CPU6 > dev.cpu.5.%pnpinfo: _HID=none _UID=0 > dev.cpu.5.%parent: acpi0 > dev.cpu.5.cx_supported: C1/1 C2/41 > dev.cpu.5.cx_lowest: C1 > dev.cpu.5.cx_usage: 100.00% 0.00% last 115281us > dev.cpu.6.%desc: ACPI CPU > dev.cpu.6.%driver: cpu > dev.cpu.6.%location: handle=\_PR_.CPU7 > dev.cpu.6.%pnpinfo: _HID=none _UID=0 > dev.cpu.6.%parent: acpi0 > dev.cpu.6.cx_supported: C1/1 C2/41 > dev.cpu.6.cx_lowest: C1 > dev.cpu.6.cx_usage: 100.00% 0.00% last 206us > dev.cpu.7.%desc: ACPI CPU > dev.cpu.7.%driver: cpu > dev.cpu.7.%location: handle=\_PR_.CPU8 > dev.cpu.7.%pnpinfo: _HID=none _UID=0 > dev.cpu.7.%parent: acpi0 > dev.cpu.7.cx_supported: C1/1 C2/41 > dev.cpu.7.cx_lowest: C1 > dev.cpu.7.cx_usage: 100.00% 0.00% last 111706us > dev.cpu.8.%desc: ACPI CPU > dev.cpu.8.%driver: cpu > dev.cpu.8.%location: handle=\_PR_.CPU9 > dev.cpu.8.%pnpinfo: _HID=none _UID=0 > dev.cpu.8.%parent: acpi0 > dev.cpu.8.cx_supported: C1/1 C2/41 > dev.cpu.8.cx_lowest: C1 > dev.cpu.8.cx_usage: 100.00% 0.00% last 86986us > dev.cpu.9.%desc: ACPI CPU > dev.cpu.9.%driver: cpu > dev.cpu.9.%location: handle=\_PR_.CPUA > dev.cpu.9.%pnpinfo: _HID=none _UID=0 > dev.cpu.9.%parent: acpi0 > dev.cpu.9.cx_supported: C1/1 C2/41 > dev.cpu.9.cx_lowest: C1 > dev.cpu.9.cx_usage: 100.00% 0.00% last 68431us > dev.cpu.10.%desc: ACPI CPU > dev.cpu.10.%driver: cpu > dev.cpu.10.%location: handle=\_PR_.CPUB > dev.cpu.10.%pnpinfo: _HID=none _UID=0 > dev.cpu.10.%parent: acpi0 > dev.cpu.10.cx_supported: C1/1 C2/41 > dev.cpu.10.cx_lowest: C1 > dev.cpu.10.cx_usage: 100.00% 0.00% last 109210us > dev.cpu.11.%desc: ACPI CPU > dev.cpu.11.%driver: cpu > dev.cpu.11.%location: handle=\_PR_.CPUC > dev.cpu.11.%pnpinfo: _HID=none _UID=0 > dev.cpu.11.%parent: acpi0 > dev.cpu.11.cx_supported: C1/1 C2/41 > dev.cpu.11.cx_lowest: C1 > dev.cpu.11.cx_usage: 100.00% 0.00% last 104907us > dev.cpu.12.%desc: ACPI CPU > dev.cpu.12.%driver: cpu > dev.cpu.12.%location: handle=\_PR_.CPUD > dev.cpu.12.%pnpinfo: _HID=none _UID=0 > dev.cpu.12.%parent: acpi0 > dev.cpu.12.cx_supported: C1/1 C2/41 > dev.cpu.12.cx_lowest: C1 > dev.cpu.12.cx_usage: 100.00% 0.00% last 103771us > dev.cpu.13.%desc: ACPI CPU > dev.cpu.13.%driver: cpu > dev.cpu.13.%location: handle=\_PR_.CPUE > dev.cpu.13.%pnpinfo: _HID=none _UID=0 > dev.cpu.13.%parent: acpi0 > dev.cpu.13.cx_supported: C1/1 C2/41 > dev.cpu.13.cx_lowest: C1 > dev.cpu.13.cx_usage: 100.00% 0.00% last 105845us > dev.cpu.14.%desc: ACPI CPU > dev.cpu.14.%driver: cpu > dev.cpu.14.%location: handle=\_PR_.CPUF > dev.cpu.14.%pnpinfo: _HID=none _UID=0 > dev.cpu.14.%parent: acpi0 > dev.cpu.14.cx_supported: C1/1 C2/41 > dev.cpu.14.cx_lowest: C1 > dev.cpu.14.cx_usage: 100.00% 0.00% last 83902us > dev.cpu.15.%desc: ACPI CPU > dev.cpu.15.%driver: cpu > dev.cpu.15.%location: handle=\_PR_.CPUG > dev.cpu.15.%pnpinfo: _HID=none _UID=0 > dev.cpu.15.%parent: acpi0 > dev.cpu.15.cx_supported: C1/1 C2/41 > dev.cpu.15.cx_lowest: C1 > dev.cpu.15.cx_usage: 100.00% 0.00% last 121122us > dev.cpu.16.%desc: ACPI CPU > dev.cpu.16.%driver: cpu > dev.cpu.16.%location: handle=\_PR_.CP17 > dev.cpu.16.%pnpinfo: _HID=none _UID=0 > dev.cpu.16.%parent: acpi0 > dev.cpu.16.cx_supported: C1/1 C2/41 > dev.cpu.16.cx_lowest: C1 > dev.cpu.16.cx_usage: 100.00% 0.00% last 87619us > dev.cpu.17.%desc: ACPI CPU > dev.cpu.17.%driver: cpu > dev.cpu.17.%location: handle=\_PR_.CP18 > dev.cpu.17.%pnpinfo: _HID=none _UID=0 > dev.cpu.17.%parent: acpi0 > dev.cpu.17.cx_supported: C1/1 C2/41 > dev.cpu.17.cx_lowest: C1 > dev.cpu.17.cx_usage: 100.00% 0.00% last 240us > dev.cpu.18.%desc: ACPI CPU > dev.cpu.18.%driver: cpu > dev.cpu.18.%location: handle=\_PR_.CP19 > dev.cpu.18.%pnpinfo: _HID=none _UID=0 > dev.cpu.18.%parent: acpi0 > dev.cpu.18.cx_supported: C1/1 C2/41 > dev.cpu.18.cx_lowest: C1 > dev.cpu.18.cx_usage: 100.00% 0.00% last 86250us > dev.cpu.19.%desc: ACPI CPU > dev.cpu.19.%driver: cpu > dev.cpu.19.%location: handle=\_PR_.CP20 > dev.cpu.19.%pnpinfo: _HID=none _UID=0 > dev.cpu.19.%parent: acpi0 > dev.cpu.19.cx_supported: C1/1 C2/41 > dev.cpu.19.cx_lowest: C1 > dev.cpu.19.cx_usage: 100.00% 0.00% last 68203us > dev.cpu.20.%desc: ACPI CPU > dev.cpu.20.%driver: cpu > dev.cpu.20.%location: handle=\_PR_.CP21 > dev.cpu.20.%pnpinfo: _HID=none _UID=0 > dev.cpu.20.%parent: acpi0 > dev.cpu.20.cx_supported: C1/1 C2/41 > dev.cpu.20.cx_lowest: C1 > dev.cpu.20.cx_usage: 100.00% 0.00% last 40696us > dev.cpu.21.%desc: ACPI CPU > dev.cpu.21.%driver: cpu > dev.cpu.21.%location: handle=\_PR_.CP22 > dev.cpu.21.%pnpinfo: _HID=none _UID=0 > dev.cpu.21.%parent: acpi0 > dev.cpu.21.cx_supported: C1/1 C2/41 > dev.cpu.21.cx_lowest: C1 > dev.cpu.21.cx_usage: 100.00% 0.00% last 114239us > dev.cpu.22.%desc: ACPI CPU > dev.cpu.22.%driver: cpu > dev.cpu.22.%location: handle=\_PR_.CP23 > dev.cpu.22.%pnpinfo: _HID=none _UID=0 > dev.cpu.22.%parent: acpi0 > dev.cpu.22.cx_supported: C1/1 C2/41 > dev.cpu.22.cx_lowest: C1 > dev.cpu.22.cx_usage: 100.00% 0.00% last 78379us > dev.cpu.23.%desc: ACPI CPU > dev.cpu.23.%driver: cpu > dev.cpu.23.%location: handle=\_PR_.CP24 > dev.cpu.23.%pnpinfo: _HID=none _UID=0 > dev.cpu.23.%parent: acpi0 > dev.cpu.23.cx_supported: C1/1 C2/41 > dev.cpu.23.cx_lowest: C1 > dev.cpu.23.cx_usage: 100.00% 0.00% last 80713us > dev.cpu.24.%desc: ACPI CPU > dev.cpu.24.%driver: cpu > dev.cpu.24.%location: handle=\_PR_.CP25 > dev.cpu.24.%pnpinfo: _HID=none _UID=0 > dev.cpu.24.%parent: acpi0 > dev.cpu.24.cx_supported: C1/1 C2/41 > dev.cpu.24.cx_lowest: C1 > dev.cpu.24.cx_usage: 100.00% 0.00% last 33025us > dev.cpu.25.%desc: ACPI CPU > dev.cpu.25.%driver: cpu > dev.cpu.25.%location: handle=\_PR_.CP26 > dev.cpu.25.%pnpinfo: _HID=none _UID=0 > dev.cpu.25.%parent: acpi0 > dev.cpu.25.cx_supported: C1/1 C2/41 > dev.cpu.25.cx_lowest: C1 > dev.cpu.25.cx_usage: 100.00% 0.00% last 100546us > dev.cpu.26.%desc: ACPI CPU > dev.cpu.26.%driver: cpu > dev.cpu.26.%location: handle=\_PR_.CP27 > dev.cpu.26.%pnpinfo: _HID=none _UID=0 > dev.cpu.26.%parent: acpi0 > dev.cpu.26.cx_supported: C1/1 C2/41 > dev.cpu.26.cx_lowest: C1 > dev.cpu.26.cx_usage: 100.00% 0.00% last 39748us > dev.cpu.27.%desc: ACPI CPU > dev.cpu.27.%driver: cpu > dev.cpu.27.%location: handle=\_PR_.CP28 > dev.cpu.27.%pnpinfo: _HID=none _UID=0 > dev.cpu.27.%parent: acpi0 > dev.cpu.27.cx_supported: C1/1 C2/41 > dev.cpu.27.cx_lowest: C1 > dev.cpu.27.cx_usage: 100.00% 0.00% last 83317us > dev.cpu.28.%desc: ACPI CPU > dev.cpu.28.%driver: cpu > dev.cpu.28.%location: handle=\_PR_.CP29 > dev.cpu.28.%pnpinfo: _HID=none _UID=0 > dev.cpu.28.%parent: acpi0 > dev.cpu.28.cx_supported: C1/1 C2/41 > dev.cpu.28.cx_lowest: C1 > dev.cpu.28.cx_usage: 100.00% 0.00% last 85644us > dev.cpu.29.%desc: ACPI CPU > dev.cpu.29.%driver: cpu > dev.cpu.29.%location: handle=\_PR_.CP30 > dev.cpu.29.%pnpinfo: _HID=none _UID=0 > dev.cpu.29.%parent: acpi0 > dev.cpu.29.cx_supported: C1/1 C2/41 > dev.cpu.29.cx_lowest: C1 > dev.cpu.29.cx_usage: 100.00% 0.00% last 98535us > dev.cpu.30.%desc: ACPI CPU > dev.cpu.30.%driver: cpu > dev.cpu.30.%location: handle=\_PR_.CP31 > dev.cpu.30.%pnpinfo: _HID=none _UID=0 > dev.cpu.30.%parent: acpi0 > dev.cpu.30.cx_supported: C1/1 C2/41 > dev.cpu.30.cx_lowest: C1 > dev.cpu.30.cx_usage: 100.00% 0.00% last 105936us > dev.cpu.31.%desc: ACPI CPU > dev.cpu.31.%driver: cpu > dev.cpu.31.%location: handle=\_PR_.CP32 > dev.cpu.31.%pnpinfo: _HID=none _UID=0 > dev.cpu.31.%parent: acpi0 > dev.cpu.31.cx_supported: C1/1 C2/41 > dev.cpu.31.cx_lowest: C1 > dev.cpu.31.cx_usage: 100.00% 0.00% last 85967us > > > > On Wed, Dec 4, 2013 at 11:05 AM, Adrian Chadd <adrian@freebsd.org > <mailto:adrian@freebsd.org>> wrote: > > Hi, > > What C states are you allowing the system to go into? > > sysctl dev.cpu > > > > -a > > > On 4 December 2013 08:09, Bret Ketchum <bcketchum@gmail.com > <mailto:bcketchum@gmail.com>> 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 > <mav@freebsd.org <mailto:mav@freebsd.org>> 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 > <bcketchum@gmail.com <mailto:bcketchum@gmail.com> > >>> <mailto:bcketchum@gmail.com <mailto:bcketchum@gmail.com>>> > 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 > <mav@freebsd.org <mailto:mav@freebsd.org> > >>> <mailto:mav@freebsd.org <mailto:mav@freebsd.org>>> 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 > <bcketchum@gmail.com <mailto:bcketchum@gmail.com> > >>> <mailto:bcketchum@gmail.com > <mailto:bcketchum@gmail.com>>> 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 > <mailto:freebsd-hackers@freebsd.org> > >>> <mailto:freebsd-hackers@freebsd.org > <mailto:freebsd-hackers@freebsd.org>> mailing list > >>> > >>> http://lists.freebsd.org/__mailman/listinfo/freebsd-__hackers > >>> > >>> > >>> <http://lists.freebsd.org/mailman/listinfo/freebsd-hackers>; > >>> To unsubscribe, send any mail to > >>> "freebsd-hackers-unsubscribe@__freebsd.org > <http://freebsd.org>; > >>> > <mailto:freebsd-hackers-unsubscribe@freebsd.org > <mailto:freebsd-hackers-unsubscribe@freebsd.org>>" > >>> > >>> > >>> > >>> -- > >>> Alexander Motin > >>> > >>> > >>> > >> > >> > >> -- > >> Alexander Motin > > > > > > > -- Alexander Motin
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?52A1B869.6080407>