From mboxrd@z Thu Jan 1 00:00:00 1970 From: bgholikh@cisco.com (Bizhan Gholikhamseh (bgholikh)) Date: Tue, 17 Feb 2009 05:03:35 -0800 Subject: [ltt-dev] Please help, system issue Message-ID: Hi All, We are trying to understand a system performance issue with our system. First of all, since we are working on a legacy system, Linux 2.6.11, we are not able to port Lttng to our platform. So I ported the older version, LTT. To our development system. Within our environment we have a multi-threaded application which runs in SCHED_RR scheduling class. W thought there might be a performance issue with "malloc" or "free" library calls. We have instrumented kernel so we can see most of the system activities with related timestamp. We have also created a wrapper which makes an ioctl calls before (pre-malloc/free) and after (post-malloc/free) each "malloc" or "free" call. This way we can timestamp anytime we call malloc or free using the same tracing tool. Here is how the execution path is: pre-malloc(); malloc(); post-malloc(); pthread_cond_wait(); // after the thread is woken by another thread it continues its execution. Here is the stack of the running thread which calls malloc and later it is put in the sleep. 1- Ioctl call: pre-malloc 2- System call: rt_sigpromask 3- System call: rt_sigsuspend After about 20 msec the suspended thread is waken up through a syscall kill by another thread and put on run queue 4- system call: kill: wake up suspended thread And finally when the suspended thread resumes execution, we see the post-malloc ioctl: 5- system call: sigreturn 6- ioctl call: post-malloc We are not sure whether malloc has been suspended due to malloc(), or pthread_cond_wait(): Looking at malloc implementation of the glibc, we do not see malloc calls any "rt_sigpromask", is this right? And also if the thread is suspended due to pthread_cond_wait, why we see post_malloc() after thread is woken up by another thread? Here is what the timestamp trace which we see is, (thread1 is the name of the thread which gets suspended and thread2 is the thread which wakes up thread1). Timestamp Thread:pid Duration Description ========================================== 0001020051834943 thread1:26515 0.001 ms pre_malloc 0001020051836671 thread1:26515 0.008 ms Syscall Exit 0001020051844671 thread1:26515 0.001 ms Syscall rt_sigprocmask 0001020051845883 thread1:26515 0.002 ms Syscall Exit 0001020051848034 thread1:26515 0.003 ms Syscall rt_sigsuspend .................. After 20 msec. 0001020077956560 thread2:26514 0.002 ms Syscall kill 0001020077964500 thread2:26514 0.002 ms WAKEUP PID : 26515; STATE : 1 And finaly the suspended thread starts executing 0001020087926167 thread1:26515 0.001 ms Trap Page Fault Enter:1025 IP : 0x32D26608 0001020087928773 thread1:26515 0.007 ms Syscall sigreturn 0001020087936409 thread1:26515 0.019 ms Trap Page Fault Enter:769 IP : 0x0FED708C 0001020087957560 thread1:26515 0.002 ms Syscall kill 0001020087960500 thread1:26515 0.002 ms WAKEUP PID : 26517; STATE : 1 0001020087962803 thread1:26515 0.001 ms Syscall Exit 0001020087964045 thread1:26515 0.002 ms Trap Page Fault Enter:1025 IP : 0x0FB52734 0001020087971590 thread1:26515 0.000 ms Syscall ioctl 0001020087974439 thread1:26515 0.001 ms Custom:ret_malloc 0001020087975924 thread1:26515 0.007 ms Syscall Exit Many thanks in advance, Bizhan -------------- next part -------------- An HTML attachment was scrubbed... URL: