Jiffy is not able to measure the fraction of time a process runs a processor

Jiffy is not able to measure the fraction of time a process runs a processor

[Mauricio Lin]

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.

Re: Jiffy is not able to measure the fraction of time a process runs a processor

[Frank Ch. Eigler]

"Mauricio Lin" <mauriciolin@gmail.com> 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

Re: Jiffy is not able to measure the fraction of time a process runs a processor

[Mauricio Lin]

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 <fche@redhat.com> wrote:
> "Mauricio Lin" <mauriciolin@gmail.com> 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.

Re: Jiffy is not able to measure the fraction of time a process runs a processor

[linux-os (Dick Johnson)]

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 <fche@redhat.com> wrote:
>> "Mauricio Lin" <mauriciolin@gmail.com> 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.
_
\x1a\x04

****************************************************************
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 DeliveryErrors@analogic.com - and destroy all copies of this information, including any attachments, without reading or disclosing them.

Thank you.

Re: Jiffy is not able to measure the fraction of time a process runs a processor

[Mauricio Lin]

Hi,

On 3/15/06, linux-os (Dick Johnson) <linux-os@analogic.com> 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 <fche@redhat.com> wrote:
> >> "Mauricio Lin" <mauriciolin@gmail.com> 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.
> _
> \x1a\x04
>
> ****************************************************************
> 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 DeliveryErrors@analogic.com - and destroy all copies of this information, including any attachments, without reading or disclosing them.
>
> Thank you.
>