Re: Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-13

["K.R. Foley" <kr@cybsft.com>]

Gene Heskett wrote:
> On Monday 29 November 2004 10:23, Ingo Molnar wrote:
> 
>>* Ingo Molnar <mingo@elte.hu> wrote:
>>
>>>but please try to the -31-10 kernel that i've just uploaded, it
>>>has a number of tracer enhancements:
>>
>>make that -31-13 (or later). Earlier kernels had a bug in where the
>>process name tracking only worked for the first latency trace saved,
>>subsequent traces showed 'unknown' for the process name. In -13 i've
>>also added a printk that shows the latest user latency in a one-line
>>printk - just like the built-in latency tracing modes do:
>>
>>(gettimeofday/3671/CPU#0): new 3068 us user-latency.
>>(gettimeofday/3784/CPU#0): new 1008627 us user-latency.
>>
>>(this should also make it easier for helper scripts to save the
>>traces, whenever they happen.)
>>
>>Ingo
> 
> 
> I just built this to see how much blood it would draw, which isn't 
> much.  I don't have jack here, so I don't have your standard torture 
> test.  Instead, I run tvtime, which runs at a -19 priority.
> 
> I let it run about 30 seconds (untimed), noted that the frame error 
> slippage wasn't improved, and got this output histogram when I quit 
> it.
> 
> Its (tvtime) is running here of course.
> --------------------
> Nov 29 18:05:45 coyote kernel: Read missed before next interrupt
> Nov 29 18:05:45 coyote kernel: wow!  That was a 22 millisec bump
> Nov 29 18:05:45 coyote kernel: `IRQ 8'[846] is being piggy. 
> need_resched=0, cpu=0
> Nov 29 18:05:45 coyote kernel: Read missed before next interrupt
> Nov 29 18:05:45 coyote kernel: wow!  That was a 22 millisec bump
> Nov 29 18:05:45 coyote kernel: `IRQ 8'[846] is being piggy. 
> need_resched=0, cpu=0
> Nov 29 18:05:45 coyote kernel: Read missed before next interrupt
> Nov 29 18:05:45 coyote kernel: wow!  That was a 21 millisec bump
> Nov 29 18:05:45 coyote kernel: `IRQ 8'[846] is being piggy. 
> need_resched=0, cpu=0
> Nov 29 18:05:45 coyote kernel: Read missed before next interrupt
> Nov 29 18:05:45 coyote kernel: wow!  That was a 21 millisec bump
> Nov 29 18:05:45 coyote kernel: `IRQ 8'[846] is being piggy. 
> need_resched=0, cpu=0
> Nov 29 18:05:45 coyote kernel: Read missed before next interrupt
> Nov 29 18:05:45 coyote kernel:
> 
> And was stopped here. 
> 
> Nov 29 18:05:45 coyote kernel: rtc latency histogram of {tvtime/3398, 
> 10609 samples}:
> Nov 29 18:05:45 coyote kernel: 4 11
> Nov 29 18:05:45 coyote kernel: 5 1716
> Nov 29 18:05:45 coyote kernel: 6 4827
> Nov 29 18:05:45 coyote kernel: 7 1495
> Nov 29 18:05:45 coyote kernel: 8 382
> Nov 29 18:05:45 coyote kernel: 9 193
> Nov 29 18:05:45 coyote kernel: 10 206
> Nov 29 18:05:45 coyote kernel: 11 188
> Nov 29 18:05:45 coyote kernel: 12 148
> Nov 29 18:05:45 coyote kernel: 13 202
> Nov 29 18:05:45 coyote kernel: 14 195
> Nov 29 18:05:45 coyote kernel: 15 95
> Nov 29 18:05:45 coyote kernel: 16 70
> Nov 29 18:05:45 coyote kernel: 17 23
> Nov 29 18:05:45 coyote kernel: 18 18
> Nov 29 18:05:45 coyote kernel: 19 8
> Nov 29 18:05:45 coyote kernel: 20 9
> Nov 29 18:05:45 coyote kernel: 21 1
> Nov 29 18:05:45 coyote kernel: 22 1
> Nov 29 18:05:45 coyote kernel: 26 1
> --------------------
> And I note that the 1-26 column of numbers does not seem to add up to 
> whats being logged above there, which are all 21 and 22 ms bumps 
> (whatever a bump is)

Is this all that is in the log? For some reason there are 820 samples 
not represented in the output above. The ms+ hits would have been 
represented by something like:

Nov 29 18:05:45 coyote kernel: 9999 4

Not that it is related to the missing output, but does tvtime use 
polling on the rtc?

kr

> 
> Is this a helpfull report, or just noise?  Subjectively, tvtime is 
> running with far fewer visible frame glitches than before I started 
> playing with these patches.  A marked improvement IMO.
>