[ltt-dev] Please help, system issue

[Bizhan Gholikhamseh (bgholikh)]

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: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20090217/8bd8fa00/attachment-0002.htm>