[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 }