[ltt-dev] trace a futex

[ltt-dev] trace a futex

[Gian Lorenzo Meocci]

Hi all,

I am working (always) on a multithread tracing system. I would know if
there is a method to trace, with LTTng, an lll_lock or a lowlevel
function futex_wait.
I want establish if a synchronization primitive (like
pthread_mutex_lock or sem_wait) has acquires a lock or not.

Thanks a lot,


-- 
Ing. Gian Lorenzo Meocci
http://www.meocci.it

[ltt-dev] trace a futex

[Mathieu Desnoyers]

* Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
> Hi all,
> 
> I am working (always) on a multithread tracing system. I would know if
> there is a method to trace, with LTTng, an lll_lock or a lowlevel
> function futex_wait.
> I want establish if a synchronization primitive (like
> pthread_mutex_lock or sem_wait) has acquires a lock or not.

Tracing futex wait will only tell you when there has been "heavy"
contention on the mutex which required to put the process to sleep. The
pthread code starts by looping a few times actively waiting for the lock
before it calls the OS.

Therefore, the best way to trace this would be to use the userspace
markers and trace the mutex down/up events. This would imply recompiling
the pthread library.

Also note that when this instrumentation will be enabled (I mean by this
dynamically enabled at runtime), the system may be noticeably slower
because there will be 1 system call each time the mutex primitive is
called. The current userspace tracing goes through a system call to the
OS. Eventually, we should be able to change that into a direct memory
write, which will be much faster.

Mathieu

> 
> Thanks a lot,
> 
> 
> -- 
> Ing. Gian Lorenzo Meocci
> http://www.meocci.it
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

[ltt-dev] trace a futex

[Gian Lorenzo Meocci]

Hi Mathieu,

thanks for your reply.

I want specify that:
1) I am already patching glibc (and, of course, nptl/pthread_*)
2) I already add two event to pthread_mutex_lock. The first at the
beginning of the function and the second after all return 0 presented
on that function. But those two events are not enough to establish if
a pthread_mutex_lock has been blocking.
In fact I know only the time spent on pthread_mutex_lock. If this time
is little probably I hold the mutex otherwise I was been descheduled.

So thanks a lot again,


-- 
Ing. Gian Lorenzo Meocci
http://www.meocci.it

[ltt-dev] trace a futex

[Mathieu Desnoyers]

* Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
> Hi Mathieu,
> 
> thanks for your reply.
> 
> I want specify that:
> 1) I am already patching glibc (and, of course, nptl/pthread_*)
> 2) I already add two event to pthread_mutex_lock. The first at the
> beginning of the function and the second after all return 0 presented
> on that function. But those two events are not enough to establish if
> a pthread_mutex_lock has been blocking.
> In fact I know only the time spent on pthread_mutex_lock. If this time
> is little probably I hold the mutex otherwise I was been descheduled.
> 
> So thanks a lot again,
> 
> 

Ok, then you will probably want to correlate your information with :

- scheduling activity regarding your threads
- system call entry events, especially sys_futex. Note that a thread
  calling sys_futex won't _necessarily_ be put to sleep.. it may still
  be able to take the lock relatively quickly.

If you need more than that, we may think of instrumenting futex.c, but I
am not sure this is required.

Mathieu

> -- 
> Ing. Gian Lorenzo Meocci
> http://www.meocci.it
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

[ltt-dev] trace a futex

[Jan Kiszka]

Mathieu Desnoyers wrote:
> * Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
>> Hi Mathieu,
>>
>> thanks for your reply.
>>
>> I want specify that:
>> 1) I am already patching glibc (and, of course, nptl/pthread_*)
>> 2) I already add two event to pthread_mutex_lock. The first at the
>> beginning of the function and the second after all return 0 presented
>> on that function. But those two events are not enough to establish if
>> a pthread_mutex_lock has been blocking.
>> In fact I know only the time spent on pthread_mutex_lock. If this time
>> is little probably I hold the mutex otherwise I was been descheduled.
>>
>> So thanks a lot again,
>>
>>
> 
> Ok, then you will probably want to correlate your information with :
> 
> - scheduling activity regarding your threads
> - system call entry events, especially sys_futex. Note that a thread
>   calling sys_futex won't _necessarily_ be put to sleep.. it may still
>   be able to take the lock relatively quickly.
> 
> If you need more than that, we may think of instrumenting futex.c, but I
> am not sure this is required.

Haven't checked the state of instrumentation recently: Is the futex
operation visible in the trace now? It used to be not, and we often had
to guess the reason for sys_futex (wake, wait, pi or not pi, etc.) from
the context - or add ad-hoc instrumentation.

Jan

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 257 bytes
Desc: OpenPGP digital signature
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20081202/16397149/attachment-0002.pgp>

[ltt-dev] trace a futex

[Jan Kiszka]

Mathieu Desnoyers wrote:
> * Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
>> Hi Mathieu,
>>
>> thanks for your reply.
>>
>> I want specify that:
>> 1) I am already patching glibc (and, of course, nptl/pthread_*)
>> 2) I already add two event to pthread_mutex_lock. The first at the
>> beginning of the function and the second after all return 0 presented
>> on that function. But those two events are not enough to establish if
>> a pthread_mutex_lock has been blocking.
>> In fact I know only the time spent on pthread_mutex_lock. If this time
>> is little probably I hold the mutex otherwise I was been descheduled.
>>
>> So thanks a lot again,
>>
>>
> 
> Ok, then you will probably want to correlate your information with :
> 
> - scheduling activity regarding your threads
> - system call entry events, especially sys_futex. Note that a thread
>   calling sys_futex won't _necessarily_ be put to sleep.. it may still
>   be able to take the lock relatively quickly.
> 
> If you need more than that, we may think of instrumenting futex.c, but I
> am not sure this is required.

Haven't checked the state of instrumentation recently: Is the futex
operation visible in the trace now? It used to be not, and we often had
to guess the reason for sys_futex (wake, wait, pi or not pi, etc.) from
the context - or add ad-hoc instrumentation.

Jan

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 257 bytes
Desc: OpenPGP digital signature
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20081202/16397149/attachment-0003.pgp>

[ltt-dev] trace a futex

[Jan Kiszka]

Mathieu Desnoyers wrote:
> * Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
>> Hi Mathieu,
>>
>> thanks for your reply.
>>
>> I want specify that:
>> 1) I am already patching glibc (and, of course, nptl/pthread_*)
>> 2) I already add two event to pthread_mutex_lock. The first at the
>> beginning of the function and the second after all return 0 presented
>> on that function. But those two events are not enough to establish if
>> a pthread_mutex_lock has been blocking.
>> In fact I know only the time spent on pthread_mutex_lock. If this time
>> is little probably I hold the mutex otherwise I was been descheduled.
>>
>> So thanks a lot again,
>>
>>
> 
> Ok, then you will probably want to correlate your information with :
> 
> - scheduling activity regarding your threads
> - system call entry events, especially sys_futex. Note that a thread
>   calling sys_futex won't _necessarily_ be put to sleep.. it may still
>   be able to take the lock relatively quickly.
> 
> If you need more than that, we may think of instrumenting futex.c, but I
> am not sure this is required.

Haven't checked the state of instrumentation recently: Is the futex
operation visible in the trace now? It used to be not, and we often had
to guess the reason for sys_futex (wake, wait, pi or not pi, etc.) from
the context - or add ad-hoc instrumentation.

Jan

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 257 bytes
Desc: OpenPGP digital signature
URL: <http://lists.casi.polymtl.ca/pipermail/ltt-dev/attachments/20081202/16397149/attachment.pgp>

[ltt-dev] trace a futex

[Mathieu Desnoyers]

* Jan Kiszka (jan.kiszka at web.de) wrote:
> Mathieu Desnoyers wrote:
> > * Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
> >> Hi Mathieu,
> >>
> >> thanks for your reply.
> >>
> >> I want specify that:
> >> 1) I am already patching glibc (and, of course, nptl/pthread_*)
> >> 2) I already add two event to pthread_mutex_lock. The first at the
> >> beginning of the function and the second after all return 0 presented
> >> on that function. But those two events are not enough to establish if
> >> a pthread_mutex_lock has been blocking.
> >> In fact I know only the time spent on pthread_mutex_lock. If this time
> >> is little probably I hold the mutex otherwise I was been descheduled.
> >>
> >> So thanks a lot again,
> >>
> >>
> > 
> > Ok, then you will probably want to correlate your information with :
> > 
> > - scheduling activity regarding your threads
> > - system call entry events, especially sys_futex. Note that a thread
> >   calling sys_futex won't _necessarily_ be put to sleep.. it may still
> >   be able to take the lock relatively quickly.
> > 
> > If you need more than that, we may think of instrumenting futex.c, but I
> > am not sure this is required.
> 
> Haven't checked the state of instrumentation recently: Is the futex
> operation visible in the trace now? It used to be not, and we often had
> to guess the reason for sys_futex (wake, wait, pi or not pi, etc.) from
> the context - or add ad-hoc instrumentation.
> 
> Jan
> 

It still isn't instrumented, and I think it would be good to add such
instrumentation.

Have a look at the patch done by K. Prasad for futex.c : it should
probably be updated so it uses tracepoints instead of markers. Anyone
would like to do this ?

See http://lkml.org/lkml/2008/4/15/125
"[RFC PATCH 0/2] Debugging infrastructure for Futexes using Markers"

Mathieu

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: Digital signature
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20081203/956283fc/attachment-0003.pgp>

[ltt-dev] trace a futex

[Mathieu Desnoyers]

* Jan Kiszka (jan.kiszka at web.de) wrote:
> Mathieu Desnoyers wrote:
> > * Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
> >> Hi Mathieu,
> >>
> >> thanks for your reply.
> >>
> >> I want specify that:
> >> 1) I am already patching glibc (and, of course, nptl/pthread_*)
> >> 2) I already add two event to pthread_mutex_lock. The first at the
> >> beginning of the function and the second after all return 0 presented
> >> on that function. But those two events are not enough to establish if
> >> a pthread_mutex_lock has been blocking.
> >> In fact I know only the time spent on pthread_mutex_lock. If this time
> >> is little probably I hold the mutex otherwise I was been descheduled.
> >>
> >> So thanks a lot again,
> >>
> >>
> > 
> > Ok, then you will probably want to correlate your information with :
> > 
> > - scheduling activity regarding your threads
> > - system call entry events, especially sys_futex. Note that a thread
> >   calling sys_futex won't _necessarily_ be put to sleep.. it may still
> >   be able to take the lock relatively quickly.
> > 
> > If you need more than that, we may think of instrumenting futex.c, but I
> > am not sure this is required.
> 
> Haven't checked the state of instrumentation recently: Is the futex
> operation visible in the trace now? It used to be not, and we often had
> to guess the reason for sys_futex (wake, wait, pi or not pi, etc.) from
> the context - or add ad-hoc instrumentation.
> 
> Jan
> 

It still isn't instrumented, and I think it would be good to add such
instrumentation.

Have a look at the patch done by K. Prasad for futex.c : it should
probably be updated so it uses tracepoints instead of markers. Anyone
would like to do this ?

See http://lkml.org/lkml/2008/4/15/125
"[RFC PATCH 0/2] Debugging infrastructure for Futexes using Markers"

Mathieu

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: Digital signature
URL: <http://lists.casi.polymtl.ca/pipermail/ltt-dev/attachments/20081203/956283fc/attachment.pgp>

[ltt-dev] trace a futex

[Mathieu Desnoyers]

* Jan Kiszka (jan.kiszka at web.de) wrote:
> Mathieu Desnoyers wrote:
> > * Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
> >> Hi Mathieu,
> >>
> >> thanks for your reply.
> >>
> >> I want specify that:
> >> 1) I am already patching glibc (and, of course, nptl/pthread_*)
> >> 2) I already add two event to pthread_mutex_lock. The first at the
> >> beginning of the function and the second after all return 0 presented
> >> on that function. But those two events are not enough to establish if
> >> a pthread_mutex_lock has been blocking.
> >> In fact I know only the time spent on pthread_mutex_lock. If this time
> >> is little probably I hold the mutex otherwise I was been descheduled.
> >>
> >> So thanks a lot again,
> >>
> >>
> > 
> > Ok, then you will probably want to correlate your information with :
> > 
> > - scheduling activity regarding your threads
> > - system call entry events, especially sys_futex. Note that a thread
> >   calling sys_futex won't _necessarily_ be put to sleep.. it may still
> >   be able to take the lock relatively quickly.
> > 
> > If you need more than that, we may think of instrumenting futex.c, but I
> > am not sure this is required.
> 
> Haven't checked the state of instrumentation recently: Is the futex
> operation visible in the trace now? It used to be not, and we often had
> to guess the reason for sys_futex (wake, wait, pi or not pi, etc.) from
> the context - or add ad-hoc instrumentation.
> 
> Jan
> 

It still isn't instrumented, and I think it would be good to add such
instrumentation.

Have a look at the patch done by K. Prasad for futex.c : it should
probably be updated so it uses tracepoints instead of markers. Anyone
would like to do this ?

See http://lkml.org/lkml/2008/4/15/125
"[RFC PATCH 0/2] Debugging infrastructure for Futexes using Markers"

Mathieu

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: Digital signature
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20081203/956283fc/attachment-0002.pgp>

[ltt-dev] trace a futex

[K.Prasad]

On Wed, Dec 03, 2008 at 12:26:40AM -0500, Mathieu Desnoyers wrote:
> * Jan Kiszka (jan.kiszka at web.de) wrote:
> > Mathieu Desnoyers wrote:
> > > * Gian Lorenzo Meocci (glmeocci at gmail.com) wrote:
> > >> Hi Mathieu,
> > >>
> > >> thanks for your reply.
> > >>
> > >> I want specify that:
> > >> 1) I am already patching glibc (and, of course, nptl/pthread_*)
> > >> 2) I already add two event to pthread_mutex_lock. The first at the
> > >> beginning of the function and the second after all return 0 presented
> > >> on that function. But those two events are not enough to establish if
> > >> a pthread_mutex_lock has been blocking.
> > >> In fact I know only the time spent on pthread_mutex_lock. If this time
> > >> is little probably I hold the mutex otherwise I was been descheduled.
> > >>
> > >> So thanks a lot again,
> > >>
> > >>
> > > 
> > > Ok, then you will probably want to correlate your information with :
> > > 
> > > - scheduling activity regarding your threads
> > > - system call entry events, especially sys_futex. Note that a thread
> > >   calling sys_futex won't _necessarily_ be put to sleep.. it may still
> > >   be able to take the lock relatively quickly.
> > > 
> > > If you need more than that, we may think of instrumenting futex.c, but I
> > > am not sure this is required.
> > 
> > Haven't checked the state of instrumentation recently: Is the futex
> > operation visible in the trace now? It used to be not, and we often had
> > to guess the reason for sys_futex (wake, wait, pi or not pi, etc.) from
> > the context - or add ad-hoc instrumentation.
> > 
> > Jan
> > 
> 
> It still isn't instrumented, and I think it would be good to add such
> instrumentation.
> 
> Have a look at the patch done by K. Prasad for futex.c : it should
> probably be updated so it uses tracepoints instead of markers. Anyone
> would like to do this ?
> 
> See http://lkml.org/lkml/2008/4/15/125
> "[RFC PATCH 0/2] Debugging infrastructure for Futexes using Markers"
> 
> Mathieu
> 
> -- 

The patches pointed out at http://lkml.org/lkml/2008/4/15/125 aimed to
introduce static probes in the form of kernel markers in the futex
subsystem. Apart from tracing function boundaries and return values,
they were intended to be helpful in gathering performance measurements
and turn-around times for futex operations.

The patches did not elicit a favourable response then, and haven't been
converted to tracepoints (owing to the format string parameter
requirements for trace_mark and the fine-granular information being
exported by the proposed markers). I doubt if the community opinion has
changed now to accept the patch, if converted to tracepoints.

On a related note, just thinking if the proposed marker patch submission
from Google (http://lwn.net/Articles/298685/) has been sent to/accepted by
the community folks? It would be interesting to note details such as
granularity, level of information exported, number and choice of probe
points in the patch that is accepted by the community.

Thanks,
K.Prasad

[ltt-dev] trace a futex

[Peter Zijlstra]

FWIW, the ftrace infrastructure has on many an occasion (even before it
was called ftrace and specific to -rt) helped in debugging and fixing
futex races.

[ltt-dev] trace a futex

[Mathieu Desnoyers]

* Peter Zijlstra (peterz at infradead.org) wrote:
> 
> FWIW, the ftrace infrastructure has on many an occasion (even before it
> was called ftrace and specific to -rt) helped in debugging and fixing
> futex races.
> 

Hrm, I'm not sure futex races is the key aspect of interest here.
Knowing which amount of pthread mutex lock calls ends up calling the
scheduler looks a bit more like the topic brought by this particular
use-case. Therefore, correlating the information from the nptl with the
kernel information would be useful.

Is lockdep called when a futex is taken ? Should we add instrumentation
(tracepoints) to futex.c ? If yes, was there specific instrumentation
you used with ftrace that should be added ?

Mathieu

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

[ltt-dev] trace a futex

[Peter Zijlstra]

On Fri, 2008-12-05 at 07:28 -0500, Mathieu Desnoyers wrote:
> * Peter Zijlstra (peterz at infradead.org) wrote:
> > 
> > FWIW, the ftrace infrastructure has on many an occasion (even before it
> > was called ftrace and specific to -rt) helped in debugging and fixing
> > futex races.
> > 
> 
> Hrm, I'm not sure futex races is the key aspect of interest here.
> Knowing which amount of pthread mutex lock calls ends up calling the
> scheduler looks a bit more like the topic brought by this particular
> use-case. Therefore, correlating the information from the nptl with the
> kernel information would be useful.

We already have the scheduler instrucmentation, so correlating that to
known futex calls (from userspace) shouldn't be too hard. 

> Is lockdep called when a futex is taken ? 

lockdep only does kernel-internal locks - so no.

> Should we add instrumentation
> (tracepoints) to futex.c ? If yes, was there specific instrumentation
> you used with ftrace that should be added ?

Not sure we should, Thomas did the bulk of that ftrace debugging, Thomas
do you think it would be worthwhile to add some tracepoints in there?

[ltt-dev] trace a futex

[Peter Zijlstra]

[ resend with a real email address for Thomas ]

On Fri, 2008-12-05 at 07:28 -0500, Mathieu Desnoyers wrote:
> * Peter Zijlstra (peterz at infradead.org) wrote:
> > 
> > FWIW, the ftrace infrastructure has on many an occasion (even before it
> > was called ftrace and specific to -rt) helped in debugging and fixing
> > futex races.
> > 
> 
> Hrm, I'm not sure futex races is the key aspect of interest here.
> Knowing which amount of pthread mutex lock calls ends up calling the
> scheduler looks a bit more like the topic brought by this particular
> use-case. Therefore, correlating the information from the nptl with the
> kernel information would be useful.

We already have the scheduler instrucmentation, so correlating that to
known futex calls (from userspace) shouldn't be too hard. 

> Is lockdep called when a futex is taken ? 

lockdep only does kernel-internal locks - so no.

> Should we add instrumentation
> (tracepoints) to futex.c ? If yes, was there specific instrumentation
> you used with ftrace that should be added ?

Not sure we should, Thomas did the bulk of that ftrace debugging, Thomas
do you think it would be worthwhile to add some tracepoints in there?