[ltt-dev] LLTng probes

[ltt-dev] LLTng probes

[Jyotiswarup Raiturkar]

Hello

 

I'm looking at LTTng working inside the kernel, and trying to understand
the instrumentation.

 

However, I am not able to see how the DEFINE_MARKER_TP() macros and
other probe_* functions in kernel-trace.c are actually used . As I
understand it, to make the actual trace, modules would have to call the
probe_* functions; yet I'm not able to locate these calls.

 

Thanks

Jyoti

-- 
IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium.  Thank you.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20100519/aa88b9b8/attachment-0002.htm>

[ltt-dev] LLTng probes

[Jyotiswarup Raiturkar]

Hello

 

I'm looking at LTTng working inside the kernel, and trying to understand
the instrumentation.

 

However, I am not able to see how the DEFINE_MARKER_TP() macros and
other probe_* functions in kernel-trace.c are actually used . As I
understand it, to make the actual trace, modules would have to call the
probe_* functions; yet I'm not able to locate these calls.

 

Thanks

Jyoti

-- 
IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium.  Thank you.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/ltt-dev/attachments/20100519/aa88b9b8/attachment-0001.htm>

[ltt-dev] LLTng probes

[Jyotiswarup Raiturkar]

Hello

 

I'm looking at LTTng working inside the kernel, and trying to understand
the instrumentation.

 

However, I am not able to see how the DEFINE_MARKER_TP() macros and
other probe_* functions in kernel-trace.c are actually used . As I
understand it, to make the actual trace, modules would have to call the
probe_* functions; yet I'm not able to locate these calls.

 

Thanks

Jyoti

-- 
IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium.  Thank you.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20100519/aa88b9b8/attachment-0003.htm>

[ltt-dev] LLTng probes

[Mathieu Desnoyers]

* Jyotiswarup Raiturkar (Jyotiswarup.Raiturkar at arm.com) wrote:
> Hello
> 
>  
> 
> I'm looking at LTTng working inside the kernel, and trying to understand
> the instrumentation.
> 
>  
> 
> However, I am not able to see how the DEFINE_MARKER_TP() macros and
> other probe_* functions in kernel-trace.c are actually used . As I
> understand it, to make the actual trace, modules would have to call the
> probe_* functions; yet I'm not able to locate these calls.

The probes are connected to the tracepoints with:

kernel:marker.c: set_marker()

                     ret = tracepoint_probe_register_noupdate(
                                elem->tp_name,
                                elem->tp_cb);

Which is called when a marker is enabled. The markers are listed in a
table which is defined by the DEFINE_MARKER_TP() macros.

Thanks,

Mathieu

> 
>  
> 
> Thanks
> 
> Jyoti
> 
> -- 
> IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium.  Thank you.

> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev


-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com

[ltt-dev] LLTng probes

[Jyotiswarup Raiturkar]

>> The probes are connected to the tracepoints with: kernel:marker.c:
set_marker()

Actually my question was where is the actual trace out call made? For
example for the tracepoint defined by DEFINE_TRACE(irq_exit), the trace
out call is trace_irq_exit(). Similarly there is a trace marker called
DEFINE_MARKER_TP() for irq_exit :
Kernel-trace.c : 
	DEFINE_MARKER_TP(kernel, irq_exit, irq_exit, probe_irq_exit,
"handled #1u%u");

But I don't see how this marker is actually hit during execution. What
is the call similar to trace_irq_exit() for the Tracepoint?

Thanks
Jyotiswarup Raiturkar

-----Original Message-----
From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] 
Sent: Wednesday, May 19, 2010 8:00 PM
To: Jyotiswarup Raiturkar
Cc: ltt-dev at lists.casi.polymtl.ca
Subject: Re: [ltt-dev] LLTng probes

* Jyotiswarup Raiturkar (Jyotiswarup.Raiturkar at arm.com) wrote:
> Hello
> 
>  
> 
> I'm looking at LTTng working inside the kernel, and trying to
understand
> the instrumentation.
> 
>  
> 
> However, I am not able to see how the DEFINE_MARKER_TP() macros and
> other probe_* functions in kernel-trace.c are actually used . As I
> understand it, to make the actual trace, modules would have to call
the
> probe_* functions; yet I'm not able to locate these calls.

The probes are connected to the tracepoints with:

kernel:marker.c: set_marker()

                     ret = tracepoint_probe_register_noupdate(
                                elem->tp_name,
                                elem->tp_cb);

Which is called when a marker is enabled. The markers are listed in a
table which is defined by the DEFINE_MARKER_TP() macros.

Thanks,

Mathieu

> 
>  
> 
> Thanks
> 
> Jyoti
> 
> -- 
> IMPORTANT NOTICE: The contents of this email and any attachments are
confidential and may also be privileged. If you are not the intended
recipient, please notify the sender immediately and do not disclose the
contents to any other person, use it for any purpose, or store or copy
the information in any medium.  Thank you.

> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev


-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com
-- 
IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium.  Thank you.

[ltt-dev] LLTng probes

[Mathieu Desnoyers]

probe_irq_exit is the callback that the tracepoint will call.

So we have, at the moment, for "optimized probes" (written by hand, not
serialized dynamically):

tracepoint -> probe_irq_exit -> ltt_specialized_trace()

These "optimized probes" skip the marker code entirely. They are only
tied to markers for the event type definitions.

Thanks,

Mathieu


* Jyotiswarup Raiturkar (Jyotiswarup.Raiturkar at arm.com) wrote:
> >> The probes are connected to the tracepoints with: kernel:marker.c:
> set_marker()
> 
> Actually my question was where is the actual trace out call made? For
> example for the tracepoint defined by DEFINE_TRACE(irq_exit), the trace
> out call is trace_irq_exit(). Similarly there is a trace marker called
> DEFINE_MARKER_TP() for irq_exit :
> Kernel-trace.c : 
> 	DEFINE_MARKER_TP(kernel, irq_exit, irq_exit, probe_irq_exit,
> "handled #1u%u");
> 
> But I don't see how this marker is actually hit during execution. What
> is the call similar to trace_irq_exit() for the Tracepoint?
> 
> Thanks
> Jyotiswarup Raiturkar
> 
> -----Original Message-----
> From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] 
> Sent: Wednesday, May 19, 2010 8:00 PM
> To: Jyotiswarup Raiturkar
> Cc: ltt-dev at lists.casi.polymtl.ca
> Subject: Re: [ltt-dev] LLTng probes
> 
> * Jyotiswarup Raiturkar (Jyotiswarup.Raiturkar at arm.com) wrote:
> > Hello
> > 
> >  
> > 
> > I'm looking at LTTng working inside the kernel, and trying to
> understand
> > the instrumentation.
> > 
> >  
> > 
> > However, I am not able to see how the DEFINE_MARKER_TP() macros and
> > other probe_* functions in kernel-trace.c are actually used . As I
> > understand it, to make the actual trace, modules would have to call
> the
> > probe_* functions; yet I'm not able to locate these calls.
> 
> The probes are connected to the tracepoints with:
> 
> kernel:marker.c: set_marker()
> 
>                      ret = tracepoint_probe_register_noupdate(
>                                 elem->tp_name,
>                                 elem->tp_cb);
> 
> Which is called when a marker is enabled. The markers are listed in a
> table which is defined by the DEFINE_MARKER_TP() macros.
> 
> Thanks,
> 
> Mathieu
> 
> > 
> >  
> > 
> > Thanks
> > 
> > Jyoti
> > 
> > -- 
> > IMPORTANT NOTICE: The contents of this email and any attachments are
> confidential and may also be privileged. If you are not the intended
> recipient, please notify the sender immediately and do not disclose the
> contents to any other person, use it for any purpose, or store or copy
> the information in any medium.  Thank you.
> 
> > _______________________________________________
> > ltt-dev mailing list
> > ltt-dev at lists.casi.polymtl.ca
> > http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 
> 
> -- 
> Mathieu Desnoyers
> Operating System Efficiency R&D Consultant
> EfficiOS Inc.
> http://www.efficios.com
> -- 
> IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium.  Thank you.
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com

[ltt-dev] LTT UserSpace Tracer, broken?

[jpaul]

So, I'm switching modes and attempting to get the "user space tracer" up and running. I'm following the instructions provided here:

http://lttng.org/files/ust/manual/ust.html

I've downloaded and built the following packages:

    libkcompat-0.2.tar.gz
    ust-0.4.tar.gz
    userspace-rcu-0.4.3.tar.bz2
    lttv-0.12.31-04072010.tar.gz

First issue: ust-0.4 will not compile due to an undefined reference to sched_getcpu(). I'm using the latest version of Redhat Enterprise 5.5 and my installed glibc doesn't have that method defined (gcc version=4.3.4, glibc version=2.5-49 .. believe this method came into being around glibc-2.6?). Knowing that upgrading glibc is not a trivial process (as I've actually taken down a machine by doing so incorrectly), I'm not confident that most users may not want to go that route. I've downloaded glib2-2.11 and pulled some code out of that library to place the following in serialize.c:

// Added to avoid upgrading glibc
int
sched_getcpu (void)
{
#ifdef __NR_getcpu
  unsigned int cpu;
//  int r = INLINE_SYSCALL (getcpu, 3, &cpu, NULL, NULL);
  int r = syscall(SYS_getcpu, 3, &cpu, NULL, NULL);

  return r == -1 ? r : cpu;
#else
  __set_errno (ENOSYS);
  return -1;
#endif
}

That may or may not be the cause of some follow-on issues. Maybe glibc "really" needs to be upgraded to effectively use the userspace tracer .. please comment if so and I go that route next. Also, note that I'm doing all this work at "root", so there should be no permissions issues.

Next, I attempted to build and run the "quick start" code as detailed in the instructions (copying that code into ustTest.c):

gcc -o ustTest -g -Wall ustTest.c -lust

# usttrace ./ustTest
/usr/local/bin/usttrace: line 156: 23606 Segmentation fault      $CMD 2>&1
Waiting for ustd to shutdown...
Trace was output in:  /root/.usttraces/machineName-20100520172047665580280

# lttv -m textDump -t  /root/.usttraces/machineName-20100520172047665580280
** (process:23613): WARNING **: Trace /root/.usttraces/machineName-20100520172047665580280 has no metadata tracefile
** (process:23613): CRITICAL **: cannot open trace /root/.usttraces/machineName-20100520172047665580280
/usr/local/bin/lttv: line 15: 23613 Segmentation fault      $0.real $*

So, next I gave up on the command line attempts and tried to get things up and running manually (still using the provided instructions).

mkdir /tmp/ustsocks   <- not sure this is correct anymore, may have changed to: /tmp/ust-app-socks
mkdir /tmp/trace
ustd &
./ustTest &
[7] 23652

My ustTest was changed as follows before running that executable:

int main(int argc, char **argv)
{
    int v = 23;
    char *st = "test23";

    for(;;)
    {
    trace_mark(main, 23, "firstarg %d secondarg %s", v, st);

    /* another marker without arguments: */
    trace_mark(main, 24, MARK_NOARGS);
    sleep(30);
    }

    return 0;
}

# ustctl --list-markers 23652
{PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x3301d0}
{PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x3301e3}
{PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x330d63}
{PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x331483}
{PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x332b35}
{PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x332be6}
{PID: 23652, channel/marker: ust/potential_exec, state: 0, fmt: " " 0x33d9b6}
{PID: 23652, channel/marker: main/23, state: 0, fmt: "firstarg %d secondarg %s" 0x8048763}
{PID: 23652, channel/marker: main/24, state: 0, fmt: " " 0x80487aa}
{PID: 23652, channel/marker: ust/dummymark, state: 0, fmt: " " 0x8048893}

ustctl --enable-marker main/23 23652

# ustctl --create-trace 23652
# ustctl --start-trace 23652
ustd[23630/23663]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
libustcomm[23630/23666]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
ustd[23630/23666]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
ustd[23630/23666]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
ustd[23630/23664]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
libustcomm[23630/23665]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
ustd[23630/23665]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
ustd[23630/23665]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
[7]+  Segmentation fault      ./ustTest

# ustctl --stop-trace 23652
libustcomm[23668/23668]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
ustctl[23668/23668]: Error: could not connect to PID 23652 (in ustcmd_send_cmd() at ../libustcmd/ustcmd.c:439)
ustctl[23668/23668]: Error: error while trying to stop trace for PID 23652
 (in main() at ustctl.c:230)

Machine info (non-RT kernel): Intel Core2 Duo
# uname -a
Linux machineName 2.6.18-194.3.1.el5PAE #1 SMP Sun May 2 04:42:25 EDT 2010 i686 i686 i386 GNU/Linux

So ... could the above be related to my glibc patch (or not having a later version of glibc) or are things more broken as they appear?  Maybe I'm missing additional steps that are not documented?

Also a suggestion: for large programs, of many developers and lots of code, it might be somewhat of a hassle to have to enable each and every marker. I would suggest adding a "--enable-all-markers" capability to ustctl.

Thanks

JP




--
This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated.

[ltt-dev] LTT UserSpace Tracer, broken?

[Mathieu Desnoyers]

* jpaul at gdrs.com (jpaul at gdrs.com) wrote:
> So, I'm switching modes and attempting to get the "user space tracer" up and running. I'm following the instructions provided here:
> 
> http://lttng.org/files/ust/manual/ust.html
> 
> I've downloaded and built the following packages:
> 
>     libkcompat-0.2.tar.gz
>     ust-0.4.tar.gz
>     userspace-rcu-0.4.3.tar.bz2
>     lttv-0.12.31-04072010.tar.gz
> 
> First issue: ust-0.4 will not compile due to an undefined reference to sched_getcpu(). I'm using the latest version of Redhat Enterprise 5.5 and my installed glibc doesn't have that method defined (gcc version=4.3.4, glibc version=2.5-49 .. believe this method came into being around glibc-2.6?). Knowing that upgrading glibc is not a trivial process (as I've actually taken down a machine by doing so incorrectly), I'm not confident that most users may not want to go that route. I've downloaded glib2-2.11 and pulled some code out of that library to place the following in serialize.c:
> 
> // Added to avoid upgrading glibc
> int
> sched_getcpu (void)
> {
> #ifdef __NR_getcpu
>   unsigned int cpu;
> //  int r = INLINE_SYSCALL (getcpu, 3, &cpu, NULL, NULL);
>   int r = syscall(SYS_getcpu, 3, &cpu, NULL, NULL);
> 
>   return r == -1 ? r : cpu;
> #else
>   __set_errno (ENOSYS);
>   return -1;
> #endif
> }

Hi,

I'll let Pierre-Marc reply to the rest of this UST-specific question. I
think it would make sense to deploy this sched_getcpu fallback in UST
headers so we could support older glibc versions. We should probably
find a way is glibc is recent enough or not to wrap this fallback into
the appropriate ifdefs.

But that doesn't solve the rest of the issues you are facing.

Thanks,

Mathieu

> 
> That may or may not be the cause of some follow-on issues. Maybe glibc "really" needs to be upgraded to effectively use the userspace tracer .. please comment if so and I go that route next. Also, note that I'm doing all this work at "root", so there should be no permissions issues.
> 
> Next, I attempted to build and run the "quick start" code as detailed in the instructions (copying that code into ustTest.c):
> 
> gcc -o ustTest -g -Wall ustTest.c -lust
> 
> # usttrace ./ustTest
> /usr/local/bin/usttrace: line 156: 23606 Segmentation fault      $CMD 2>&1
> Waiting for ustd to shutdown...
> Trace was output in:  /root/.usttraces/machineName-20100520172047665580280
> 
> # lttv -m textDump -t  /root/.usttraces/machineName-20100520172047665580280
> ** (process:23613): WARNING **: Trace /root/.usttraces/machineName-20100520172047665580280 has no metadata tracefile
> ** (process:23613): CRITICAL **: cannot open trace /root/.usttraces/machineName-20100520172047665580280
> /usr/local/bin/lttv: line 15: 23613 Segmentation fault      $0.real $*
> 
> So, next I gave up on the command line attempts and tried to get things up and running manually (still using the provided instructions).
> 
> mkdir /tmp/ustsocks   <- not sure this is correct anymore, may have changed to: /tmp/ust-app-socks
> mkdir /tmp/trace
> ustd &
> ./ustTest &
> [7] 23652
> 
> My ustTest was changed as follows before running that executable:
> 
> int main(int argc, char **argv)
> {
>     int v = 23;
>     char *st = "test23";
> 
>     for(;;)
>     {
>     trace_mark(main, 23, "firstarg %d secondarg %s", v, st);
> 
>     /* another marker without arguments: */
>     trace_mark(main, 24, MARK_NOARGS);
>     sleep(30);
>     }
> 
>     return 0;
> }
> 
> # ustctl --list-markers 23652
> {PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x3301d0}
> {PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x3301e3}
> {PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x330d63}
> {PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x331483}
> {PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x332b35}
> {PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x332be6}
> {PID: 23652, channel/marker: ust/potential_exec, state: 0, fmt: " " 0x33d9b6}
> {PID: 23652, channel/marker: main/23, state: 0, fmt: "firstarg %d secondarg %s" 0x8048763}
> {PID: 23652, channel/marker: main/24, state: 0, fmt: " " 0x80487aa}
> {PID: 23652, channel/marker: ust/dummymark, state: 0, fmt: " " 0x8048893}
> 
> ustctl --enable-marker main/23 23652
> 
> # ustctl --create-trace 23652
> # ustctl --start-trace 23652
> ustd[23630/23663]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> libustcomm[23630/23666]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[23630/23666]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[23630/23666]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> ustd[23630/23664]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> libustcomm[23630/23665]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[23630/23665]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[23630/23665]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> [7]+  Segmentation fault      ./ustTest
> 
> # ustctl --stop-trace 23652
> libustcomm[23668/23668]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustctl[23668/23668]: Error: could not connect to PID 23652 (in ustcmd_send_cmd() at ../libustcmd/ustcmd.c:439)
> ustctl[23668/23668]: Error: error while trying to stop trace for PID 23652
>  (in main() at ustctl.c:230)
> 
> Machine info (non-RT kernel): Intel Core2 Duo
> # uname -a
> Linux machineName 2.6.18-194.3.1.el5PAE #1 SMP Sun May 2 04:42:25 EDT 2010 i686 i686 i386 GNU/Linux
> 
> So ... could the above be related to my glibc patch (or not having a later version of glibc) or are things more broken as they appear?  Maybe I'm missing additional steps that are not documented?
> 
> Also a suggestion: for large programs, of many developers and lots of code, it might be somewhat of a hassle to have to enable each and every marker. I would suggest adding a "--enable-all-markers" capability to ustctl.
> 
> Thanks
> 
> JP
> 
> 
> 
> 
> --
> This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated.
> 
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com

[ltt-dev] LLTng probes

[Jyotiswarup Raiturkar]

Ok I think I'm beginning to understand the scheme. For a tracepoint like
irq_exit, DECLARE_MARKER_TP() defines an corresponding marker. And when
set_marker() is called, the probe callback mentioned in
DEFINE_MARKER_TP() gets attached to the tracepoint. The tracepoint
itself is hit when the trace_* (trace_irq_exit) is called by the
module/subsystem performing the trace. Is this understanding correct?

Couple of more questions though:
- Why is this better/"optimized" instead of just calling
register_trace_* (register_trace_irq_exit )?
- set_marker() is called by marker_update_probe_range() which is called
when probe functions are registered/unregistered, and modules are
loaded/unloaded. But you said below that this is called when markers are
'enabled'. Does registering a probe function, enable a marker?

I'm trying to attach custom probes, to the kernel markers and
tracepoints; hence all the questions.

Thanks
Jyotiswarup

-----Original Message-----
From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] 
Sent: Thursday, May 20, 2010 7:34 PM
To: Jyotiswarup Raiturkar
Cc: ltt-dev at lists.casi.polymtl.ca
Subject: Re: [ltt-dev] LLTng probes

probe_irq_exit is the callback that the tracepoint will call.

So we have, at the moment, for "optimized probes" (written by hand, not
serialized dynamically):

tracepoint -> probe_irq_exit -> ltt_specialized_trace()

These "optimized probes" skip the marker code entirely. They are only
tied to markers for the event type definitions.

Thanks,

Mathieu


* Jyotiswarup Raiturkar (Jyotiswarup.Raiturkar at arm.com) wrote:
> >> The probes are connected to the tracepoints with: kernel:marker.c:
> set_marker()
> 
> Actually my question was where is the actual trace out call made? For
> example for the tracepoint defined by DEFINE_TRACE(irq_exit), the
trace
> out call is trace_irq_exit(). Similarly there is a trace marker called
> DEFINE_MARKER_TP() for irq_exit :
> Kernel-trace.c : 
> 	DEFINE_MARKER_TP(kernel, irq_exit, irq_exit, probe_irq_exit,
> "handled #1u%u");
> 
> But I don't see how this marker is actually hit during execution. What
> is the call similar to trace_irq_exit() for the Tracepoint?
> 
> Thanks
> Jyotiswarup Raiturkar
> 
> -----Original Message-----
> From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] 
> Sent: Wednesday, May 19, 2010 8:00 PM
> To: Jyotiswarup Raiturkar
> Cc: ltt-dev at lists.casi.polymtl.ca
> Subject: Re: [ltt-dev] LLTng probes
> 
> * Jyotiswarup Raiturkar (Jyotiswarup.Raiturkar at arm.com) wrote:
> > Hello
> > 
> >  
> > 
> > I'm looking at LTTng working inside the kernel, and trying to
> understand
> > the instrumentation.
> > 
> >  
> > 
> > However, I am not able to see how the DEFINE_MARKER_TP() macros and
> > other probe_* functions in kernel-trace.c are actually used . As I
> > understand it, to make the actual trace, modules would have to call
> the
> > probe_* functions; yet I'm not able to locate these calls.
> 
> The probes are connected to the tracepoints with:
> 
> kernel:marker.c: set_marker()
> 
>                      ret = tracepoint_probe_register_noupdate(
>                                 elem->tp_name,
>                                 elem->tp_cb);
> 
> Which is called when a marker is enabled. The markers are listed in a
> table which is defined by the DEFINE_MARKER_TP() macros.
> 
> Thanks,
> 
> Mathieu
> 
> > 
> >  
> > 
> > Thanks
> > 
> > Jyoti
> > 
> > -- 
> > IMPORTANT NOTICE: The contents of this email and any attachments are
> confidential and may also be privileged. If you are not the intended
> recipient, please notify the sender immediately and do not disclose
the
> contents to any other person, use it for any purpose, or store or copy
> the information in any medium.  Thank you.
> 
> > _______________________________________________
> > ltt-dev mailing list
> > ltt-dev at lists.casi.polymtl.ca
> > http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 
> 
> -- 
> Mathieu Desnoyers
> Operating System Efficiency R&D Consultant
> EfficiOS Inc.
> http://www.efficios.com
> -- 
> IMPORTANT NOTICE: The contents of this email and any attachments are
confidential and may also be privileged. If you are not the intended
recipient, please notify the sender immediately and do not disclose the
contents to any other person, use it for any purpose, or store or copy
the information in any medium.  Thank you.
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com
-- 
IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium.  Thank you.

[ltt-dev] LLTng probes

[Mathieu Desnoyers]

* Jyotiswarup Raiturkar (Jyotiswarup.Raiturkar at arm.com) wrote:
> Ok I think I'm beginning to understand the scheme. For a tracepoint like
> irq_exit, DECLARE_MARKER_TP() defines an corresponding marker. And when
> set_marker() is called, the probe callback mentioned in
> DEFINE_MARKER_TP() gets attached to the tracepoint. The tracepoint
> itself is hit when the trace_* (trace_irq_exit) is called by the
> module/subsystem performing the trace. Is this understanding correct?

Yes.

> 
> Couple of more questions though:
> - Why is this better/"optimized" instead of just calling
> register_trace_* (register_trace_irq_exit )?

see ltt-serialize.c which provides a "generic" serializer. But it's
slower. The "custom" serializer require that the programmer write code
for each event, hence the "specialized". Note that I will replace all
this by TRACE_EVENT() eventually.

> - set_marker() is called by marker_update_probe_range() which is called
> when probe functions are registered/unregistered, and modules are
> loaded/unloaded. But you said below that this is called when markers are
> 'enabled'. Does registering a probe function, enable a marker?

Yes.

> 
> I'm trying to attach custom probes, to the kernel markers and
> tracepoints; hence all the questions.

No problem. I'm glad to help you clarify this.

Thanks,

Mathieu

> 
> Thanks
> Jyotiswarup
> 
> -----Original Message-----
> From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] 
> Sent: Thursday, May 20, 2010 7:34 PM
> To: Jyotiswarup Raiturkar
> Cc: ltt-dev at lists.casi.polymtl.ca
> Subject: Re: [ltt-dev] LLTng probes
> 
> probe_irq_exit is the callback that the tracepoint will call.
> 
> So we have, at the moment, for "optimized probes" (written by hand, not
> serialized dynamically):
> 
> tracepoint -> probe_irq_exit -> ltt_specialized_trace()
> 
> These "optimized probes" skip the marker code entirely. They are only
> tied to markers for the event type definitions.
> 
> Thanks,
> 
> Mathieu
> 
> 
> * Jyotiswarup Raiturkar (Jyotiswarup.Raiturkar at arm.com) wrote:
> > >> The probes are connected to the tracepoints with: kernel:marker.c:
> > set_marker()
> > 
> > Actually my question was where is the actual trace out call made? For
> > example for the tracepoint defined by DEFINE_TRACE(irq_exit), the
> trace
> > out call is trace_irq_exit(). Similarly there is a trace marker called
> > DEFINE_MARKER_TP() for irq_exit :
> > Kernel-trace.c : 
> > 	DEFINE_MARKER_TP(kernel, irq_exit, irq_exit, probe_irq_exit,
> > "handled #1u%u");
> > 
> > But I don't see how this marker is actually hit during execution. What
> > is the call similar to trace_irq_exit() for the Tracepoint?
> > 
> > Thanks
> > Jyotiswarup Raiturkar
> > 
> > -----Original Message-----
> > From: Mathieu Desnoyers [mailto:compudj@krystal.dyndns.org] 
> > Sent: Wednesday, May 19, 2010 8:00 PM
> > To: Jyotiswarup Raiturkar
> > Cc: ltt-dev at lists.casi.polymtl.ca
> > Subject: Re: [ltt-dev] LLTng probes
> > 
> > * Jyotiswarup Raiturkar (Jyotiswarup.Raiturkar at arm.com) wrote:
> > > Hello
> > > 
> > >  
> > > 
> > > I'm looking at LTTng working inside the kernel, and trying to
> > understand
> > > the instrumentation.
> > > 
> > >  
> > > 
> > > However, I am not able to see how the DEFINE_MARKER_TP() macros and
> > > other probe_* functions in kernel-trace.c are actually used . As I
> > > understand it, to make the actual trace, modules would have to call
> > the
> > > probe_* functions; yet I'm not able to locate these calls.
> > 
> > The probes are connected to the tracepoints with:
> > 
> > kernel:marker.c: set_marker()
> > 
> >                      ret = tracepoint_probe_register_noupdate(
> >                                 elem->tp_name,
> >                                 elem->tp_cb);
> > 
> > Which is called when a marker is enabled. The markers are listed in a
> > table which is defined by the DEFINE_MARKER_TP() macros.
> > 
> > Thanks,
> > 
> > Mathieu
> > 
> > > 
> > >  
> > > 
> > > Thanks
> > > 
> > > Jyoti
> > > 
> > > -- 
> > > IMPORTANT NOTICE: The contents of this email and any attachments are
> > confidential and may also be privileged. If you are not the intended
> > recipient, please notify the sender immediately and do not disclose
> the
> > contents to any other person, use it for any purpose, or store or copy
> > the information in any medium.  Thank you.
> > 
> > > _______________________________________________
> > > ltt-dev mailing list
> > > ltt-dev at lists.casi.polymtl.ca
> > > http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> > 
> > 
> > -- 
> > Mathieu Desnoyers
> > Operating System Efficiency R&D Consultant
> > EfficiOS Inc.
> > http://www.efficios.com
> > -- 
> > IMPORTANT NOTICE: The contents of this email and any attachments are
> confidential and may also be privileged. If you are not the intended
> recipient, please notify the sender immediately and do not disclose the
> contents to any other person, use it for any purpose, or store or copy
> the information in any medium.  Thank you.
> > 
> 
> -- 
> Mathieu Desnoyers
> Operating System Efficiency R&D Consultant
> EfficiOS Inc.
> http://www.efficios.com
> -- 
> IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium.  Thank you.
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com

[ltt-dev] LTT UserSpace Tracer, broken?

[Pierre-Marc Fournier]

jpaul at gdrs.com wrote:
> So, I'm switching modes and attempting to get the "user space tracer" up and running. I'm following the instructions provided here:
> 
> http://lttng.org/files/ust/manual/ust.html
> 
> I've downloaded and built the following packages:
> 
>     libkcompat-0.2.tar.gz
>     ust-0.4.tar.gz
>     userspace-rcu-0.4.3.tar.bz2
>     lttv-0.12.31-04072010.tar.gz
> 
> First issue: ust-0.4 will not compile due to an undefined reference to sched_getcpu(). I'm using the latest version of Redhat Enterprise 5.5 and my installed glibc doesn't have that method defined (gcc version=4.3.4, glibc version=2.5-49 .. believe this method came into being around glibc-2.6?). Knowing that upgrading glibc is not a trivial process (as I've actually taken down a machine by doing so incorrectly), I'm not confident that most users may not want to go that route. I've downloaded glib2-2.11 and pulled some code out of that library to place the following in serialize.c:
> 
> // Added to avoid upgrading glibc
> int
> sched_getcpu (void)
> {
> #ifdef __NR_getcpu
>   unsigned int cpu;
> //  int r = INLINE_SYSCALL (getcpu, 3, &cpu, NULL, NULL);
>   int r = syscall(SYS_getcpu, 3, &cpu, NULL, NULL);
> 
>   return r == -1 ? r : cpu;
> #else
>   __set_errno (ENOSYS);
>   return -1;
> #endif
> }

Yes you need glibc 2.6 to have sched_getcpu. However, on my system, it 
is a vsyscall, therefore you cannot call it with syscall().

> 
> That may or may not be the cause of some follow-on issues. Maybe glibc "really" needs to be upgraded to effectively use the userspace tracer .. please comment if so and I go that route next. Also, note that I'm doing all this work at "root", so there should be no permissions issues.
> 
> Next, I attempted to build and run the "quick start" code as detailed in the instructions (copying that code into ustTest.c):
> 
> gcc -o ustTest -g -Wall ustTest.c -lust
> 
> # usttrace ./ustTest
> /usr/local/bin/usttrace: line 156: 23606 Segmentation fault      $CMD 2>&1
> Waiting for ustd to shutdown...
> Trace was output in:  /root/.usttraces/machineName-20100520172047665580280

Hmmm... what is the use of the "3" you are passing as argument to 
syscall()? This appears to be an invalid pointer, which results in -1 
being returned by the syscall and consequently a segfault.

> 
> # lttv -m textDump -t  /root/.usttraces/machineName-20100520172047665580280
> ** (process:23613): WARNING **: Trace /root/.usttraces/machineName-20100520172047665580280 has no metadata tracefile
> ** (process:23613): CRITICAL **: cannot open trace /root/.usttraces/machineName-20100520172047665580280
> /usr/local/bin/lttv: line 15: 23613 Segmentation fault      $0.real $*
> 
> So, next I gave up on the command line attempts and tried to get things up and running manually (still using the provided instructions).
> 
> mkdir /tmp/ustsocks   <- not sure this is correct anymore, may have changed to: /tmp/ust-app-socks

Thanks, fixed in the manual.

> mkdir /tmp/trace
> ustd &
> ./ustTest &
> [7] 23652
> 
> My ustTest was changed as follows before running that executable:
> 
> int main(int argc, char **argv)
> {
>     int v = 23;
>     char *st = "test23";
> 
>     for(;;)
>     {
>     trace_mark(main, 23, "firstarg %d secondarg %s", v, st);
> 
>     /* another marker without arguments: */
>     trace_mark(main, 24, MARK_NOARGS);
>     sleep(30);
>     }
> 
>     return 0;
> }
> 
> # ustctl --list-markers 23652
> {PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x3301d0}
> {PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x3301e3}
> {PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x330d63}
> {PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x331483}
> {PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x332b35}
> {PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x332be6}
> {PID: 23652, channel/marker: ust/potential_exec, state: 0, fmt: " " 0x33d9b6}
> {PID: 23652, channel/marker: main/23, state: 0, fmt: "firstarg %d secondarg %s" 0x8048763}
> {PID: 23652, channel/marker: main/24, state: 0, fmt: " " 0x80487aa}
> {PID: 23652, channel/marker: ust/dummymark, state: 0, fmt: " " 0x8048893}
> 
> ustctl --enable-marker main/23 23652
> 
> # ustctl --create-trace 23652
> # ustctl --start-trace 23652
> ustd[23630/23663]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> libustcomm[23630/23666]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[23630/23666]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[23630/23666]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> ustd[23630/23664]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> libustcomm[23630/23665]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[23630/23665]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[23630/23665]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> [7]+  Segmentation fault      ./ustTest
> 
> # ustctl --stop-trace 23652
> libustcomm[23668/23668]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustctl[23668/23668]: Error: could not connect to PID 23652 (in ustcmd_send_cmd() at ../libustcmd/ustcmd.c:439)
> ustctl[23668/23668]: Error: error while trying to stop trace for PID 23652
>  (in main() at ustctl.c:230)
> 
> Machine info (non-RT kernel): Intel Core2 Duo
> # uname -a
> Linux machineName 2.6.18-194.3.1.el5PAE #1 SMP Sun May 2 04:42:25 EDT 2010 i686 i686 i386 GNU/Linux
> 
> So ... could the above be related to my glibc patch (or not having a later version of glibc) or are things more broken as they appear?  Maybe I'm missing additional steps that are not documented?
> 
> Also a suggestion: for large programs, of many developers and lots of code, it might be somewhat of a hassle to have to enable each and every marker. I would suggest adding a "--enable-all-markers" capability to ustctl.

Good idea. In the meantime, you can start your program with the 
UST_AUTOPROBE=1 environment var, which will have the same effect. When 
you use usttrace, this is done automatically.

> 
> Thanks
> 
> JP
> 
> 
> 
> 
> --
> This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated.
> 
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev

[ltt-dev] LTT UserSpace Tracer, broken?

[jpaul]

Thanks Pierre-Marc.  That will teach me to post something to a public board without double checking the interface first. The "3" below was a cut/paste issue from some glibc code (sched_getcpu.c) and I've replaced that coding line with:

  int r = syscall(SYS_getcpu, &cpu);

I've verified the proper operation of the above call in a separate test program. I've rebuild everything after making that change. Unfortunately, that does not get rid of the segmentation fault with usttrace:

# usttrace ./ustTest
/usr/local/bin/usttrace: line 156: 20724 Segmentation fault      $CMD 2>&1
Waiting for ustd to shutdown...
Trace was output in:  /root/.usttraces/machineName-20100524100514656225139

Nor does this resolve the issue with the application seg-faulting with ustd:

# export UST_AUTOPROBE=1
# gcc -o ustTest ustTest.c -lust
# mkdir /tmp/trace                 <- ust-app-socks already present
# ustd &
# ./ustTest &

# ustctl --create-trace 20798
# ustctl --start-trace 20798

libustcomm[20795/20812]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
ustd[20795/20812]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
ustd[20795/20812]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
libustcomm[20795/20813]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
ustd[20795/20813]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
ustd[20795/20813]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
libustcomm[20795/20814]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
ustd[20795/20814]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
ustd[20795/20814]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
libustcomm[20795/20815]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
ustd[20795/20815]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
ustd[20795/20815]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
ustd[20795/20810]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
ustd[20795/20811]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
[6]+  Segmentation fault      ./ustTest

# ls /tmp/ust-app-socks/
20798  ustd

I'm guessing that ustd is complaining as my test application dumped and is no longer active. Looking at a core dump of my test app, it appears that the seg fault occurred at the following line of _rcu_read_unlock():

  _STORE_SHARED(rcu_reader->ctr, rcu_reader->ctr - RCU_GP_COUNT);

Which was called from ltt_vtrace(). But that only seems to fail when the syscall(getcpu) returns with a -1. I actually changed ltt_vtrace() code as follows:

{
//	cpu = ust_get_cpu();
  int r = syscall(SYS_getcpu, &cpu);
  if (r == -1)
    cpu = r;
  if (cpu == -1)
    printf(".. invalid cpu %s (%d)\n", strerror(errno), errno);
}

And had the following print out:

.. invalid cpu Bad address (14)

So ... it appears that something isn't working correctly to make that syscall here. Not really sure why this is failing .. maybe a thread related issue? It doesn't fail every time. Maybe best to upgrade the latest glibc and try again with the inline methods? It is important to note that the following code comes directly from glibc-2.11 and sched_getcpu() can return a -1 upon a failed INLINE_SYSCALL. Would suggest that ltt_vtrace() be changed to properly handle a -1 cpu value:

int
sched_getcpu (void)
{
#ifdef __NR_getcpu
  unsigned int cpu;
  int r = INLINE_SYSCALL (getcpu, 3, &cpu, NULL, NULL);

  return r == -1 ? r : cpu;
#else
  __set_errno (ENOSYS);
  return -1;
#endif
}

Other suggestions?

Thanks

JP

-----Original Message-----
From: Pierre-Marc Fournier [mailto:pierre-marc.fournier@polymtl.ca]
Sent: Fri 5/21/2010 2:49 PM
To: John P. Paul
Cc: ltt-dev at lists.casi.polymtl.ca; Kenneth R. Macfarlane; Mathieu Desnoyers
Subject: Re: [ltt-dev] LTT UserSpace Tracer, broken?
 
jpaul at gdrs.com wrote:
> So, I'm switching modes and attempting to get the "user space tracer" up and running. I'm following the instructions provided here:
> 
> http://lttng.org/files/ust/manual/ust.html
> 
> I've downloaded and built the following packages:
> 
>     libkcompat-0.2.tar.gz
>     ust-0.4.tar.gz
>     userspace-rcu-0.4.3.tar.bz2
>     lttv-0.12.31-04072010.tar.gz
> 
> First issue: ust-0.4 will not compile due to an undefined reference to sched_getcpu(). I'm using the latest version of Redhat Enterprise 5.5 and my installed glibc doesn't have that method defined (gcc version=4.3.4, glibc version=2.5-49 .. believe this method came into being around glibc-2.6?). Knowing that upgrading glibc is not a trivial process (as I've actually taken down a machine by doing so incorrectly), I'm not confident that most users may not want to go that route. I've downloaded glib2-2.11 and pulled some code out of that library to place the following in serialize.c:
> 
> // Added to avoid upgrading glibc
> int
> sched_getcpu (void)
> {
> #ifdef __NR_getcpu
>   unsigned int cpu;
> //  int r = INLINE_SYSCALL (getcpu, 3, &cpu, NULL, NULL);
>   int r = syscall(SYS_getcpu, 3, &cpu, NULL, NULL);
> 
>   return r == -1 ? r : cpu;
> #else
>   __set_errno (ENOSYS);
>   return -1;
> #endif
> }

Yes you need glibc 2.6 to have sched_getcpu. However, on my system, it 
is a vsyscall, therefore you cannot call it with syscall().

> 
> That may or may not be the cause of some follow-on issues. Maybe glibc "really" needs to be upgraded to effectively use the userspace tracer .. please comment if so and I go that route next. Also, note that I'm doing all this work at "root", so there should be no permissions issues.
> 
> Next, I attempted to build and run the "quick start" code as detailed in the instructions (copying that code into ustTest.c):
> 
> gcc -o ustTest -g -Wall ustTest.c -lust
> 
> # usttrace ./ustTest
> /usr/local/bin/usttrace: line 156: 23606 Segmentation fault      $CMD 2>&1
> Waiting for ustd to shutdown...
> Trace was output in:  /root/.usttraces/machineName-20100520172047665580280

Hmmm... what is the use of the "3" you are passing as argument to 
syscall()? This appears to be an invalid pointer, which results in -1 
being returned by the syscall and consequently a segfault.

> 
> # lttv -m textDump -t  /root/.usttraces/machineName-20100520172047665580280
> ** (process:23613): WARNING **: Trace /root/.usttraces/machineName-20100520172047665580280 has no metadata tracefile
> ** (process:23613): CRITICAL **: cannot open trace /root/.usttraces/machineName-20100520172047665580280
> /usr/local/bin/lttv: line 15: 23613 Segmentation fault      $0.real $*
> 
> So, next I gave up on the command line attempts and tried to get things up and running manually (still using the provided instructions).
> 
> mkdir /tmp/ustsocks   <- not sure this is correct anymore, may have changed to: /tmp/ust-app-socks

Thanks, fixed in the manual.

> mkdir /tmp/trace
> ustd &
> ./ustTest &
> [7] 23652
> 
> My ustTest was changed as follows before running that executable:
> 
> int main(int argc, char **argv)
> {
>     int v = 23;
>     char *st = "test23";
> 
>     for(;;)
>     {
>     trace_mark(main, 23, "firstarg %d secondarg %s", v, st);
> 
>     /* another marker without arguments: */
>     trace_mark(main, 24, MARK_NOARGS);
>     sleep(30);
>     }
> 
>     return 0;
> }
> 
> # ustctl --list-markers 23652
> {PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x3301d0}
> {PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x3301e3}
> {PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x330d63}
> {PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x331483}
> {PID: 23652, channel/marker: metadata/core_marker_format, state: 1, fmt: "channel %s name %s format %s" 0x332b35}
> {PID: 23652, channel/marker: metadata/core_marker_id, state: 1, fmt: "channel %s name %s event_id %hu int #1u%zu long #1u%zu pointer #1u%zu size_t #1u%zu alignment #1u%u" 0x332be6}
> {PID: 23652, channel/marker: ust/potential_exec, state: 0, fmt: " " 0x33d9b6}
> {PID: 23652, channel/marker: main/23, state: 0, fmt: "firstarg %d secondarg %s" 0x8048763}
> {PID: 23652, channel/marker: main/24, state: 0, fmt: " " 0x80487aa}
> {PID: 23652, channel/marker: ust/dummymark, state: 0, fmt: " " 0x8048893}
> 
> ustctl --enable-marker main/23 23652
> 
> # ustctl --create-trace 23652
> # ustctl --start-trace 23652
> ustd[23630/23663]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> libustcomm[23630/23666]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[23630/23666]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[23630/23666]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> ustd[23630/23664]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> libustcomm[23630/23665]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[23630/23665]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[23630/23665]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> [7]+  Segmentation fault      ./ustTest
> 
> # ustctl --stop-trace 23652
> libustcomm[23668/23668]: Error: connect (path=/tmp/ust-app-socks/23652): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustctl[23668/23668]: Error: could not connect to PID 23652 (in ustcmd_send_cmd() at ../libustcmd/ustcmd.c:439)
> ustctl[23668/23668]: Error: error while trying to stop trace for PID 23652
>  (in main() at ustctl.c:230)
> 
> Machine info (non-RT kernel): Intel Core2 Duo
> # uname -a
> Linux machineName 2.6.18-194.3.1.el5PAE #1 SMP Sun May 2 04:42:25 EDT 2010 i686 i686 i386 GNU/Linux
> 
> So ... could the above be related to my glibc patch (or not having a later version of glibc) or are things more broken as they appear?  Maybe I'm missing additional steps that are not documented?
> 
> Also a suggestion: for large programs, of many developers and lots of code, it might be somewhat of a hassle to have to enable each and every marker. I would suggest adding a "--enable-all-markers" capability to ustctl.

Good idea. In the meantime, you can start your program with the 
UST_AUTOPROBE=1 environment var, which will have the same effect. When 
you use usttrace, this is done automatically.

> 
> Thanks
> 
> JP
> 
> 
> 
> 
> --
> This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated.
> 
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev






--
This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated.

[ltt-dev] LTT UserSpace Tracer, broken?

[Pierre-Marc Fournier]

On 05/24/2010 01:11 PM, jpaul at gdrs.com wrote:
> Thanks Pierre-Marc.  That will teach me to post something to a public board without double checking the interface first. The "3" below was a cut/paste issue from some glibc code (sched_getcpu.c) and I've replaced that coding line with:
>
>    int r = syscall(SYS_getcpu,&cpu);
>
> I've verified the proper operation of the above call in a separate test program. I've rebuild everything after making that change. Unfortunately, that does not get rid of the segmentation fault with usttrace:
>
> # usttrace ./ustTest
> /usr/local/bin/usttrace: line 156: 20724 Segmentation fault      $CMD 2>&1
> Waiting for ustd to shutdown...
> Trace was output in:  /root/.usttraces/machineName-20100524100514656225139
>
> Nor does this resolve the issue with the application seg-faulting with ustd:
>
> # export UST_AUTOPROBE=1
> # gcc -o ustTest ustTest.c -lust
> # mkdir /tmp/trace<- ust-app-socks already present
> # ustd&
> # ./ustTest&
>
> # ustctl --create-trace 20798
> # ustctl --start-trace 20798
>
> libustcomm[20795/20812]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[20795/20812]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[20795/20812]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> libustcomm[20795/20813]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[20795/20813]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[20795/20813]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> libustcomm[20795/20814]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[20795/20814]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[20795/20814]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> libustcomm[20795/20815]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> ustd[20795/20815]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> ustd[20795/20815]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> ustd[20795/20810]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> ustd[20795/20811]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> [6]+  Segmentation fault      ./ustTest
>
> # ls /tmp/ust-app-socks/
> 20798  ustd
>
> I'm guessing that ustd is complaining as my test application dumped and is no longer active. Looking at a core dump of my test app, it appears that the seg fault occurred at the following line of _rcu_read_unlock():
>
>    _STORE_SHARED(rcu_reader->ctr, rcu_reader->ctr - RCU_GP_COUNT);
>
> Which was called from ltt_vtrace(). But that only seems to fail when the syscall(getcpu) returns with a -1. I actually changed ltt_vtrace() code as follows:
>
> {
> //	cpu = ust_get_cpu();
>    int r = syscall(SYS_getcpu,&cpu);
>    if (r == -1)
>      cpu = r;
>    if (cpu == -1)
>      printf(".. invalid cpu %s (%d)\n", strerror(errno), errno);
> }
>
> And had the following print out:
>
> .. invalid cpu Bad address (14)
>
> So ... it appears that something isn't working correctly to make that
> syscall here. Not really sure why this is failing .. maybe a thread
> related issue? It doesn't fail every time. Maybe best to upgrade the
> latest glibc and try again with the inline methods? It is important
> to note that the following code comes directly from glibc-2.11 and
> sched_getcpu() can return a -1 upon a failed INLINE_SYSCALL. Would
> suggest that ltt_vtrace() be changed to properly handle a -1 cpu
> value:
>

I believe the above code is failing some of the time with an "invalid 
address" because some pointers are missing in the call. You have only 1 
argument and you need 3.

I am not too enthousiastic at the idea of adding error checking for the 
getcpu call. The call should never fail and this is in the critical path 
of the tracer.

I would consider a patch with some preprocessor logic that chooses the 
right call based on the one available on the system. However, this patch 
must take into account the latest kernels which provide getcpu as a vdso.

By the way, you will get considerable performance penalty with this old 
libc. UST tries very hard not to make system calls in the tracing 
critical path because they are slow. The recent kernels/glibc's provide 
getcpu/sched_getcpu as a vdso, which helps a lot. If you are doing a 
real system call in the tracing path, this will result in a penalty.

pmf

[ltt-dev] LTT UserSpace Tracer, broken?

[Mathieu Desnoyers]

Hi,

Can you prepare a README patch for UST that specify dependency on glibc
2.6 in the README file along with a note telling which symbol is needed
(sched_getcpu) ? I'll recommend Pierre-Marc to pull it.

Thanks,

Mathieu

* jpaul at gdrs.com (jpaul at gdrs.com) wrote:
> Just an FYI: here's what RedHat tech support said:
> 
> There was a feature request for this symbol sched_getcpu in RHEL 5.x. Unfortunately, it was not approved due to the following reason. sched_getcpu is a GLIBC_2.6 symbol, so can not be added to RHEL5.x glibc, which is glibc 2.5. It would require all glibc 2.6 specific symbols get backported.  Since this is equivalent to a rebase, we would be unable to do this in this major release of RHEL. RHEL 6 will be shipped with glibc-2.11, which will be having all the required features.
> 
> -----Original Message-----
> From: jpaul@gdrs.com [mailto:jpaul@gdrs.com]
> Sent: Mon 6/7/2010 3:31 PM
> To: ltt-dev at lists.casi.polymtl.ca
> Cc: Kenneth R. Macfarlane
> Subject: Re: [ltt-dev] LTT UserSpace Tracer, broken?
>  
> Greetings:
> 
> Thought I'd provide an update here on efforts to get the user space tracer to work. Based on this web site:
> 
> http://www.kernel.org/doc/man-pages/online/pages/man2/getcpu.2.html
> 
> I do see that getcpu() can accept up to three arguments (this detail is somewhat hidden when using syscall), depending on the kernel version. Per my modified code below, I've tried both of the following:
> 
>   int r = syscall(SYS_getcpu,&cpu,NULL);
> 
> or
> 
>   int r = syscall(SYS_getcpu,&cpu,NULL,NULL);
> 
> Either of the above calls still result in a segmentation fault. As an FYI: I'm working with a 2.6.18 RedHat base kernel that has glibc 2.5-49 installed. Also installed on this same machine is a couple of 2.6.33 kernels (RT and non-RT), of which I have also tried. There is no glibc update from RedHat that goes beyond what I have listed (per a recent note from tech support). I have put in a request for an update that would specifically include sched_getcpu() ... I don't expect an update anytime soon.
> 
> I spent a good part of a day trying to manually update glibc to v2.11. No luck .. my attempts usually resulting in having to restore /usr/local due to corrupted systems calls. I've also tried installing glibc into a different location and building the ust library (by either changing arguments to configure or hand editing Makefiles) to just look at that new location ... this has not been successful either. Might still be some work that could be done to allow this type of build.
> 
> The above web site that I listed seems to indicate that getcpu was added in glibc 2.6 and appeared in kernels starting at 2.6.19 ... not really sure how we are seeing some indications of that working in the versions that I listed above.
> 
> Given these details, unless anyone has any suggestions, I'm currently under the assumption that there is a hard/fast dependence on glibc 2.6 for the user space tracer.
> 
> JP
> 
> -----Original Message-----
> From: Pierre-Marc Fournier [mailto:pierre-marc.fournier@polymtl.ca]
> Sent: Fri 5/28/2010 12:51 PM
> To: John P. Paul
> Cc: ltt-dev at lists.casi.polymtl.ca; Kenneth R. Macfarlane
> Subject: Re: [ltt-dev] LTT UserSpace Tracer, broken?
>  
> On 05/24/2010 01:11 PM, jpaul at gdrs.com wrote:
> > Thanks Pierre-Marc.  That will teach me to post something to a public board without double checking the interface first. The "3" below was a cut/paste issue from some glibc code (sched_getcpu.c) and I've replaced that coding line with:
> >
> >    int r = syscall(SYS_getcpu,&cpu);
> >
> > I've verified the proper operation of the above call in a separate test program. I've rebuild everything after making that change. Unfortunately, that does not get rid of the segmentation fault with usttrace:
> >
> > # usttrace ./ustTest
> > /usr/local/bin/usttrace: line 156: 20724 Segmentation fault      $CMD 2>&1
> > Waiting for ustd to shutdown...
> > Trace was output in:  /root/.usttraces/machineName-20100524100514656225139
> >
> > Nor does this resolve the issue with the application seg-faulting with ustd:
> >
> > # export UST_AUTOPROBE=1
> > # gcc -o ustTest ustTest.c -lust
> > # mkdir /tmp/trace<- ust-app-socks already present
> > # ustd&
> > # ./ustTest&
> >
> > # ustctl --create-trace 20798
> > # ustctl --start-trace 20798
> >
> > libustcomm[20795/20812]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> > ustd[20795/20812]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> > ustd[20795/20812]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> > libustcomm[20795/20813]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> > ustd[20795/20813]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> > ustd[20795/20813]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> > libustcomm[20795/20814]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> > ustd[20795/20814]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> > ustd[20795/20814]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> > libustcomm[20795/20815]: Error: connect (path=/tmp/ust-app-socks/20798): Connection refused (in ustcomm_connect_path() at ustcomm.c:581)
> > ustd[20795/20815]: Warning: unable to connect to process, it probably died before we were able to connect (in connect_buffer() at ustd.c:250)
> > ustd[20795/20815]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> > ustd[20795/20810]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> > ustd[20795/20811]: Error: failed to connect to buffer (in consumer_thread() at ustd.c:581)
> > [6]+  Segmentation fault      ./ustTest
> >
> > # ls /tmp/ust-app-socks/
> > 20798  ustd
> >
> > I'm guessing that ustd is complaining as my test application dumped and is no longer active. Looking at a core dump of my test app, it appears that the seg fault occurred at the following line of _rcu_read_unlock():
> >
> >    _STORE_SHARED(rcu_reader->ctr, rcu_reader->ctr - RCU_GP_COUNT);
> >
> > Which was called from ltt_vtrace(). But that only seems to fail when the syscall(getcpu) returns with a -1. I actually changed ltt_vtrace() code as follows:
> >
> > {
> > //	cpu = ust_get_cpu();
> >    int r = syscall(SYS_getcpu,&cpu);
> >    if (r == -1)
> >      cpu = r;
> >    if (cpu == -1)
> >      printf(".. invalid cpu %s (%d)\n", strerror(errno), errno);
> > }
> >
> > And had the following print out:
> >
> > .. invalid cpu Bad address (14)
> >
> > So ... it appears that something isn't working correctly to make that
> > syscall here. Not really sure why this is failing .. maybe a thread
> > related issue? It doesn't fail every time. Maybe best to upgrade the
> > latest glibc and try again with the inline methods? It is important
> > to note that the following code comes directly from glibc-2.11 and
> > sched_getcpu() can return a -1 upon a failed INLINE_SYSCALL. Would
> > suggest that ltt_vtrace() be changed to properly handle a -1 cpu
> > value:
> >
> 
> I believe the above code is failing some of the time with an "invalid 
> address" because some pointers are missing in the call. You have only 1 
> argument and you need 3.
> 
> I am not too enthousiastic at the idea of adding error checking for the 
> getcpu call. The call should never fail and this is in the critical path 
> of the tracer.
> 
> I would consider a patch with some preprocessor logic that chooses the 
> right call based on the one available on the system. However, this patch 
> must take into account the latest kernels which provide getcpu as a vdso.
> 
> By the way, you will get considerable performance penalty with this old 
> libc. UST tries very hard not to make system calls in the tracing 
> critical path because they are slow. The recent kernels/glibc's provide 
> getcpu/sched_getcpu as a vdso, which helps a lot. If you are doing a 
> real system call in the tracing path, this will result in a penalty.
> 
> pmf
> 
> 
> 
> 
> --
> This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated.
> 
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 
> 
> 
> --
> This is an e-mail from General Dynamics Robotic Systems. It is for the intended recipient only and may contain confidential and privileged information. No one else may read, print, store, copy, forward or act in reliance on it or its attachments. If you are not the intended recipient, please return this message to the sender and delete the message and any attachments from your computer. Your cooperation is appreciated.
> 
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com