system or malloc issue

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 93%malloc94% or 93%free=
94%
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 93%malloc94% or 93%free94%
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 93%rt_sigpromask94%, 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

3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%
3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%3D3D%
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



85%8585%8585%85

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
0001020087928773 thread1:26515   0.007 ms  Syscall sigreturn
0001020087936409 thread1:26515   0.019 ms  Trap Page Fault Enter:769
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
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