9.1 callout behavior

Wed Dec 4 17:05:17 UTC 2013

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> 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> 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>> 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>> 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>> 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> 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
>>>                 <mailto:freebsd-hackers-unsubscribe at freebsd.org>"
>>>
>>>
>>>
>>>         --
>>>         Alexander Motin
>>>
>>>
>>>
>>
>>
>> --
>> Alexander Motin
>
>