spin_lock cause ?

spin_lock cause ?

[Kelly, Mark (RIS-BCT)]

Hi,

Perf report for our application shows:

  34.27%  [kernel]                    [k] _spin_lock
   8.19%  libjlib.so                  [.] CLZWExpander::expand(void*)
   4.62%  libjhtree.so                [.] CMRUCacheOf<CKeyIdAndPos, CJHTreeNode>
   1.97%  [kernel]                    [k] futex_wait_setup
   1.51%  [kernel]                    [k] native_write_msr_safe
   1.34%  [kernel]                    [k] futex_wake

Any suggestion for how to trace where/who is responsible for the spin_lock ?

thank you in advance,
mark



---------------------------------------- The information contained in this e-mail message is intended only for the personal and confidential use of the recipient(s) named above. This message may be an attorney-client communication and/or work product and as such is privileged and confidential. If the reader of this message is not the intended recipient or an agent responsible for delivering it to the intended recipient, you are hereby notified that you have received this document in error and that any review, dissemination, distribution, or copying of this message is strictly prohibited. If you have received this communication in error, please notify us immediately by e-mail, and delete the original message.  

Re: spin_lock cause ?

[Milian Wolff]

[-- Attachment #1: Type: text/plain, Size: 911 bytes --]

On Wednesday, June 1, 2016 1:05:40 PM CEST Kelly, Mark (RIS-BCT) wrote:
> Hi,
> 
> Perf report for our application shows:
> 
>   34.27%  [kernel]                    [k] _spin_lock
>    8.19%  libjlib.so                  [.] CLZWExpander::expand(void*)
>    4.62%  libjhtree.so                [.] CMRUCacheOf<CKeyIdAndPos,
> CJHTreeNode> 1.97%  [kernel]                    [k] futex_wait_setup
>    1.51%  [kernel]                    [k] native_write_msr_safe
>    1.34%  [kernel]                    [k] futex_wake
> 
> Any suggestion for how to trace where/who is responsible for the spin_lock ?

For both cases, you should collect backtraces which should allow you to find 
culprits. Have you tried:

perf record --call-graph dwarf

or similar?

Cheers

-- 
Milian Wolff | milian.wolff@kdab.com | Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 5903 bytes --]

Re: spin_lock cause ?

[M Kelly]

Milian Wolff <milian.wolff <at> kdab.com> writes:

> 
> On Wednesday, June 1, 2016 1:05:40 PM CEST Kelly, Mark (RIS-BCT) wrote:
> > Hi,
> > 
> > Perf report for our application shows:
> > 
> >   34.27%  [kernel]                    [k] _spin_lock
> >    8.19%  libjlib.so                  [.] CLZWExpander::expand(void*)
> >    4.62%  libjhtree.so                [.] CMRUCacheOf<CKeyIdAndPos,
> > CJHTreeNode> 1.97%  [kernel]                    [k] futex_wait_setup
> >    1.51%  [kernel]                    [k] native_write_msr_safe
> >    1.34%  [kernel]                    [k] futex_wake
> > 
> > Any suggestion for how to trace where/who is responsible for the 
spin_lock ?
> 
> For both cases, you should collect backtraces which should allow you to 
find 
> culprits. Have you tried:
> 
> perf record --call-graph dwarf
> 
> or similar?
> 
> Cheers
> 

ok, I will try it, thank you.  I will have to upgrade perf or move to a 
newer kernel ? because dwarf does not seem to be supported on my current 
system.  I will report back what it shows once I get it working.

thanks,
mark

Re: spin_lock cause ?

[Arnaldo Carvalho de Melo]

Em Wed, Jun 01, 2016 at 05:43:12PM +0000, M Kelly escreveu:
> Milian Wolff <milian.wolff <at> kdab.com> writes:
> > On Wednesday, June 1, 2016 1:05:40 PM CEST Kelly, Mark (RIS-BCT) wrote:
> > > Perf report for our application shows:
> > > 
> > >   34.27%  [kernel]                    [k] _spin_lock
> > >    8.19%  libjlib.so                  [.] CLZWExpander::expand(void*)
> > >    4.62%  libjhtree.so                [.] CMRUCacheOf<CKeyIdAndPos,
> > >    1.97%  [kernel]                    [k] futex_wait_setup

> > > Any suggestion for how to trace where/who is responsible for the 
> spin_lock ?

> > For both cases, you should collect backtraces which should allow you
> > to find culprits. Have you tried:

> > perf record --call-graph dwarf

> > or similar?
 
> ok, I will try it, thank you.  I will have to upgrade perf or move to a 
> newer kernel ? because dwarf does not seem to be supported on my current 
> system.  I will report back what it shows once I get it working.

No need for DWARF if you want to know what leads to the spinlock just up
to the syscall layer or if your userland components have frame pointers.
So first try with:

	perf record -g ./workload

Or:

	perf record -g -p `pidof workload`

- Arnaldo

Re: spin_lock cause ?

[M Kelly]

Arnaldo Carvalho de Melo <acme <at> kernel.org> writes:

> No need for DWARF if you want to know what leads to the spinlock just up
> to the syscall layer or if your userland components have frame pointers.

Hi,

ok, I rebuilt our app using -fno-omit-frame-pointer 
and did the perf record -g and when looking at the 
report output I now see:

    40.90%  thorslave_mytho  [kernel.kallsyms]                   [k] _spin_lock                                                                       
            |
            --- _spin_lock
               |          
               |--49.11%-- futex_wake
               |          do_futex
               |          sys_futex
               |          system_call_fastpath
               |          __lll_unlock_wake
               |          |          
               |          |--99.81%-- CKeyCursor::gtEqual(char const*, char*, bool)
               |          |          _ZN16CKeyLevelManager7_lookupEbj.constprop.100
               |
               |--44.31%-- futex_wait_setup
               |          futex_wait
               |          do_futex
               |          sys_futex
               |          system_call_fastpath
               |          __lll_lock_wait
               |          |          
               |          |--99.83%-- CKeyCursor::gtEqual(char const*, char*, bool)
               |          |          _ZN16CKeyLevelManager7_lookupEbj.constprop.100
               |
               |--5.46%-- task_rq_lock
               |          try_to_wake_up
               |          |          
               |          |--99.98%-- wake_up_state
               |          |          wake_futex
               |          |          futex_wake
               |          |          do_futex
               |          |          sys_futex
               |          |          system_call_fastpath
               |          |          __lll_unlock_wake
               |          |          |          
               |          |          |--99.75%-- CKeyCursor::gtEqual(char const*, char*, bool)
               |          |          |          _ZN16CKeyLevelManager7_lookupEbj.constprop.100
               |          
               |--0.73%-- try_to_wake_up
               |          |          
               |          |--99.83%-- wake_up_state
               |          |          wake_futex
               |          |          futex_wake
               |          |          do_futex
               |          |          sys_futex
               |          |          system_call_fastpath
               |          |          __lll_unlock_wake
               |          |          |          
               |          |          |--99.88%-- CKeyCursor::gtEqual(char const*, char*, bool)
               |          |          |          _ZN16CKeyLevelManager7_lookupEbj.constprop.100

So that is helpful.  
I do not understand the system_call_fastpath->futex->_spin_lock part yet, 
but that is a separate issue!

thanks so much,
mark

Re: spin_lock cause ?

[Rick Jones]

On 06/01/2016 11:49 AM, M Kelly wrote:
> So that is helpful.
> I do not understand the system_call_fastpath->futex->_spin_lock part yet,
> but that is a separate issue!

Just a guess, but if your application is using threads, contention on 
the synchonrization primitives you use to keep things straight can 
end-up punting to the kernel.

rick jones

Re: spin_lock cause ?

[M Kelly]

Rick Jones <rick.jones2 <at> hpe.com> writes:

> 
> On 06/01/2016 11:49 AM, M Kelly wrote:
> > So that is helpful.
> > I do not understand the system_call_fastpath->futex->_spin_lock part
> > yet,
> > but that is a separate issue!
> 
> Just a guess, but if your application is using threads, contention on 
> the synchonrization primitives you use to keep things straight can 
> end-up punting to the kernel.
> 
> rick jones
> 

Hi,

I think I recall you from hp, years ago when I was there :-)
Thanks for the info.  I suspect we are too heavy on 
pthread_mutex_lock()/unlock() 
which could probably produce these call graphs:

            --- _spin_lock
               |          
               |--49.11%-- futex_wake
               |          do_futex
               |          sys_futex
               |          system_call_fastpath
               |          __lll_unlock_wake
               |          
               |--44.31%-- futex_wait_setup
               |          futex_wait
               |          do_futex
               |          sys_futex
               |          system_call_fastpath
               |          __lll_lock_wait

thanks again,
mark

Re: spin_lock cause ?

[Rick Jones]

On 06/01/2016 12:25 PM, M Kelly wrote:
> I think I recall you from hp, years ago when I was there :-)
> Thanks for the info.  I suspect we are too heavy on
> pthread_mutex_lock()/unlock()

HP-UX has some ways/tools to track mutex contention.  Some extensions to 
give names to mutexes and then get stats on how often one went to grab 
them and it was held etc etc.  Been ages since I used them - I'd hope 
there was something similar for Linux but I've not played with threads 
in a very long time.

happy benchmarking,

rick jones

Re: spin_lock cause ?

[David Ahern]

On 6/1/16 2:24 PM, Rick Jones wrote:
> On 06/01/2016 12:25 PM, M Kelly wrote:
>> I think I recall you from hp, years ago when I was there :-)
>> Thanks for the info.  I suspect we are too heavy on
>> pthread_mutex_lock()/unlock()
>
> HP-UX has some ways/tools to track mutex contention.  Some extensions to
> give names to mutexes and then get stats on how often one went to grab
> them and it was held etc etc.  Been ages since I used them - I'd hope
> there was something similar for Linux but I've not played with threads
> in a very long time.

If the kernel is new enough (3.8 or 3.10, I forget when userspace return 
probes were added) you can use probes + futex system call to analyze 
lock contention.

 From an old script for x86:

PL=/lib64/libpthread.so.0
perf probe -x ${PL} -a 'mutex_lock=pthread_mutex_lock addr=%di'
perf probe -x ${PL} -a 'mutex_trylock=pthread_mutex_trylock addr=%di'
perf probe -x ${PL} -a 'mutex_timedlock=pthread_mutex_timedlock addr=%di'
perf probe -x ${PL} -a 'mutex_unlock=pthread_mutex_unlock addr=%di'

perf probe -x ${PL} -a 'mutex_lock_ret=pthread_mutex_lock%return ret=%ax'
perf probe -x ${PL} -a 'mutex_trylock_ret=pthread_mutex_trylock%return 
ret=%ax'
perf probe -x ${PL} -a 
'mutex_timedlock_ret=pthread_mutex_timedlock%return ret=%ax'


perf record -a -e probe_libpthread:* -e 
syscalls:sys_enter_futex,syscalls:sys_exit_futex -- <workload spec>

perf script -g python

--> edit perf-script.py for analysis of interest.

perf script -s perf-script.py

e.g., you can track the thread id holding a lock and for a how long, how 
many contentions, who got the lock when it was released, etc.

Many years ago I used the above to understand a nasty apparent deadlock 
in a process.

Re: spin_lock cause ?

[Milian Wolff]

[-- Attachment #1: Type: text/plain, Size: 1870 bytes --]

On Mittwoch, 1. Juni 2016 18:49:01 CEST M Kelly wrote:
> Arnaldo Carvalho de Melo <acme <at> kernel.org> writes:
> > No need for DWARF if you want to know what leads to the spinlock just up
> > to the syscall layer or if your userland components have frame pointers.
> 
> Hi,
> 
> ok, I rebuilt our app using -fno-omit-frame-pointer
> and did the perf record -g and when looking at the
> report output I now see:
> 
>     40.90%  thorslave_mytho  [kernel.kallsyms]                   [k]
> _spin_lock
> 
>             --- _spin_lock
> 
>                |--49.11%-- futex_wake
>                |
>                |          do_futex
>                |          sys_futex
>                |          system_call_fastpath
>                |          __lll_unlock_wake
>                |          
>                |          |--99.81%-- CKeyCursor::gtEqual(char const*,
>                |          |char*, bool)
>                |          |
>                |          |          _ZN16CKeyLevelManager7_lookupEbj.constp
>                |          |          rop.100

<snip>

You are running an older perf, I recommend you rerun the report step and pass 
`-g graph`, the old default of `-g fractal` outputs relative-to-parent numbers 
which is often misleading.

The above already shows that you are suffering from lock contention issues, 
and where from (i.e. CKeyCursor::gtEqual). As the above only shows CPU time 
spent, I can only recommend to additionally look at sleep times, e.g. via 

https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times

You can easily put the above commands into a shell helper file, I did this:

https://github.com/milianw/shell-helpers/blob/master/perf-sleep-record

HTH
-- 
Milian Wolff | milian.wolff@kdab.com | Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts

[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 5903 bytes --]