[PATCH] latency-profiling

[PATCH] latency-profiling

[Roger Larsson]

[-- Attachment #1: Type: text/plain, Size: 3639 bytes --]

Hi,

I ported my old latency-profiling patch to 2.4.10-pre10 with
the reschedulable kernel patch. (I have not checked that it is
preemption safe itself...)

This patch works a little different from Robert Loves.
Since it samples the execution location at ticks.
It is possible to instrument an ordinary kernel too...
These are the results (>5 ms):

Sep 19 20:09:28 jeloin kernel: Latency  17ms PID   316 %% ifconfig
Sep 19 20:09:28 jeloin kernel: Trace: 
[mousedev:__insmod_mousedev_O/lib/modules/2.4.10-pre10/kernel/drivers+-93829/96] 
[__rdtsc_delay+20/28]
Sep 19 20:12:48 jeloin kernel: Latency  10ms PID   870 %% artsd
Sep 19 20:12:48 jeloin kernel: Trace: [console_softint+230/232] 
[__rdtsc_delay+20/28]
Sep 19 20:13:28 jeloin kernel: Latency   8ms PID   667 %% X
Sep 19 20:13:28 jeloin kernel: Trace: [__rdtsc_delay+22/28]
Sep 19 20:13:53 jeloin kernel: Latency  35ms PID   972 %% bash
Sep 19 20:13:53 jeloin kernel: Trace: [unmap_buffer+100/132] 
[kmem_cache_free+140/148] [block_flushpage+43/112]
Sep 19 20:14:19 jeloin kernel: Latency  40ms PID   979 %% bash
Sep 19 20:14:19 jeloin kernel: Trace: [__refile_buffer+95/108] 
[block_flushpage+43/112] [remove_inode_page+36/64] [__lru_cache_del+1/272]
Sep 19 20:15:55 jeloin kernel: Latency  21ms PID  1038 %% cp
Sep 19 20:15:55 jeloin kernel: Trace: [truncate_list_pages+200/456] 
[try_to_free_buffers+332/556]
Sep 19 20:32:18 jeloin kernel: Latency   6ms PID     7 %% kupdated
Sep 19 20:32:19 jeloin kernel: Latency   5ms PID  1214 %% mmap002
Sep 19 20:35:18 jeloin kernel: Latency  22ms PID  1214 %% mmap002
Sep 19 20:35:18 jeloin kernel: Trace: [zap_page_range+318/628] 
[zap_page_range+382/628]
Sep 19 21:49:22 jeloin kernel: Latency  10ms PID     0 %% swapper
Sep 19 21:49:22 jeloin kernel: Trace: [schedule+463/1032]
Sep 19 22:37:45 jeloin kernel: Latency   5ms PID  2439 %% y2bignfat
Sep 19 22:37:45 jeloin kernel: Latency   5ms PID  2446 %% y2bignfat
Sep 19 22:46:18 jeloin kernel: Latency   5ms PID  2552 %% y2bignfat
Sep 19 22:46:18 jeloin kernel: Trace: [zap_page_range+382/628]
Sep 19 22:46:18 jeloin kernel: Latency   5ms PID  2555 %% y2bignfat
Sep 19 22:46:18 jeloin kernel: Trace: [zap_page_range+318/628]
Sep 19 22:46:18 jeloin kernel: Latency   5ms PID  2559 %% y2bignfat
Sep 19 22:46:18 jeloin kernel: Latency   5ms PID  2571 %% y2bignfat
Sep 19 22:46:19 jeloin kernel: Latency   5ms PID  2573 %% y2bignfat
Sep 19 22:46:19 jeloin kernel: Latency   5ms PID  2574 %% y2bignfat
Sep 19 22:46:19 jeloin kernel: Latency   5ms PID  2578 %% y2bignfat
Sep 19 22:46:19 jeloin kernel: Latency   5ms PID  2579 %% y2bignfat
Sep 19 22:46:19 jeloin kernel: Trace: [zap_page_range+382/628]
Sep 19 22:46:19 jeloin kernel: Latency   5ms PID  2593 %% y2bignfat
Sep 19 22:46:19 jeloin kernel: Trace: [zap_page_range+318/628]
Sep 19 22:46:19 jeloin kernel: Latency   5ms PID  2594 %% y2bignfat
Sep 19 22:46:20 jeloin kernel: Latency   5ms PID  2596 %% y2bignfat
Sep 20 07:27:57 jeloin kernel: Latency  59ms PID   281 %% cardmgr
Sep 20 07:27:57 jeloin kernel: Trace: [__rdtsc_delay+20/28] 
[__rdtsc_delay+20/28] [__rdtsc_delay+22/28] [__rdtsc_delay+20/28] 
[__rdtsc_delay+20/28]
Sep 20 07:27:57 jeloin kernel: Trace: [__rdtsc_delay+20/28]
Sep 20 07:27:57 jeloin kernel: Latency  24ms PID   316 %% ifconfig
Sep 20 07:27:57 jeloin kernel: Trace: [__rdtsc_delay+20/28] 
[mousedev:__insmod_mousedev_O/lib/modules/2.4.10-pre10/kernel/drivers+-93829/96] 
[mousedev:__insmod_mousedev_O/lib/modules/2.4.10-pre10/kernel/drivers+-93562/96]
Sep 20 07:27:59 jeloin kernel: Latency   8ms PID   649 %% X
Sep 20 07:27:59 jeloin kernel: Trace: [aux_write_ack+54/60]
-- 
Roger Larsson
Skellefteå
Sweden

[-- Attachment #2: latency-profiling-2.4.10-pre10-preempt-r16.patch.gz --]
[-- Type: application/x-gzip, Size: 2178 bytes --]

Re: [PATCH] latency-profiling

[george anzinger]

Roger Larsson wrote:
> 
> Hi,
> 
> I ported my old latency-profiling patch to 2.4.10-pre10 with
> the reschedulable kernel patch. (I have not checked that it is
> preemption safe itself...)
> 
> This patch works a little different from Robert Loves.
> Since it samples the execution location at ticks.
> It is possible to instrument an ordinary kernel too...

It gives experienced latencies rather than potential latencies, but more
important from the developer/maintainers point of view, "Robert Loves"
patch provides information on the bad guys, i.e. the reason for the long
latency, which, hopefully, will allow them to be addressed by competent
maintainers.

George

Re: [PATCH] latency-profiling

[Roger Larsson]

On Thursdayen den 20 September 2001 21.55, george anzinger wrote:
> Roger Larsson wrote:
> > Hi,
> >
> > I ported my old latency-profiling patch to 2.4.10-pre10 with
> > the reschedulable kernel patch. (I have not checked that it is
> > preemption safe itself...)
> >
> > This patch works a little different from Robert Loves.
> > Since it samples the execution location at ticks.
> > It is possible to instrument an ordinary kernel too...
>
> It gives experienced latencies rather than potential latencies, but more
> important from the developer/maintainers point of view, "Robert Loves"
> patch provides information on the bad guys, i.e. the reason for the long
> latency, which, hopefully, will allow them to be addressed by competent
> maintainers.
>

Yes, but my technique can be applied to any kernel. It does not require
an preemptible kernel...

I.e. measures time from the moment a reschedulation was reqired to it
is actually done - independent of how it is done...

And if you run something that needs periodic reshedules you will detect
actual problems.

And thus it can be used as a bench, it is hard to describe skips in music,
textual data is easier to send by mail...

But I agree that Roberts is better to find the critical ones!

/RogerL

-- 
Roger Larsson
Skellefteå
Sweden

Re: [PATCH] latency-profiling

[Karim Yaghmour]

Roger Larsson wrote:
> This patch works a little different from Robert Loves.
> Since it samples the execution location at ticks.
> It is possible to instrument an ordinary kernel too...

You could also try the Linux Trace Toolkit which would provide
you with much more accurate results and exact times instead of
samples. LTT is here: http://www.opersys.com/LTT

Cheers,

Karim

===================================================
                 Karim Yaghmour
               karym@opersys.com
      Embedded and Real-Time Linux Expert
===================================================