2006-03-13 13:49:07

by Mauricio Lin

[permalink] [raw]
Subject: Jiffy is not able to measure the fraction of time a process runs a processor

Hi all,

I am trying to measure the fraction of time a process runs on a
processor, but the jiffies is not able to provide an accurate value.

The example below shows that in one kernel tick or one jiffy, kmix
and lpd was schedule in the same processor and the cpu time of each
one was zero. The calculation of cpu time is based on jiffies and the
cpu time is zero because the jiffy value was not incremented yet.

PID : NAME : LAST ARRIVAL : CPU TIME : CALLER
4544 : kmix : 6170433 : 0
: work_resched+0x6c
4078 : lpd : 6170433 : 0
: __down_interruptible+0x5
4544 : kmix : 6170433 : 0
: schedule_timeout+0xb8


Look again, when jiffies is 6170503 klipper and emacs are scheduled
many times.

4534 : klipper : 6170503 : 0
: preempt_schedule_irq+0xb8
4534 : klipper : 6170503 : 0
: preempt_schedule+0x3d
4534 : klipper : 6170503 : 0
: work_resched+0x34
4534 : klipper : 6170503 : 0
: work_resched+0x5
4534 : klipper : 6170503 : 0
: preempt_schedule+0x5
4534 : klipper : 6170503 : 0
: work_resched+0x34
4534 : klipper : 6170503 : 0
: work_resched+0x5
4534 : klipper : 6170503 : 0
: work_resched+0x5
4534 : klipper : 6170503 : 0
: work_resched+0x5
4534 : klipper : 6170503 : 0
: work_resched+0x5
4534 : klipper : 6170503 : 0
: work_resched+0x5
16150 : emacs : 6170503 : 0
: work_resched+0x5
16150 : emacs : 6170503 : 0
: work_resched+0x5
16150 : emacs : 6170503 : 0
: work_resched+0x5
16150 : emacs : 6170503 : 0
: preempt_schedule+0x5
16150 : emacs : 6170503 : 0
: schedule_timeout+0x34
4534 : klipper : 6170503 : 0
: preempt_schedule+0x6c
4534 : klipper : 6170503 : 0
: work_resched+0x34
4534 : klipper : 6170503 : 0
: work_resched+0x5
4534 : klipper : 6170503 : 0
: schedule_timeout+0x5

Does anyone know how can I measure precisely the fraction of time a
process runs on a processor?

BR,

Mauricio Lin.


2006-03-14 20:54:29

by Frank Ch. Eigler

[permalink] [raw]
Subject: Re: Jiffy is not able to measure the fraction of time a process runs a processor

"Mauricio Lin" <[email protected]> writes:

> I am trying to measure the fraction of time a process runs on a
> processor, but the jiffies is not able to provide an accurate value.

See sched_clock().

> The example below [...]
> PID : NAME : LAST ARRIVAL : CPU TIME : CALLER
> 4544 : kmix : 6170433 : 0 : work_resched+0x6c
> 4078 : lpd : 6170433 : 0 : __down_interruptible+0x5
> 4544 : kmix : 6170433 : 0 : schedule_timeout+0xb8

What tool/patchset are you using to generate this trace?


- FChE

2006-03-15 14:40:36

by Mauricio Lin

[permalink] [raw]
Subject: Re: Jiffy is not able to measure the fraction of time a process runs a processor

Hi all,

I have managed to measure the cpu time in nanoseconds. On i386 I have used
the monotonic_clock() to measure the cpu time accurately.

The cpu time measurements were based on t->sched_info.cpu_time, but
instead of accumulate
the all cpu time, I needed just the diff=jiffies
-t->sched_info.last_arrival in the sched_info_depart().

The problem was most of time the diff was zero. So to solve this
problem I used the monotonic_clock() function that provides more accurate
way to measure cpu time.

Any comments?

On 14 Mar 2006 15:54:17 -0500, Frank Ch. Eigler <[email protected]> wrote:
> "Mauricio Lin" <[email protected]> writes:
>
> > I am trying to measure the fraction of time a process runs on a
> > processor, but the jiffies is not able to provide an accurate value.
>
> See sched_clock().

I have checked it. It helped me to reach the monotonic_clock()
function after hacking the code.

>
> > The example below [...]
> > PID : NAME : LAST ARRIVAL : CPU TIME : CALLER
> > 4544 : kmix : 6170433 : 0 : work_resched+0x6c
> > 4078 : lpd : 6170433 : 0 : __down_interruptible+0x5
> > 4544 : kmix : 6170433 : 0 : schedule_timeout+0xb8
>
> What tool/patchset are you using to generate this trace?

I am using the relayfs to report the information I need among the
processors. I just put some klog in some key points in the code.

BR,

Mauricio Lin.

2006-03-15 15:55:43

by linux-os (Dick Johnson)

[permalink] [raw]
Subject: Re: Jiffy is not able to measure the fraction of time a process runs a processor


On Wed, 15 Mar 2006, Mauricio Lin wrote:

> Hi all,
>
> I have managed to measure the cpu time in nanoseconds. On i386 I have used
> the monotonic_clock() to measure the cpu time accurately.
>
> The cpu time measurements were based on t->sched_info.cpu_time, but
> instead of accumulate
> the all cpu time, I needed just the diff=jiffies
> -t->sched_info.last_arrival in the sched_info_depart().
>
> The problem was most of time the diff was zero. So to solve this
> problem I used the monotonic_clock() function that provides more accurate
> way to measure cpu time.
>
> Any comments?
>
> On 14 Mar 2006 15:54:17 -0500, Frank Ch. Eigler <[email protected]> wrote:
>> "Mauricio Lin" <[email protected]> writes:
>>
>>> I am trying to measure the fraction of time a process runs on a
>>> processor, but the jiffies is not able to provide an accurate value.
>>
>> See sched_clock().
>
> I have checked it. It helped me to reach the monotonic_clock()
> function after hacking the code.
>
>>
>>> The example below [...]
>>> PID : NAME : LAST ARRIVAL : CPU TIME : CALLER
>>> 4544 : kmix : 6170433 : 0 : work_resched+0x6c
>>> 4078 : lpd : 6170433 : 0 : __down_interruptible+0x5
>>> 4544 : kmix : 6170433 : 0 : schedule_timeout+0xb8
>>
>> What tool/patchset are you using to generate this trace?
>
> I am using the relayfs to report the information I need among the
> processors. I just put some klog in some key points in the code.
>
> BR,
>
> Mauricio Lin.

Jiffies changes only 1000 times per second if it's set to 1000.
On a fast CPU this kind of coarse resolution will not give you
any useful information when trying to determine execution time.

You need to use the number of CPU clocks that it has taken.
This is obtained using rdtsc on ix86 machines.

Cheers,
Dick Johnson
Penguin : Linux version 2.6.15.4 on an i686 machine (5589.54 BogoMips).
Warning : 98.36% of all statistics are fiction, book release in April.
_


****************************************************************
The information transmitted in this message is confidential and may be privileged. Any review, retransmission, dissemination, or other use of this information by persons or entities other than the intended recipient is prohibited. If you are not the intended recipient, please notify Analogic Corporation immediately - by replying to this message or by sending an email to [email protected] - and destroy all copies of this information, including any attachments, without reading or disclosing them.

Thank you.

2006-03-15 17:43:12

by Mauricio Lin

[permalink] [raw]
Subject: Re: Jiffy is not able to measure the fraction of time a process runs a processor

Hi,

On 3/15/06, linux-os (Dick Johnson) <[email protected]> wrote:
>
> On Wed, 15 Mar 2006, Mauricio Lin wrote:
>
> > Hi all,
> >
> > I have managed to measure the cpu time in nanoseconds. On i386 I have used
> > the monotonic_clock() to measure the cpu time accurately.
> >
> > The cpu time measurements were based on t->sched_info.cpu_time, but
> > instead of accumulate
> > the all cpu time, I needed just the diff=jiffies
> > -t->sched_info.last_arrival in the sched_info_depart().
> >
> > The problem was most of time the diff was zero. So to solve this
> > problem I used the monotonic_clock() function that provides more accurate
> > way to measure cpu time.
> >
> > Any comments?
> >
> > On 14 Mar 2006 15:54:17 -0500, Frank Ch. Eigler <[email protected]> wrote:
> >> "Mauricio Lin" <[email protected]> writes:
> >>
> >>> I am trying to measure the fraction of time a process runs on a
> >>> processor, but the jiffies is not able to provide an accurate value.
> >>
> >> See sched_clock().
> >
> > I have checked it. It helped me to reach the monotonic_clock()
> > function after hacking the code.
> >
> >>
> >>> The example below [...]
> >>> PID : NAME : LAST ARRIVAL : CPU TIME : CALLER
> >>> 4544 : kmix : 6170433 : 0 : work_resched+0x6c
> >>> 4078 : lpd : 6170433 : 0 : __down_interruptible+0x5
> >>> 4544 : kmix : 6170433 : 0 : schedule_timeout+0xb8
> >>
> >> What tool/patchset are you using to generate this trace?
> >
> > I am using the relayfs to report the information I need among the
> > processors. I just put some klog in some key points in the code.
> >
> > BR,
> >
> > Mauricio Lin.
>
> Jiffies changes only 1000 times per second if it's set to 1000.
> On a fast CPU this kind of coarse resolution will not give you
> any useful information when trying to determine execution time.
>
> You need to use the number of CPU clocks that it has taken.
> This is obtained using rdtsc on ix86 machines.

Yes. The monotonic_clock() can use it, if the timer selected is TSC. I
have checked how monotonic_clock() is implemented and it uses
monotonic_clock_tsc() if the timer used is TSC. monotonic_clock_tsc()
calls rdtscll() that reads the time stamp counter as rdstc() also
does. So probably monotonic_clock() can help me.

Any comments?

BR,

Mauricio Lin.

> Cheers,
> Dick Johnson
> Penguin : Linux version 2.6.15.4 on an i686 machine (5589.54 BogoMips).
> Warning : 98.36% of all statistics are fiction, book release in April.
> _
> 
>
> ****************************************************************
> The information transmitted in this message is confidential and may be privileged. Any review, retransmission, dissemination, or other use of this information by persons or entities other than the intended recipient is prohibited. If you are not the intended recipient, please notify Analogic Corporation immediately - by replying to this message or by sending an email to [email protected] - and destroy all copies of this information, including any attachments, without reading or disclosing them.
>
> Thank you.
>