9.1 callout behavior
Alexander Motin
mav at FreeBSD.org
Fri Dec 6 11:43:42 UTC 2013
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 at gmail.com
> <mailto:bcketchum at 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 at freebsd.org
> <mailto:adrian at 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 at gmail.com
> <mailto:bcketchum at 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 at freebsd.org <mailto:mav at 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 at gmail.com <mailto:bcketchum at gmail.com>
> >>> <mailto:bcketchum at gmail.com <mailto:bcketchum at 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 at freebsd.org <mailto:mav at freebsd.org>
> >>> <mailto:mav at freebsd.org <mailto:mav at 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 at gmail.com <mailto:bcketchum at gmail.com>
> >>> <mailto:bcketchum at gmail.com
> <mailto:bcketchum at 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 at freebsd.org
> <mailto:freebsd-hackers at freebsd.org>
> >>> <mailto:freebsd-hackers at freebsd.org
> <mailto:freebsd-hackers at 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 at __freebsd.org
> <http://freebsd.org>
> >>>
> <mailto:freebsd-hackers-unsubscribe at freebsd.org
> <mailto:freebsd-hackers-unsubscribe at freebsd.org>>"
> >>>
> >>>
> >>>
> >>> --
> >>> Alexander Motin
> >>>
> >>>
> >>>
> >>
> >>
> >> --
> >> Alexander Motin
> >
> >
>
>
>
--
Alexander Motin
More information about the freebsd-hackers
mailing list