[ltt-dev] sys time

[ltt-dev] sys time

[Gian Lorenzo Meocci]

Hi,

I want to retrieve from a lttng trace a total time that a thread has
spent in the kernel.
For example this stupid program uses only sys call functions:

int main()
{
       int i=0;
       char buf[1024];
       FILE *fd=fopen("/dev/urandom","r");
       while(i<10000)
       {
               fread(&buf[0],1,1024,fd);
               i++;
       }

       fclose(fd);
       return 0;
}

if I run it with the linux command "time" I give:

real    0m1.714s
user    0m0.004s
sys     0m1.708s

I want to know if it is possible to obtain this results using lttng trace.
Actually I made a sum of all differences from a
kernel_arch_trap_entry/kernel_arch_trap_exit,
kernel_arch_syscall_entry/exit, kernel_softirq_entry/exit,
mm_handle_fault_entry/exit, kernel_irq_entry/exit.
But for now, my results isn't very good.

Best regards,

-- 
Ing. Gian Lorenzo Meocci
http://www.meocci.it

[ltt-dev] sys time

[Pierre-Marc Fournier]

Gian Lorenzo Meocci wrote:

> I want to know if it is possible to obtain this results using lttng trace.

It is definitely possible.

> Actually I made a sum of all differences from a
> kernel_arch_trap_entry/kernel_arch_trap_exit,
> kernel_arch_syscall_entry/exit, kernel_softirq_entry/exit,
> mm_handle_fault_entry/exit, kernel_irq_entry/exit.

You don't need mm_handle_fault_entry/exit because they are always
enclosed within kernel_arch_trap_entry/exit's.

> But for now, my results isn't very good.

- You need to stop counting time when your process is being scheduled
out. See the kernel_sched_schedule events.

- You need to filter the events based on the pid of the process you're
investigating, but I guess you're already doing that.

- If the process is being created inside the trace, you need to start
counting time only after it is created, of course. You could count
syscall time starting at the kernel_process_fork that creates the
process. Also, you need to stop counting time when it's destroyed of course.

- If the process already exists when the trace is started, only consider
events after the list_statedump_end event. Before that, the pid of each
event might not be reliable.

pmf

[ltt-dev] sys time

[Mathieu Desnoyers]

* Pierre-Marc Fournier (pierre-marc.fournier at polymtl.ca) wrote:
> Gian Lorenzo Meocci wrote:
> 
> > I want to know if it is possible to obtain this results using lttng trace.
> 
> It is definitely possible.
> 
> > Actually I made a sum of all differences from a
> > kernel_arch_trap_entry/kernel_arch_trap_exit,
> > kernel_arch_syscall_entry/exit, kernel_softirq_entry/exit,
> > mm_handle_fault_entry/exit, kernel_irq_entry/exit.
> 
> You don't need mm_handle_fault_entry/exit because they are always
> enclosed within kernel_arch_trap_entry/exit's.
> 
> > But for now, my results isn't very good.
> 
> - You need to stop counting time when your process is being scheduled
> out. See the kernel_sched_schedule events.
> 
> - You need to filter the events based on the pid of the process you're
> investigating, but I guess you're already doing that.
> 
> - If the process is being created inside the trace, you need to start
> counting time only after it is created, of course. You could count
> syscall time starting at the kernel_process_fork that creates the
> process. Also, you need to stop counting time when it's destroyed of course.
> 
> - If the process already exists when the trace is started, only consider
> events after the list_statedump_end event. Before that, the pid of each
> event might not be reliable.
> 

All the above is good. Another thing : if an interrupt handler is
executed on top of system call code, don't count it twice. :)

Mathieu

> pmf
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

[ltt-dev] sys time

[Gian Lorenzo Meocci]

I agree with you but this don't resolv my problem. Infact my problem
is that "time" give me 1.74 sec of sys time when analising lttng-trace
I obtain only 0.87.

WHY???

-- 
Ing. Gian Lorenzo Meocci
http://www.meocci.it

[ltt-dev] sys time

[Michel Dagenais]

On Fri, 2008-10-17 at 18:40 +0200, Gian Lorenzo Meocci wrote:
> I agree with you but this don't resolv my problem. Infact my problem
> is that "time" give me 1.74 sec of sys time when analising lttng-trace
> I obtain only 0.87.

The time command can be pretty far off when a process is making a lot of
system calls. It usually underestimates the user time, which is
consistent with what you are seeing. Basically, the kernel simply counts
a full jiffy for the process currently executing when the timer
generates an interrupt. If a process makes a lot of system calls, it
will often be scheduled at the beginning of a timer interval but will
quickly yield to another process and not be there at the timer
interrupt.