[ltt-dev] kernel_arch_syscall_exit

[ltt-dev] kernel_arch_syscall_exit

[Gian Lorenzo Meocci]

Hi,

Is possible to have a kernel_arch_syscall_exit related to a process
without the correspondent kernel_arch_syscall_entry?

thanks,

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

[ltt-dev] kernel_arch_syscall_exit

[Mathieu Desnoyers]

* Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
> Hi,
> 
> Is possible to have a kernel_arch_syscall_exit related to a process
> without the correspondent kernel_arch_syscall_entry?
> 

Early in the trace ? (before the statedump end event ?)
When LTTng/LTTV versions ?

Mathieu

> thanks,
> 
> -- 
> Ing. Gian Lorenzo Meocci
> http://www.meocci.it
> 
> _______________________________________________
> 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] kernel_arch_syscall_exit

[Gian Lorenzo Meocci]

I am testing LTTng 0.44 with last lttv 0.11.3.

My trace is even like this:

fs_exec: 583.329460188 (/tmp/trace1/control/processes_0), 30279,
30279, ./OCEAN, , 30253, 0x0, SYSCALL { filename = "./OCEAN" }
kernel_syscall_exit: 583.329461613 (/tmp/trace1/cpu_0), 30279, 30279,
./OCEAN, , 30253, 0x0, USER_MODE { ret = 0 }
kernel_arch_trap_exit: 583.361027971 (/tmp/trace1/cpu_0), 30279,
30279, ./OCEAN, , 30253, 0x0, USER_MODE
kernel_arch_trap_entry: 583.361029692 (/tmp/trace1/cpu_0), 30279,
30279, ./OCEAN, , 30253, 0x0, TRAP { trap_id = 14, ip = 0x8079800 }

I am quite confusing from this behaviour.

best regards,

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

[ltt-dev] kernel_arch_syscall_exit

[Mathieu Desnoyers]

* Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
> I am testing LTTng 0.44 with last lttv 0.11.3.
> 
> My trace is even like this:
> 
> fs_exec: 583.329460188 (/tmp/trace1/control/processes_0), 30279,
> 30279, ./OCEAN, , 30253, 0x0, SYSCALL { filename = "./OCEAN" }
> kernel_syscall_exit: 583.329461613 (/tmp/trace1/cpu_0), 30279, 30279,
> ./OCEAN, , 30253, 0x0, USER_MODE { ret = 0 }
> kernel_arch_trap_exit: 583.361027971 (/tmp/trace1/cpu_0), 30279,
> 30279, ./OCEAN, , 30253, 0x0, USER_MODE
> kernel_arch_trap_entry: 583.361029692 (/tmp/trace1/cpu_0), 30279,
> 30279, ./OCEAN, , 30253, 0x0, TRAP { trap_id = 14, ip = 0x8079800 }
> 
> I am quite confusing from this behaviour.
> 

Do you have multiple syscall_exit without any syscall entry ?

Is it near the beginning of the trace ?

I see you have a "fs_exec" in SYSCALL mode, which tells me that lttv
either enountered a syscall_entry event or it's at the beginning of the
trace.

Do you see syscall entry events elsewhere in the trace (later ?)

Mathieu

> best regards,
> 
> -- 
> Ing. Gian Lorenzo Meocci
> http://www.meocci.it
> 

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

[ltt-dev] kernel_arch_syscall_exit

[Gian Lorenzo Meocci]

Hi Mathieu Desnoyers,

> Do you have multiple syscall_exit without any syscall entry ?

I have an equal number of syscall entry and syscall_exit.

> I see you have a "fs_exec" in SYSCALL mode, which tells me that lttv
> either enountered a syscall_entry event or it's at the beginning of the
> trace.

No ... (if I understood your question)

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

[ltt-dev] kernel_arch_syscall_exit

[Gian Lorenzo Meocci]

This is the trace:

http://www.enginetwork.com/tmp_ktrace.bz2

I am interesting to OCEAN program. This program has two thread and I
want to calculate the time elapsed from syscall_entry and
syscall_exit. For do this the entry MUST come before the exit.

But thats not even true.

Thanks a lot,

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

[ltt-dev] kernel_arch_syscall_exit

[Mathieu Desnoyers]

* Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
> This is the trace:
> 
> http://www.enginetwork.com/tmp_ktrace.bz2
> 
> I am interesting to OCEAN program. This program has two thread and I
> want to calculate the time elapsed from syscall_entry and
> syscall_exit. For do this the entry MUST come before the exit.
> 
> But thats not even true.
> 

Hrm ? shouldn't this be a .tar.bz2 ??

Also, please give me a timestamp to look at.

Mathieu

> Thanks a lot,
> 
> -- 
> Ing. Gian Lorenzo Meocci
> http://www.meocci.it
> 

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

[ltt-dev] kernel_arch_syscall_exit

[Pierre-Marc Fournier]

Gian Lorenzo Meocci wrote:
> This is the trace:
> 
> http://www.enginetwork.com/tmp_ktrace.bz2
> 
> I am interesting to OCEAN program. This program has two thread and I
> want to calculate the time elapsed from syscall_entry and
> syscall_exit. For do this the entry MUST come before the exit.
> 
> But thats not even true.
> 
> Thanks a lot,
> 


Since this trace isn't the one from which you pasted an excerpt earlier 
in this thread, I can't use the same example as you. But here is a very 
similar excerpt where the OCEAN program is being started. The only 
difference is that I went back further before the exec() in order to get 
the corresponding syscall_entry.

pmf


kernel_syscall_entry: 6767.420898517 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { ip = 0xffffe424, syscall_id = 11 
[sys_execve+0x0/0x80] }
mm_page_alloc: 6767.420904130 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 222088, order = 0 }
mm_handle_fault_entry: 6767.420911312 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { address = 3221225460, ip = 0xffffe424, 
write_access = 1 }
mm_page_alloc: 6767.420912609 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 222089, order = 0 }
mm_page_alloc: 6767.420914203 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 514396, order = 0 }
mm_handle_fault_exit: 6767.420914608 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { res = 0 }
mm_page_free: 6767.420945913 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 498947, order = 0 }
mm_page_free: 6767.420946656 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 402976, order = 0 }
mm_page_free: 6767.420946974 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 402248, order = 0 }
mm_page_free: 6767.420947259 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 271783, order = 0 }
mm_page_free: 6767.420947541 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 497202, order = 0 }
mm_page_free: 6767.420947829 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 499932, order = 0 }
mm_page_free: 6767.420948114 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 272511, order = 0 }
mm_page_free: 6767.420948969 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 272287, order = 0 }
mm_page_free: 6767.420949258 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 494118, order = 0 }
mm_page_free: 6767.420949543 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 323285, order = 0 }
mm_page_free: 6767.420949828 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 398923, order = 0 }
mm_page_free: 6767.420950109 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 500671, order = 0 }
mm_page_free: 6767.420950391 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 335412, order = 0 }
mm_page_free: 6767.420950676 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 499978, order = 0 }
mm_page_free: 6767.420950957 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 406759, order = 0 }
mm_page_free: 6767.420953034 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 503728, order = 0 }
mm_page_free: 6767.420953402 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 499732, order = 0 }
mm_page_free: 6767.420954114 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 502876, order = 0 }
mm_page_free: 6767.420954872 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 512950, order = 0 }
mm_page_free: 6767.420955176 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 245004, order = 0 }
mm_page_free: 6767.420955877 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 226124, order = 0 }
mm_page_free: 6767.420956226 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 221789, order = 0 }
mm_page_free: 6767.420956518 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 511561, order = 0 }
mm_page_free: 6767.420956811 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 406214, order = 0 }
mm_page_free: 6767.420957272 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 224379, order = 0 }
mm_page_free: 6767.420957572 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 224697, order = 0 }
mm_page_free: 6767.420959788 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL { pfn = 221655, order = 0 }
kernel_arch_trap_entry: 6767.420971372 (/tmp/trace1/cpu_0), 30591, 
30591, start.sh, , 30581, 0x0, TRAP { trap_id = 14, ip = 0xc0238ccf }
mm_handle_fault_entry: 6767.420972103 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, TRAP { address = 135145556, ip = 0xffffe424, 
write_access = 1 }
mm_page_alloc: 6767.420973209 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, TRAP { pfn = 221655, order = 0 }
mm_page_alloc: 6767.420974308 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, TRAP { pfn = 406214, order = 0 }
mm_handle_fault_exit: 6767.420976033 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, TRAP { res = 512 }
kernel_arch_trap_exit: 6767.420976322 (/tmp/trace1/cpu_0), 30591, 30591, 
start.sh, , 30581, 0x0, SYSCALL
fs_close: 6767.420977518 (/tmp/trace1/cpu_0), 30591, 30591, start.sh, , 
30581, 0x0, SYSCALL { fd = 3 }
fs_exec: 6767.420987167 (/tmp/trace1/control/processes_0), 30591, 30591, 
./OCEAN, , 30581, 0x0, SYSCALL { filename = "./OCEAN" }
kernel_syscall_exit: 6767.420988067 (/tmp/trace1/cpu_0), 30591, 30591, 
./OCEAN, , 30581, 0x0, USER_MODE { ret = 0 }

[ltt-dev] kernel_arch_syscall_exit

[Pierre-Marc Fournier]

Gian Lorenzo Meocci wrote:
> I am testing LTTng 0.44 with last lttv 0.11.3.
> 
> My trace is even like this:
> 
> fs_exec: 583.329460188 (/tmp/trace1/control/processes_0), 30279,
> 30279, ./OCEAN, , 30253, 0x0, SYSCALL { filename = "./OCEAN" }
> kernel_syscall_exit: 583.329461613 (/tmp/trace1/cpu_0), 30279, 30279,
> ./OCEAN, , 30253, 0x0, USER_MODE { ret = 0 }
> kernel_arch_trap_exit: 583.361027971 (/tmp/trace1/cpu_0), 30279,
> 30279, ./OCEAN, , 30253, 0x0, USER_MODE
> kernel_arch_trap_entry: 583.361029692 (/tmp/trace1/cpu_0), 30279,
> 30279, ./OCEAN, , 30253, 0x0, TRAP { trap_id = 14, ip = 0x8079800 }
> 

syscall_entry would come before fs_exec. fs_exec is an event that occurs
between syscall_entry and syscall_exit in the particular case where this
syscall is an exec(). So you need to look before this sequence to find
the syscall_entry.

[ltt-dev] kernel_arch_syscall_exit

[Gian Lorenzo Meocci]

I can't find this syscall_entry.

Can I attach the complete trace?

On Fri, Oct 24, 2008 at 4:48 PM, Pierre-Marc Fournier
<pierre-marc.fournier at polymtl.ca> wrote:
> Gian Lorenzo Meocci wrote:
>> I am testing LTTng 0.44 with last lttv 0.11.3.
>>
>> My trace is even like this:
>>
>> fs_exec: 583.329460188 (/tmp/trace1/control/processes_0), 30279,
>> 30279, ./OCEAN, , 30253, 0x0, SYSCALL { filename = "./OCEAN" }
>> kernel_syscall_exit: 583.329461613 (/tmp/trace1/cpu_0), 30279, 30279,
>> ./OCEAN, , 30253, 0x0, USER_MODE { ret = 0 }
>> kernel_arch_trap_exit: 583.361027971 (/tmp/trace1/cpu_0), 30279,
>> 30279, ./OCEAN, , 30253, 0x0, USER_MODE
>> kernel_arch_trap_entry: 583.361029692 (/tmp/trace1/cpu_0), 30279,
>> 30279, ./OCEAN, , 30253, 0x0, TRAP { trap_id = 14, ip = 0x8079800 }
>>
>
> syscall_entry would come before fs_exec. fs_exec is an event that occurs
> between syscall_entry and syscall_exit in the particular case where this
> syscall is an exec(). So you need to look before this sequence to find
> the syscall_entry.
>



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