Re: use systemtep to debug TLS var in glibc lib

[kemi <kemi dot wang at intel dot com>]

On 2018年05月22日 01:38, David Smith wrote:
> The way to usually improve performance with global variables is use
> stats instead of incrementing the variable - the locking situation is
> greatly improved. So, change your script to:
> 

Thanks for your reply. I guess it can avoid cache line including the global
variable address bouncing. 

> probe
> process("/home/kemi/git/lib/lib/libpthread.so").statement("pthread_mutex_lock@*pthread_mutex_lock.c:163)
> {
>   immediate[tid()] <<< 1
> }
> 

It still have significant performance loss with that change.
Even with a empty probe handler like:

 probe
 process("/home/kemi/git/lib/lib/libpthread.so").statement("pthread_mutex_lock@*pthread_mutex_lock.c:163)
 {
  
 }

So, maybe the real overhead is caused by uprobe module used for user space probing.
 
> Then when printing the value of the variable, instead of something like:
> 
>   printf("hits: %d\n", immediate[i])
> 
> do:
> 
>   printf("hits: %d\n", @count(immediate[i]))
> 
> On Thu, May 17, 2018 at 6:18 AM, kemi <kemi.wang@intel.com> wrote:
>>
>> On 2018年05月16日 09:43, kemi wrote:
>>> Resend because the previous one is blocked by mail server．．．
>>>
>>> On 2018年05月16日 09:26, kemi wrote:
>>>> Hi, All
>>>>    I am using Systemtap to debug Glibc library, and wonder if Systemtap
>>>> has the capability to track TLS vars (__thread)? More details are provided
>>>> as below.
>>>>
>>>> Case description:
>>>> I would like to track lock statistics for pthread adaptive spin mutex,
>>>> e.g. the number of immediate gets, spin gets and the sleeping thread number.
>>>> So, I created three TLS vars (e.g. static __thread unsigned long immediate_get)
>>>> and hack the code accordingly for that purpose.
>>>> When I tried to use "stap -L 'process("/home/kemi/git/lib/lib/libpthread.so")
>>>> .statement("pthread_mutex_lock@*pthread_mutex_lock.c:*")' | grep immediate_get"
>>>> to check the available debug info. Unfortunately, there is nothing to show in
>>>> the terminal. Maybe the systemtap can't debug the TLS vars?
>>>> I have no idea about it. To workaround this issue, I use a local variable "local_immediate" to
>>>> store the thread local variable "immediate_get" at the entry point of pthread_mutex_lock().
>>>> Then I can see the correct output as below:
>>>>
>>>> root@kemi-desktop:/home/kemi/git/lib/lib# stap  -L 'process("/home/kemi/git/lib/lib/
>>>> libpthread.so").statement("pthread_mutex_lock@*pthread_mutex_lock.c:*")' | grep immediate
>>>> process("/home/kemi/git/lib/lib/libpthread-2.27.9000.so").statement("__pthread_mutex_lock@
>>>> ../nptl/pthread_mutex_lock.c:133") $local_immediate:int $local_spin:int $local_block:
>>>> int $mutex:pthread_mutex_t* $type:unsigned int $__PRETTY_FUNCTION__:char const[] const
>>>>
>>>> And create a mutex.stp script as follow:
>>>>   1 #! /usr/bin/env stap
>>>>   2
>>>>   3 probe
>>>>   4 process("/home/kemi/git/lib/lib/libpthread.so").statement("pthread_mutex_lock@*pthread_mutex_lock.c:133")
>>>>   5 {
>>>>   6             printf("immediate_get:%d.n", $local_immediate);
>>>>   7 }
>>>>   8
>>>>
>>
>> As TLS vars can't be quoted via "$" symbol, I have another workaround which uses a counter to record for
>> every hit.
>>
>> probe
>> process("/home/kemi/git/lib/lib/libpthread.so").statement("pthread_mutex_lock@*pthread_mutex_lock.c:163)
>> {
>>   immediate[tid()]++
>> }
>>
>> And print the statistics number for each thread when my benchmark is finished.
>> But I observed obvious (about 10x)performance regression, the overhead probably caused by calling tid()
>> in the handler is intolerable. I will be very appreciated for any suggestion to help reduce this overhead
>> to an acceptable level.
>>
>>>> When I run my benchmark with that script, it complains the follow errors message:
>>>> root@kemi-desktop:/home/kemi/git/will-it-scale# stap  mutex.stp -c "/home/kemi/git
>>>> /will-it-scale/pthread_mutex3_adaptive_threads -t 2 -s 1" -o mutex.txt
>>>> semantic error: while processing probe process("/home/kemi/git/lib/lib/libpthread-
>>>> 2.27.9000.so").statement("__pthread_mutex_lock@../nptl/pthread_mutex_lock.c:133")
>>>> from: process("/home/kemi/git/lib/lib/libpthread.so").statement("pthread_mutex_lock
>>>> @*pthread_mutex_lock.c:133")
>>>>
>>>> semantic error: unrecognized operation in DWARF expression [0] at 0 (0xe0: 0, 0):
>>>> identifier '$local_immediate' at mutex.stp:6:39
>>>>         dieoffset: 0x258e8 from unknown debug file for /home/kemi/git/lib/lib/libpthread-2.27.9000.so
>>>>         function: __GI___pthread_mutex_lock at ../nptl/pthread_mutex_lock.c:133
>>>>         source:                 printf("immediate_get:%d.n", $local_immediate);
>>>>                                                              ^
>>>>
>>>> Pass 2: analysis failed.  [man error::pass2]
>>>> Tip: /usr/share/doc/systemtap/README.Debian should help you get started.
>>>>
>>>> If I change the script to dump other existed local variables, it works well. So
>>>> I am confused what I did wrong here?
>>>> It's very helpful if you can give me some suggestion, thanks very much!
>>>>
>>>>
>>>> Other info may be useful:
>>>> OS: ubuntu 16.06 with 4.4.0-103-generic
>>>>
>>>> Systemtap installation:
>>>> apt-get install systemtap systemtap-runtime
>>>> stap-prep (missing kernel-debuginfo package is installed manually)
>>>>
>>>>
>>>> Glibc build:
>>>> cd ~/glibc
>>>> mkdir compile
>>>> cd compile
>>>> ../configure --prefix=/home/kemi/git/lib
>>>> make -j 16 && make install
>>>>
>>>>
>>>>
> 
> 
>