* [ltt-dev] ltt channel thread safe?
2010-08-04 6:12 [ltt-dev] ltt channel thread safe? chris meyers
@ 2010-08-04 6:12 ` chris meyers
2010-08-04 6:12 ` chris meyers
` (2 subsequent siblings)
3 siblings, 0 replies; 9+ messages in thread
From: chris meyers @ 2010-08-04 6:12 UTC (permalink / raw)
To give a bit of context to the problem. I am using user space ltt to help
profile code. I have created two events, time_begin and time_end. The goal
is to allow for logging the runtime of specific code blocks via start()
stop() insertions.
I am having some issues with traces not coming out "correct" on the other
"end". Let me further explain what I mean by correct and end.
correct
trace_mark(ust, time_begin, "thread %d func %s depth %d extra %s", 0,
__FUNCTION__, 1, __FUNCTION__)
trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 0,
__FUNCTION__, 1, __FUNCTION__)
end
ust.time_begin: 30208.932264102
(/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
"memloc_request_response_decider", depth = 1, extra =
"memloc_request_response_decider" }
ust.time_end: 30208.932267455
(/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
"memloc_request_response_decider", depth = 1, extra =
"memloc_request_response_decider" }
Later on the output looks like this:
ust.time_begin: 30198.142843837
(/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func = "ne_worker_thread",
depth = 560296821, extra = "" }
Notice that in the trace_mark() code above I hard coded depth to be 0 and
_str is always __FUNCTION__.
Possible reasons:
* Buffer is being overrun. I changed the buffer size using the -N and -S
options in usttrace to something > 2 MB (plenty large).
* Channels are not thread-safe? I have 3 threads of execution in this
example. All using the ust channel.
* My code is crappy and I am overwriting the lust library buffer?
Also, I am having trouble using any channel other than ust. Is ust the only
channel available in user space?
Many thanks,
-Chris
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20100804/0436241d/attachment-0001.htm>
^ permalink raw reply [flat|nested] 9+ messages in thread* [ltt-dev] ltt channel thread safe?
2010-08-04 6:12 [ltt-dev] ltt channel thread safe? chris meyers
2010-08-04 6:12 ` chris meyers
@ 2010-08-04 6:12 ` chris meyers
2010-08-06 20:55 ` chris meyers
2010-08-10 4:28 ` Pierre-Marc Fournier
3 siblings, 0 replies; 9+ messages in thread
From: chris meyers @ 2010-08-04 6:12 UTC (permalink / raw)
To give a bit of context to the problem. I am using user space ltt to help
profile code. I have created two events, time_begin and time_end. The goal
is to allow for logging the runtime of specific code blocks via start()
stop() insertions.
I am having some issues with traces not coming out "correct" on the other
"end". Let me further explain what I mean by correct and end.
correct
trace_mark(ust, time_begin, "thread %d func %s depth %d extra %s", 0,
__FUNCTION__, 1, __FUNCTION__)
trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 0,
__FUNCTION__, 1, __FUNCTION__)
end
ust.time_begin: 30208.932264102
(/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
"memloc_request_response_decider", depth = 1, extra =
"memloc_request_response_decider" }
ust.time_end: 30208.932267455
(/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
"memloc_request_response_decider", depth = 1, extra =
"memloc_request_response_decider" }
Later on the output looks like this:
ust.time_begin: 30198.142843837
(/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func = "ne_worker_thread",
depth = 560296821, extra = "" }
Notice that in the trace_mark() code above I hard coded depth to be 0 and
_str is always __FUNCTION__.
Possible reasons:
* Buffer is being overrun. I changed the buffer size using the -N and -S
options in usttrace to something > 2 MB (plenty large).
* Channels are not thread-safe? I have 3 threads of execution in this
example. All using the ust channel.
* My code is crappy and I am overwriting the lust library buffer?
Also, I am having trouble using any channel other than ust. Is ust the only
channel available in user space?
Many thanks,
-Chris
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/ltt-dev/attachments/20100804/0436241d/attachment.htm>
^ permalink raw reply [flat|nested] 9+ messages in thread* [ltt-dev] ltt channel thread safe?
2010-08-04 6:12 [ltt-dev] ltt channel thread safe? chris meyers
2010-08-04 6:12 ` chris meyers
2010-08-04 6:12 ` chris meyers
@ 2010-08-06 20:55 ` chris meyers
2010-08-06 20:55 ` chris meyers
` (2 more replies)
2010-08-10 4:28 ` Pierre-Marc Fournier
3 siblings, 3 replies; 9+ messages in thread
From: chris meyers @ 2010-08-06 20:55 UTC (permalink / raw)
Forget any mention of threading being the reason. After trying way too many
things, removal of the __FUNCTION__ macro seems to "fix" the problem. Does
the __FUNCTION__ macro not play well with ltt? The binary trace file
seemed void of any error. It seemed as if the __FUNCTION__ macro had some
indirect influence on how the lttv -m textDump behaved.
-Chris
On Wed, Aug 4, 2010 at 2:12 AM, chris meyers <chris.meyers.fsu at gmail.com>wrote:
> To give a bit of context to the problem. I am using user space ltt to help
> profile code. I have created two events, time_begin and time_end. The goal
> is to allow for logging the runtime of specific code blocks via start()
> stop() insertions.
>
> I am having some issues with traces not coming out "correct" on the other
> "end". Let me further explain what I mean by correct and end.
>
> correct
> trace_mark(ust, time_begin, "thread %d func %s depth %d extra %s", 0,
> __FUNCTION__, 1, __FUNCTION__)
> trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 0,
> __FUNCTION__, 1, __FUNCTION__)
>
> end
> ust.time_begin: 30208.932264102
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> "memloc_request_response_decider", depth = 1, extra =
> "memloc_request_response_decider" }
> ust.time_end: 30208.932267455
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> "memloc_request_response_decider", depth = 1, extra =
> "memloc_request_response_decider" }
>
> Later on the output looks like this:
> ust.time_begin: 30198.142843837
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func = "ne_worker_thread",
> depth = 560296821, extra = "" }
>
> Notice that in the trace_mark() code above I hard coded depth to be 0 and
> _str is always __FUNCTION__.
>
> Possible reasons:
> * Buffer is being overrun. I changed the buffer size using the -N and -S
> options in usttrace to something > 2 MB (plenty large).
> * Channels are not thread-safe? I have 3 threads of execution in this
> example. All using the ust channel.
> * My code is crappy and I am overwriting the lust library buffer?
>
>
> Also, I am having trouble using any channel other than ust. Is ust the
> only channel available in user space?
>
> Many thanks,
> -Chris
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20100806/5aa70a13/attachment-0002.htm>
^ permalink raw reply [flat|nested] 9+ messages in thread* [ltt-dev] ltt channel thread safe?
2010-08-06 20:55 ` chris meyers
@ 2010-08-06 20:55 ` chris meyers
2010-08-06 20:55 ` chris meyers
2010-08-06 21:02 ` Mathieu Desnoyers
2 siblings, 0 replies; 9+ messages in thread
From: chris meyers @ 2010-08-06 20:55 UTC (permalink / raw)
Forget any mention of threading being the reason. After trying way too many
things, removal of the __FUNCTION__ macro seems to "fix" the problem. Does
the __FUNCTION__ macro not play well with ltt? The binary trace file
seemed void of any error. It seemed as if the __FUNCTION__ macro had some
indirect influence on how the lttv -m textDump behaved.
-Chris
On Wed, Aug 4, 2010 at 2:12 AM, chris meyers <chris.meyers.fsu at gmail.com>wrote:
> To give a bit of context to the problem. I am using user space ltt to help
> profile code. I have created two events, time_begin and time_end. The goal
> is to allow for logging the runtime of specific code blocks via start()
> stop() insertions.
>
> I am having some issues with traces not coming out "correct" on the other
> "end". Let me further explain what I mean by correct and end.
>
> correct
> trace_mark(ust, time_begin, "thread %d func %s depth %d extra %s", 0,
> __FUNCTION__, 1, __FUNCTION__)
> trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 0,
> __FUNCTION__, 1, __FUNCTION__)
>
> end
> ust.time_begin: 30208.932264102
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> "memloc_request_response_decider", depth = 1, extra =
> "memloc_request_response_decider" }
> ust.time_end: 30208.932267455
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> "memloc_request_response_decider", depth = 1, extra =
> "memloc_request_response_decider" }
>
> Later on the output looks like this:
> ust.time_begin: 30198.142843837
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func = "ne_worker_thread",
> depth = 560296821, extra = "" }
>
> Notice that in the trace_mark() code above I hard coded depth to be 0 and
> _str is always __FUNCTION__.
>
> Possible reasons:
> * Buffer is being overrun. I changed the buffer size using the -N and -S
> options in usttrace to something > 2 MB (plenty large).
> * Channels are not thread-safe? I have 3 threads of execution in this
> example. All using the ust channel.
> * My code is crappy and I am overwriting the lust library buffer?
>
>
> Also, I am having trouble using any channel other than ust. Is ust the
> only channel available in user space?
>
> Many thanks,
> -Chris
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20100806/5aa70a13/attachment-0001.htm>
^ permalink raw reply [flat|nested] 9+ messages in thread* [ltt-dev] ltt channel thread safe?
2010-08-06 20:55 ` chris meyers
2010-08-06 20:55 ` chris meyers
@ 2010-08-06 20:55 ` chris meyers
2010-08-06 21:02 ` Mathieu Desnoyers
2 siblings, 0 replies; 9+ messages in thread
From: chris meyers @ 2010-08-06 20:55 UTC (permalink / raw)
Forget any mention of threading being the reason. After trying way too many
things, removal of the __FUNCTION__ macro seems to "fix" the problem. Does
the __FUNCTION__ macro not play well with ltt? The binary trace file
seemed void of any error. It seemed as if the __FUNCTION__ macro had some
indirect influence on how the lttv -m textDump behaved.
-Chris
On Wed, Aug 4, 2010 at 2:12 AM, chris meyers <chris.meyers.fsu at gmail.com>wrote:
> To give a bit of context to the problem. I am using user space ltt to help
> profile code. I have created two events, time_begin and time_end. The goal
> is to allow for logging the runtime of specific code blocks via start()
> stop() insertions.
>
> I am having some issues with traces not coming out "correct" on the other
> "end". Let me further explain what I mean by correct and end.
>
> correct
> trace_mark(ust, time_begin, "thread %d func %s depth %d extra %s", 0,
> __FUNCTION__, 1, __FUNCTION__)
> trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 0,
> __FUNCTION__, 1, __FUNCTION__)
>
> end
> ust.time_begin: 30208.932264102
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> "memloc_request_response_decider", depth = 1, extra =
> "memloc_request_response_decider" }
> ust.time_end: 30208.932267455
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> "memloc_request_response_decider", depth = 1, extra =
> "memloc_request_response_decider" }
>
> Later on the output looks like this:
> ust.time_begin: 30198.142843837
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func = "ne_worker_thread",
> depth = 560296821, extra = "" }
>
> Notice that in the trace_mark() code above I hard coded depth to be 0 and
> _str is always __FUNCTION__.
>
> Possible reasons:
> * Buffer is being overrun. I changed the buffer size using the -N and -S
> options in usttrace to something > 2 MB (plenty large).
> * Channels are not thread-safe? I have 3 threads of execution in this
> example. All using the ust channel.
> * My code is crappy and I am overwriting the lust library buffer?
>
>
> Also, I am having trouble using any channel other than ust. Is ust the
> only channel available in user space?
>
> Many thanks,
> -Chris
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/ltt-dev/attachments/20100806/5aa70a13/attachment.htm>
^ permalink raw reply [flat|nested] 9+ messages in thread* [ltt-dev] ltt channel thread safe?
2010-08-06 20:55 ` chris meyers
2010-08-06 20:55 ` chris meyers
2010-08-06 20:55 ` chris meyers
@ 2010-08-06 21:02 ` Mathieu Desnoyers
2010-08-10 4:29 ` Pierre-Marc Fournier
2 siblings, 1 reply; 9+ messages in thread
From: Mathieu Desnoyers @ 2010-08-06 21:02 UTC (permalink / raw)
* chris meyers (chris.meyers.fsu at gmail.com) wrote:
> Forget any mention of threading being the reason. After trying way too many
> things, removal of the __FUNCTION__ macro seems to "fix" the problem. Does
> the __FUNCTION__ macro not play well with ltt? The binary trace file
> seemed void of any error. It seemed as if the __FUNCTION__ macro had some
> indirect influence on how the lttv -m textDump behaved.
>
> -Chris
>
Can you try applying this patch to UST and see if it fixes your problem ?
You'll have to apply the patch by hand to UST, because it is originally
made for the Linux kernel marker code (it's a one-liner).
markers fix out of bound array
While creating my own probes, I've observed that I get format mismatch error...
While digging into the executed code I observe that my format (stored in a
marker_entry) was overwritten by a new allocated structure. Finally I found
that in add_marker function the format pointer seems to be set to the wrong
position:
e->format = &e->name[channel_len + name_len];
while the proper assignment should be
e->format = &e->name[name_len];
indead:
size_t channel_len = strlen(channel) + 1;
size_t name_len = strlen(name) + 1;
...
size_t format_len ...= strlen(format) + 1;
and
struct marker_entry {
....
char channel[0]; /* Contains channel'\0'name'\0'format'\0' * /
};
...
e = kmalloc(sizeof(struct marker_entry)
+ channel_len + name_len + format_len,
GFP_KERNEL);
....
e->name = &e->channel[channel_len];
Rgds,
Damien COTTIER.
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers at efficios.com>
---
kernel/marker.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
Index: linux-2.6-lttng/kernel/marker.c
===================================================================
--- linux-2.6-lttng.orig/kernel/marker.c 2010-08-02 15:44:51.000000000 -0400
+++ linux-2.6-lttng/kernel/marker.c 2010-08-02 15:45:55.000000000 -0400
@@ -436,7 +436,7 @@ static struct marker_entry *add_marker(c
e->name = &e->channel[channel_len];
memcpy(e->name, name, name_len);
if (format) {
- e->format = &e->name[channel_len + name_len];
+ e->format = &e->name[name_len];
memcpy(e->format, format, format_len);
if (strcmp(e->format, MARK_NOARGS) == 0)
e->call = marker_probe_cb_noarg;
--
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com
^ permalink raw reply [flat|nested] 9+ messages in thread* [ltt-dev] ltt channel thread safe?
2010-08-06 21:02 ` Mathieu Desnoyers
@ 2010-08-10 4:29 ` Pierre-Marc Fournier
0 siblings, 0 replies; 9+ messages in thread
From: Pierre-Marc Fournier @ 2010-08-10 4:29 UTC (permalink / raw)
On 08/06/2010 05:02 PM, Mathieu Desnoyers wrote:
> * chris meyers (chris.meyers.fsu at gmail.com) wrote:
>> Forget any mention of threading being the reason. After trying way too many
>> things, removal of the __FUNCTION__ macro seems to "fix" the problem. Does
>> the __FUNCTION__ macro not play well with ltt? The binary trace file
>> seemed void of any error. It seemed as if the __FUNCTION__ macro had some
>> indirect influence on how the lttv -m textDump behaved.
>>
>> -Chris
>>
>
> Can you try applying this patch to UST and see if it fixes your problem ?
>
BTW it's been in HEAD for a while... no need to struggle with porting
the patch.
pmf
^ permalink raw reply [flat|nested] 9+ messages in thread
* [ltt-dev] ltt channel thread safe?
2010-08-04 6:12 [ltt-dev] ltt channel thread safe? chris meyers
` (2 preceding siblings ...)
2010-08-06 20:55 ` chris meyers
@ 2010-08-10 4:28 ` Pierre-Marc Fournier
3 siblings, 0 replies; 9+ messages in thread
From: Pierre-Marc Fournier @ 2010-08-10 4:28 UTC (permalink / raw)
On 08/04/2010 02:12 AM, chris meyers wrote:
> To give a bit of context to the problem. I am using user space ltt to
> help profile code. I have created two events, time_begin and time_end.
> The goal is to allow for logging the runtime of specific code blocks
> via start() stop() insertions.
>
> I am having some issues with traces not coming out "correct" on the
> other "end". Let me further explain what I mean by correct and end.
>
> correct
> trace_mark(ust, time_begin, "thread %d func %s depth %d extra %s", 0,
> __FUNCTION__, 1, __FUNCTION__)
> trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 0,
> __FUNCTION__, 1, __FUNCTION__)
>
> end
> ust.time_begin: 30208.932264102
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> "memloc_request_response_decider", depth = 1, extra =
> "memloc_request_response_decider" }
> ust.time_end: 30208.932267455
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> "memloc_request_response_decider", depth = 1, extra =
> "memloc_request_response_decider" }
>
> Later on the output looks like this:
> ust.time_begin: 30198.142843837
> (/home/meyers/.usttraces/lappy-20100804020140730811027/28367_5501430910891543571/ust_0),
> 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func = "ne_worker_thread",
> depth = 560296821, extra = "" }
>
> Notice that in the trace_mark() code above I hard coded depth to be 0
> and _str is always __FUNCTION__.
>
> Possible reasons:
> * Buffer is being overrun. I changed the buffer size using the -N and
> -S options in usttrace to something > 2 MB (plenty large).
> * Channels are not thread-safe? I have 3 threads of execution in this
> example. All using the ust channel.
Channels are supposed to be thread-safe.
If there is an overrun, it will be printed in the console output from
lttv. Overruns are always possible if the rate at which the application
produces events is higher than the rate at which they can be flushed to
the disk. The solution may be to increase buffer size to counter
temporary event rate peaks. However if the sustained rate is too high,
an overrun will still eventually happen. One way to avoid this would be
to add a synchronous mode where the application may block on a marker to
prevent overruns.
> * My code is crappy and I am overwriting the lust library buffer?
>
>
> Also, I am having trouble using any channel other than ust. Is ust the
> only channel available in user space?
From the ust manual:
"Note: Although this example uses mychannel as the channel, the only
channel name currently supported with early tracing is ust. The usttrace
tool always uses the early tracing mode. When using manual mode without
early tracing, any channel name may be used."
pmf
^ permalink raw reply [flat|nested] 9+ messages in thread