[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Mathieu Desnoyers]

Hello,

The test case included in attachement reproduces reliably a problem with
UST. It generates randomly-sized strings, and I've noticed that the
string gets corrupted at some point. A README file in included with the
attachment.

I also got to a point where ustd segfaults very reliably on my machine.
I cannot take traces with it anymore.

Can you guys have a look ?

Thanks,

Mathieu

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com
-------------- next part --------------
An embedded message was scrubbed...
From: chris meyers <chris.meyers.fsu@gmail.com>
Subject: Re: [ltt-dev] ltt channel thread safe?
Date: Tue, 10 Aug 2010 14:45:22 -0400
Size: 1649130
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20100810/97044719/attachment-0001.eml>

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Mathieu Desnoyers]

Hello,

The test case included in attachement reproduces reliably a problem with
UST. It generates randomly-sized strings, and I've noticed that the
string gets corrupted at some point. A README file in included with the
attachment.

I also got to a point where ustd segfaults very reliably on my machine.
I cannot take traces with it anymore.

Can you guys have a look ?

Thanks,

Mathieu

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com
-------------- next part --------------
An embedded message was scrubbed...
From: chris meyers <chris.meyers.fsu@gmail.com>
Subject: Re: [ltt-dev] ltt channel thread safe?
Date: Tue, 10 Aug 2010 14:45:22 -0400
Size: 1649130
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20100810/97044719/attachment.eml>

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Mathieu Desnoyers]

Hello,

The test case included in attachement reproduces reliably a problem with
UST. It generates randomly-sized strings, and I've noticed that the
string gets corrupted at some point. A README file in included with the
attachment.

I also got to a point where ustd segfaults very reliably on my machine.
I cannot take traces with it anymore.

Can you guys have a look ?

Thanks,

Mathieu

-- 
Mathieu Desnoyers
Operating System Efficiency R&D Consultant
EfficiOS Inc.
http://www.efficios.com
-------------- next part --------------
An embedded message was scrubbed...
From: chris meyers <chris.meyers.fsu@gmail.com>
Subject: Re: [ltt-dev] ltt channel thread safe?
Date: Tue, 10 Aug 2010 14:45:22 -0400
Size: 1649130
URL: <http://lists.casi.polymtl.ca/pipermail/ltt-dev/attachments/20100810/97044719/attachment-0001.mht>

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Mathieu Desnoyers]

Ah, there was a bug in the test case I received. It was modifying 2
strings shared between threads concurrently.

It made me think of a way to handle concurrently modified strings
gracefully within both lttng and ust. I'll work on a patch. I plan to
use strncpy and detect if the string size changed after the strlen
performed for space reservation.

Here is the updated test case. It works now.

#include <ust/marker.h>
#include <stdio.h>
#include <pthread.h>

#define STR_SIZE	30

char funcA[STR_SIZE+10];
char extraA[STR_SIZE+10];

char funcB[STR_SIZE+10];
char extraB[STR_SIZE+10];

void *threadA(void *ptr);
void *threadB(void *ptr);

int main() {
	int i=0;

	pthread_t thread_id[2];
	srand(1000);

	for (i=0; i < STR_SIZE; ++i) {
		funcA[i] = (i % (90-65)) + 65;
		extraA[i] = (i % (90-65)) + 65;
		funcB[i] = (i % (90-65)) + 65;
		extraB[i] = (i % (90-65)) + 65;
	}
	funcA[STR_SIZE-1] = '\0';
	extraA[STR_SIZE-1] = '\0';
	funcB[STR_SIZE-1] = '\0';
	extraB[STR_SIZE-1] = '\0';

	printf("funcA:  %s\n", funcA);
	printf("extraA: %s\n", extraA);
	printf("funcB:  %s\n", funcB);
	printf("extraB: %s\n", extraB);
	pthread_create(&thread_id[0], NULL, threadA, (void*)NULL);
	pthread_create(&thread_id[1], NULL, threadB, (void*)NULL);

	for (i=0; i < 2; ++i) {
		pthread_detach(thread_id[i]);
	}
	sleep(10);
}


void *threadA(void *ptr) {
	int i=0,count_prev=0,count=0, index;
	char save_func, save_extra;
	for (i=0; i < 500000; ++i) {
//		if (i % 1000)
//			sleep(1);
		index = rand() % (STR_SIZE-1) + 1;
		save_func = funcA[index];
		save_extra = extraA[index];
		funcA[index] = '\0';
		extraA[index] = '\0';
		trace_mark(ust, times_begins, "thread %d func %s depth %d extra %s", 1, funcA, 1, extraA);
//		profile_time_begin("Hello");
		count += count_prev;
		count_prev = count;
//		trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 1, func, 1, extra);
//		profile_time_end("Goodbye");
		funcA[index] = save_func;
		extraA[index] = save_extra;
	}
}

void *threadB(void *ptr) {
	int i=0,count_prev=0,count=0, index;
	char save_func, save_extra;
	for (i=0; i < 100000; ++i) {
//		if (i % 1000)
//			sleep(1);
		index = rand() % (STR_SIZE-1) + 1;
		save_func = funcB[index];
		save_extra = extraB[index];
		funcB[index] = '\0';
		extraB[index] = '\0';
//		profile_time_begin("Hello");
		trace_mark(ust, times_begins, "thread %d func %s depth %d extra %s", 1, funcB, 1, extraB);
		count += count_prev;
		count_prev = count;
//		profile_time_end("Goodbye");
//		trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 1, func, 1, extra);
		funcB[index] = save_func;
		extraB[index] = save_extra;
	}
}

* Mathieu Desnoyers (compudj at krystal.dyndns.org) wrote:
> Hello,
> 
> The test case included in attachement reproduces reliably a problem with
> UST. It generates randomly-sized strings, and I've noticed that the
> string gets corrupted at some point. A README file in included with the
> attachment.
> 
> I also got to a point where ustd segfaults very reliably on my machine.
> I cannot take traces with it anymore.
> 
> Can you guys have a look ?
> 
> Thanks,
> 
> Mathieu
> 
> -- 
> Mathieu Desnoyers
> Operating System Efficiency R&D Consultant
> EfficiOS Inc.
> http://www.efficios.com

> Date: Tue, 10 Aug 2010 14:45:22 -0400
> To: Mathieu Desnoyers <compudj at krystal.dyndns.org>
> From: chris meyers <chris.meyers.fsu@gmail.com>
> Subject: Re: [ltt-dev] ltt channel thread safe?
> 
> I made a simple test case that mimics the properties of my program that
> produces the error (ie. multi-threaded and variable length strings mixed
> with constant int's).
> 
> Check out the README in the archive.  Let me know if you have any questions!
> 
> Thanks,
> -Chris
> 
> On Tue, Aug 10, 2010 at 11:46 AM, Mathieu Desnoyers <
> compudj at krystal.dyndns.org> wrote:
> 
> > I think this looks like a data generation problem in UST.
> >
> > Can you send me your test program and a copy of a generated trace that
> > contains the error, along with a full description of the system you
> > gather the trace from and the system on which you run lttv ?
> >
> > It will be easier to debug if I can reproduce the problem myself.
> >
> > Thanks,
> >
> > Mathieu
> >
> > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > So does it sound like maybe marker_update_fields_offsets() or add_type()
> > is
> > > at fault?
> > >
> > > -Chris
> > >
> > > On Tue, Aug 10, 2010 at 8:47 AM, Mathieu Desnoyers <
> > > compudj at krystal.dyndns.org> wrote:
> > >
> > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > Ok sorry it's late.  The pasted output in the previous post should be
> > the
> > > > > below.  The debug printed hex data differs from when I print the
> > buffer
> > > > in
> > > > > hex.  This is weird.
> > > >
> > > > I think because the debug and text dump outputs use a different file
> > > > descriptor to output the text, and because there is a one event queue
> > > > that is kept, there is a 1 or 2 events difference between the text dump
> > > > output and the debug output.
> > > >
> > >
> > > Ya, that makes it a bit more confusing :)
> > >
> > > >
> > > > >
> > > > > =========================
> > > > > Info field lengths:
> > > > > offset: 0 | size: 4
> > > > > offset: 4 | size: 0
> > > > > offset: 27 | size: 4
> > > > > offset: 31 | size: 0
> > > > >
> > > > > 01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > 71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > 00 73 65 6C  65 63 74 28  29 20 62 6C  6F 63 6B 20
> > > > > 74 69 6D 65  00
> > > > > =========================
> > > > > -------------------------------------
> > > > > offset: 0 | size: 4
> > > > > 01 00 00 00
> > > > > -------------------------------------
> > > > > -------------------------------------
> > > > > offset: 4 | size: 0
> > > > > 6E 65 5F 73  65 6C 65 63  74 5F 72 65  71 75 65 73
> > > > > 74 5F 74 68  72 65 61 64  00 01 00 00  00 73 65 6C
> > > > > 65 63 74 28  29 20 62 6C  6F 63 6B 20  74 69 6D 65
> > > > > 00
> > > >
> > > > Hrm, it looks like the \0 here also belongs to the next integer.
> > > >
> > > > > -------------------------------------
> > > > > -------------------------------------
> > > > > offset: 27 | size: 4
> > > > > 64 00 01 00
> > > >
> > > > So this is not the value you recorded, right ?
> > > >
> > > Correct, I recorded a 1.
> > >
> > > >
> > > > Mathieu
> > > >
> > > > > -------------------------------------
> > > > > -------------------------------------
> > > > > offset: 31 | size: 0
> > > > > 00 00 73 65  6C 65 63 74  28 29 20 62  6C 6F 63 6B
> > > > > 20 74 69 6D  65 00
> > > > > -------------------------------------
> > > > > ust.time_end: 116791.642023291
> > > > >
> > > >
> > (/home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0),
> > > > > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > Event header (tracefile
> > > > >
> > > >
> > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0
> > > > > offset 3c0c5):
> > > > >    3c0c5    66 FC 55 0C
> > > > > tracefile.c ltt_update_event_size() data_size: 58
> > > > > Event data (tracefile
> > > > >
> > > >
> > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0
> > > > > offset 3c0c9):
> > > > >    3c0c9    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > >  ....ne_select_re
> > > > >    3c0d9    71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > >  quest_thread....
> > > > >    3c0e9    00 6E 65 5F  73 65 6C 65  63 74 5F 72  65 71 75 65
> > > > >  .ne_select_reque
> > > > >    3c0f9    73 74 5F 74  68 72 65 61  64 00
> > > > > st_thread.
> > > > >
> > > > > On Tue, Aug 10, 2010 at 1:31 AM, chris meyers <
> > > > chris.meyers.fsu at gmail.com>wrote:
> > > > >
> > > > > > Thanks for the reply Pierre.  I still think my error is coming from
> > > > lttv.
> > > > > >
> > > > > > Below is a trace with some printf's inserted.  In
> > > > lttv_event_to_string() I
> > > > > > iterate over all the 'struct marker_field' entries and output
> > offset,
> > > > into
> > > > > > data, and size.  Then the data that corresponds to that offset is
> > > > printed.
> > > > > >  This can be cross-referenced against the two hex outputs above the
> > > > print
> > > > > > outs (the first hex output is from pre-existing debug code; the
> > second
> > > > hex
> > > > > > output is to verify that the data buffer didn't change).  For some
> > > > reason
> > > > > > the second %lld (depth =) has a wrong offset.  Currently, I am
> > > > investigating
> > > > > > marker_update_fields_offsets() and add_type(), as these seem to be
> > on
> > > > the
> > > > > > only two functions that deal with modifying the marker offset.
> >  Maybe
> > > > the
> > > > > > string before 'depth' is "eating" too many bytes.  Any
> > hints/help/ideas
> > > > > > would be appreciated :)
> > > > > >
> > > > > > Event header (tracefile
> > > > > >
> > > >
> > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_1
> > > > > > offset 3f39f):
> > > > > >    3f39f    AB 66 D7 EA  01 00 36 00  AB 66 D7 B2  38 6A 00 00
> > > > > > tracefile.c ltt_update_event_size() data_size: 54
> > > > > > Event data (tracefile
> > > > > >
> > > >
> > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_1
> > > > > > offset 3f3af):
> > > > > >    3f3af    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > >  ....ne_select_re
> > > > > >    3f3bf    70 6C 79 5F  74 68 72 65  61 64 00 01  00 00 00 6E
> > > > > >  ply_thread.....n
> > > > > >    3f3cf    65 5F 73 65  6C 65 63 74  5F 72 65 70  6C 79 5F 74
> > > > > >  e_select_reply_t
> > > > > >    3f3df    68 72 65 61  64 00
> > > >  hread.
> > > > > >
> > > > > > =========================
> > > > > > Info field lengths:
> > > > > > offset: 0 | size: 4
> > > > > > offset: 4 | size: 0
> > > > > > offset: 27 | size: 4
> > > > > > offset: 31 | size: 0
> > > > > >
> > > > > > 01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > 71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > 00 73 65 6C  65 63 74 28  29 20 62 6C  6F 63 6B 20
> > > > > > 74 69 6D 65  00
> > > > > > =========================
> > > > > > -------------------------------------
> > > > > > offset: 0 | size: 4
> > > > > > 01 00 00 00
> > > > > > -------------------------------------
> > > > > > -------------------------------------
> > > > > > offset: 4 | size: 0
> > > > > > 6E 65 5F 73  65 6C 65 63  74 5F 72 65  71 75 65 73
> > > > > > 74 5F 74 68  72 65 61 64  00 01 00 00  00 73 65 6C
> > > > > > 65 63 74 28  29 20 62 6C  6F 63 6B 20  74 69 6D 65
> > > > > > 00
> > > > > > -------------------------------------
> > > > > > -------------------------------------
> > > > > > offset: 27 | size: 4
> > > > > > 64 00 01 00
> > > > > > -------------------------------------
> > > > > > -------------------------------------
> > > > > > offset: 31 | size: 0
> > > > > > 00 00 73 65  6C 65 63 74  28 29 20 62  6C 6F 63 6B
> > > > > > 20 74 69 6D  65 00
> > > > > > -------------------------------------
> > > > > > ust.time_end: 116791.642023291
> > > > > >
> > > >
> > (/home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0),
> > > > > > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > >
> > > > > >
> > > > > > On Mon, Aug 9, 2010 at 3:18 PM, Mathieu Desnoyers <
> > > > > > compudj at krystal.dyndns.org> wrote:
> > > > > >
> > > > > >> * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > >> > debuging turned on.
> > > > > >> > String: is the printf() added to lttv_print_field()
> > > > > >> >
> > > > > >> > Just eyeballing the debugging output from below, the log file
> > seams
> > > > > >> correct.
> > > > > >> >  This further leads me to believe it is the output
> > (lttv/textDump)
> > > > that
> > > > > >> is
> > > > > >> > at fault.  Does the log entry seem correct to you?
> > > > > >> >
> > > > > >> > What I expected to be output:
> > > > > >> > String: ne_select_request_thread
> > > > > >> > String: ne_select_request_thread
> > > > > >> > ust.time_end: 121283.601051208
> > > > > >> >
> > > > > >>
> > > >
> > (/home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0),
> > > > > >> > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > >> > "ne_select_request_thread", depth = 65636, extra =
> > > > > >> > "ne_select_request_thread" }
> > > > > >> >
> > > > > >> > ---------------------------------------------------------
> > > > > >> >
> > > > > >> > Actual output:
> > > > > >> >
> > > > > >> > String: ne_select_request_thread
> > > > > >> > String:
> > > > > >> > ust.time_end: 121283.601051208
> > > > > >> >
> > > > > >>
> > > >
> > (/home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0),
> > > > > >> > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > >> > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > >> > Event header (tracefile
> > > > > >> >
> > > > > >>
> > > >
> > /home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0
> > > > > >> > offset 4b643):
> > > > > >> >    4b643    A7 41 F5 09
> > > > > >> > Event data (tracefile
> > > > > >> >
> > > > > >>
> > > >
> > /home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0
> > > > > >> > offset 4b647):
> > > > > >> >    4b647    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > >> >  ....ne_select_re
> > > > > >> >    4b657    71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > >>
> > > > > >> Is it me or the "64 00 01 00 00" part at the end above is
> > unexpected ?
> > > > > >>
> > > > > >> We should have "64 00" which would be the end of string followed
> > by
> > > > the
> > > > > >> final \0, and then the "00 01 00 00" which represents the 65536
> > value.
> > > > > >>
> > > > > >> So I expect there might be a problem in UST where it forgets about
> > > > doing
> > > > > >> the +1 to taken into account the end of string \0 somewhere.
> > > > > >>
> > > > > >> Thanks,
> > > > > >>
> > > > > >> Mathieu
> > > > > >>
> > > > > >> >  quest_thread....
> > > > > >> >    4b667    00 6E 65 5F  73 65 6C 65  63 74 5F 72  65 71 75 65
> > > > > >> >  .ne_select_reque
> > > > > >> >    4b677    73 74 5F 74  68 72 65 61  64 00
> > > > > >> > st_thread.
> > > > > >> >
> > > > > >> >
> > > > > >> > On Mon, Aug 9, 2010 at 11:08 AM, chris meyers <
> > > > > >> chris.meyers.fsu at gmail.com>wrote:
> > > > > >> >
> > > > > >> > > Scratch that, the printf does not print out the correct data.
> >  It
> > > > > >> prints
> > > > > >> > > the wrong data.
> > > > > >> > >
> > > > > >> > >
> > > > > >> > > On Mon, Aug 9, 2010 at 11:06 AM, chris meyers <
> > > > > >> chris.meyers.fsu at gmail.com>wrote:
> > > > > >> > >
> > > > > >> > >> The printf outputs the correct data (function names).
> > > > > >> > >>
> > > > > >> > >>
> > > > > >> > >> On Mon, Aug 9, 2010 at 10:22 AM, Mathieu Desnoyers <
> > > > > >> > >> compudj at krystal.dyndns.org> wrote:
> > > > > >> > >>
> > > > > >> > >>> Hrm, can you try adding some printfs in lttv
> > > > > >> > >>>
> > > > > >> > >>> lttv/lttv/print.c
> > > > > >> > >>>
> > > > > >> > >>> ltt_print_field()
> > > > > >> > >>> within LTT_TYPE_STRING case of the switch.
> > > > > >> > >>>
> > > > > >> > >>> Thanks,
> > > > > >> > >>>
> > > > > >> > >>> Mathieu
> > > > > >> > >>>
> > > > > >> > >>> * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > >> > >>> > func_rand and extra_rand are two varying length "random"
> > > > strings.
> > > > > >>  This
> > > > > >> > >>> > seems to be what causes the "garbling" output.  For some
> > > > reason it
> > > > > >> > >>> affects
> > > > > >> > >>> > the value of depth (a constant set to 1).  I added a
> > printf
> > > > like
> > > > > >> you
> > > > > >> > >>> > mentioned and the correct values are printing out.  It
> > seems
> > > > that
> > > > > >> the
> > > > > >> > >>> > logging is correct.  I have a suspicion that the
> > "textDump"
> > > > module
> > > > > >> in
> > > > > >> > >>> lttv
> > > > > >> > >>> > may be parsing incorrect.
> > > > > >> > >>> >
> > > > > >> > >>> > func_rand = ALLOC_RANDOM(rand() % 1024 + 1);
> > > > > >> > >>> > extra_rand = ALLOC_RANDOM(rand() % 1024 + 1);
> > > > > >> > >>> >
> > > > > >> > >>> > trace_mark(ust, time_end, "thread %d func %s depth %d
> > extra
> > > > %s",
> > > > > >> > >>> thread,
> > > > > >> > >>> > func_rand, depth, extra_rand);
> > > > > >> > >>> >
> > > > > >> > >>> > On Sat, Aug 7, 2010 at 12:58 PM, Mathieu Desnoyers <
> > > > > >> > >>> > compudj at krystal.dyndns.org> wrote:
> > > > > >> > >>> >
> > > > > >> > >>> > > Hrm, it might be caused by the fact that the
> > __FUNCTION__ is
> > > > > >> passed
> > > > > >> > >>> > > through the trace_mark() macro. It could be a macro
> > problem
> > > > with
> > > > > >> the
> > > > > >> > >>> > > precompiler (odd behavior with __FUNCTION__ and
> > defines).
> > > > You
> > > > > >> could
> > > > > >> > >>> try
> > > > > >> > >>> > > just outputting the result in the marker callback (the
> > > > function
> > > > > >> > >>> called
> > > > > >> > >>> > > in marker.c) with printf and see if this is OK or not.
> > > > > >> > >>> > >
> > > > > >> > >>> > > Thanks,
> > > > > >> > >>> > >
> > > > > >> > >>> > > Mathieu
> > > > > >> > >>> > >
> > > > > >> > >>> > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > >> > >>> > > > I think I jumped the gun in saying that __func__
> > worked.
> > > > > >>  However,
> > > > > >> > >>> I can
> > > > > >> > >>> > > > confidently say that ca constant string, such as the
> > one
> > > > > >> below,
> > > > > >> > >>> does not
> > > > > >> > >>> > > > result in garbled output.  I will try dynamically
> > > > generating
> > > > > >> > >>> different
> > > > > >> > >>> > > > length strings at runtime to log and see if that
> > causes an
> > > > > >> error.
> > > > > >> > >>> > > >
> > > > > >> > >>> > > > So to summarize thus far:
> > > > > >> > >>> > > > __FUNCTION__ and __func__ both result in inconsistent
> > > > output.
> > > > > >> > >>> > > > Constant strings result in consistent output.
> > > > > >> > >>> > > >
> > > > > >> > >>> > > > trace_mark(ust, time_begin, "thread %d func %s depth
> > %d
> > > > extra
> > > > > >> %s",
> > > > > >> > >>> > > thread,
> > > > > >> > >>> > > > "I like pie because it taste good", depth, "yummm i
> > too
> > > > like
> > > > > >> pie
> > > > > >> > >>> for
> > > > > >> > >>> > > > dessert");
> > > > > >> > >>> > > >
> > > > > >> > >>> > > > quantify inconsistent: 260 out of 8197 (31%) log
> > entries
> > > > were
> > > > > >> > >>> corrupt in
> > > > > >> > >>> > > my
> > > > > >> > >>> > > > case.
> > > > > >> > >>> > > >
> > > > > >> > >>> > > > -Chris
> > > > > >> > >>> > > >
> > > > > >> > >>> > > > On Sat, Aug 7, 2010 at 11:28 AM, Mathieu Desnoyers <
> > > > > >> > >>> > > > compudj at krystal.dyndns.org> wrote:
> > > > > >> > >>> > > >
> > > > > >> > >>> > > > > What compiler do you use ? Can you reproduce with
> > > > different
> > > > > >> > >>> compiler
> > > > > >> > >>> > > > > versions?
> > > > > >> > >>> > > > >
> > > > > >> > >>> > > > > Thanks,
> > > > > >> > >>> > > > >
> > > > > >> > >>> > > > > Mathieu
> > > > > >> > >>> > > > >
> > > > > >> > >>> > > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > >> > >>> > > > > > I don't know the exact reason why but __func__
> > works
> > > > and
> > > > > >> > >>> __FUNCTION__
> > > > > >> > >>> > > > > > doesn't.
> > > > > >> > >>> > > > > >
> > > > > >> > >>> > > > > > -Chris
> > > > > >> > >>> > > > > >
> > > > > >> > >>> > > > > > On Fri, Aug 6, 2010 at 11:47 PM, chris meyers <
> > > > > >> > >>> > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > >> > >>> > > > > >
> > > > > >> > >>> > > > > > > #define LARGE_CONST 127LL
> > > > > >> > >>> > > > > > > #define MY_STR "Hello"
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > > > > trace_mark(ust, time_end, "thread %lld func %s
> > depth
> > > > > >> %lld
> > > > > >> > >>> extra
> > > > > >> > >>> > > %s",
> > > > > >> > >>> > > > > > > LARGE_CONST, MY_STR, LARGE_CONST, __FUNCTION__)
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > > > > Below is a snippet of the macro trace_marker
> > > > expanded.
> > > > > >>  My
> > > > > >> > >>> macor
> > > > > >> > >>> > > > > "MY_STR"
> > > > > >> > >>> > > > > > > is replaced with Hello, while __FUNCTION__ is
> > not
> > > > > >> replaced.
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > > > > The expected output is inconsistent when I DO
> > use
> > > > > >> > >>> __FUNCTION__.
> > > > > >> > >>> > > > > > > The expected output IS consistent when I do NOT
> > use
> > > > > >> > >>> __FUNCTION__.
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > > > > gcc -lust example.c -E
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > > > >  do { struct marker *m; struct registers regs;
> > asm
> > > > > >> volatile (
> > > > > >> > >>> > > ".ifndef
> > > > > >> > >>> > > > > > > __mstrtab_" "ust" "_" "time_end" "_channel_"
> > "39"
> > > > "\n\t"
> > > > > >> > >>> ".section
> > > > > >> > >>> > > > > > > __markers_strings,\"aw\", at progbits\n\t"
> > "__mstrtab_"
> > > > > >> "ust"
> > > > > >> > >>> "_"
> > > > > >> > >>> > > > > "time_end"
> > > > > >> > >>> > > > > > > "_channel_" "39" ":\n\t" ".string \"" "ust"
> > "\"\n\t"
> > > > > >> > >>> "__mstrtab_"
> > > > > >> > >>> > > "ust"
> > > > > >> > >>> > > > > "_"
> > > > > >> > >>> > > > > > > "time_end" "_name_" "39" ":\n\t" ".string \""
> > > > "time_end"
> > > > > >> > >>> "\"\n\t"
> > > > > >> > >>> > > > > > > "__mstrtab_" "ust" "_" "time_end" "_format_"
> > "39"
> > > > > >> ":\n\t"
> > > > > >> > >>> ".string
> > > > > >> > >>> > > "
> > > > > >> > >>> > > > > "\""
> > > > > >> > >>> > > > > > > "thread %lld func %s depth %lld extra %s" "\""
> > > > "\n\t"
> > > > > >> > >>> > > ".previous\n\t"
> > > > > >> > >>> > > > > > > ".endif\n\t" ); asm volatile ( ".section
> > > > > >> > >>> > > > > __markers,\"aw\", at progbits\n\t"
> > > > > >> > >>> > > > > > > ".balign 8\n\t" "2:\n\t" ".quad " "(__mstrtab_"
> > > > "ust"
> > > > > >> "_"
> > > > > >> > >>> > > "time_end"
> > > > > >> > >>> > > > > > > "_channel_" "39" ")\n\t" ".quad " "(__mstrtab_"
> > > > "ust"
> > > > > >> "_"
> > > > > >> > >>> > > "time_end"
> > > > > >> > >>> > > > > > > "_name_" "39" ")\n\t" ".quad " "(__mstrtab_"
> > "ust"
> > > > "_"
> > > > > >> > >>> "time_end"
> > > > > >> > >>> > > > > "_format_"
> > > > > >> > >>> > > > > > > "39" ")\n\t" ".byte 0\n\t" ".byte 0\n\t" ".word
> > > > 0\n\t"
> > > > > >> ".word
> > > > > >> > >>> > > 0\n\t"
> > > > > >> > >>> > > > > > > ".balign " "64" " / 8\n\t" ".quad "
> > > > > >> "(marker_probe_cb)\n\t"
> > > > > >> > >>> ".quad
> > > > > >> > >>> > > "
> > > > > >> > >>> > > > > > > "(__mark_empty_function)\n\t" ".quad " "0\n\t"
> > > > ".quad "
> > > > > >> > >>> "0\n\t"
> > > > > >> > >>> > > ".quad
> > > > > >> > >>> > > > > "
> > > > > >> > >>> > > > > > > "0\n\t" ".quad " "0\n\t" ".quad " "(1f)\n\t"
> > > > > >> ".previous\n\t"
> > > > > >> > >>> > > "1:\n\t"
> > > > > >> > >>> > > > > "lea
> > > > > >> > >>> > > > > > > 2b(%%rip)," "%[outptr]" "\n\t" : [outptr] "=r"
> > (m)
> > > > ); ;
> > > > > >> do {
> > > > > >> > >>> if (0)
> > > > > >> > >>> > > > > > > ___mark_check_format("thread %lld func %s depth
> > %lld
> > > > > >> extra
> > > > > >> > >>> %s",
> > > > > >> > >>> > > 127LL,
> > > > > >> > >>> > > > > > > "First", 127LL, __FUNCTION__); } while (0); if
> > (!0)
> > > > { if
> > > > > >> > >>> > > > > > > (__builtin_expect(!!((m->state__imv)), 0))
> > > > (m->call)(m,
> > > > > >> > >>> ((void
> > > > > >> > >>> > > *)0),
> > > > > >> > >>> > > > > &regs,
> > > > > >> > >>> > > > > > > 127LL, "First", 127LL, __FUNCTION__); } else {
> > if
> > > > > >> > >>> > > > > > > (__builtin_expect(!!((m->state__imv)), 0))
> > > > (m->call)(m,
> > > > > >> > >>> ((void
> > > > > >> > >>> > > *)0),
> > > > > >> > >>> > > > > &regs,
> > > > > >> > >>> > > > > > > 127LL, "First", 127LL, __FUNCTION__); } } while
> > (0);
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > > > > On Fri, Aug 6, 2010 at 5:10 PM, chris meyers <
> > > > > >> > >>> > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > > > >> I am using the newest, development, version
> > from
> > > > the
> > > > > >> git.  I
> > > > > >> > >>> had
> > > > > >> > >>> > > tried
> > > > > >> > >>> > > > > the
> > > > > >> > >>> > > > > > >> newest stable version with the same results.  I
> > > > believe
> > > > > >> the
> > > > > >> > >>> newest
> > > > > >> > >>> > > git
> > > > > >> > >>> > > > > > >> commit has the patch that you are talking
> > about.
> > > > > >> > >>> > > > > > >>
> > > > > >> > >>> > > > > > >> Thanks,
> > > > > >> > >>> > > > > > >> -Chris
> > > > > >> > >>> > > > > > >>
> > > > > >> > >>> > > > > > >>
> > > > > >> > >>> > > > > > >> On Fri, Aug 6, 2010 at 5:02 PM, Mathieu
> > Desnoyers <
> > > > > >> > >>> > > > > > >> compudj at krystal.dyndns.org> 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 ?
> > > > > >> > >>> > > > > > >>>
> > > > > >> > >>> > > > > > >>> 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
> > > > > >> > >>> > > > > > >>>
> > > > > >> > >>> > > > > > >>
> > > > > >> > >>> > > > > > >>
> > > > > >> > >>> > > > > > >
> > > > > >> > >>> > > > >
> > > > > >> > >>> > > > > --
> > > > > >> > >>> > > > > Mathieu Desnoyers
> > > > > >> > >>> > > > > Operating System Efficiency R&D Consultant
> > > > > >> > >>> > > > > EfficiOS Inc.
> > > > > >> > >>> > > > > http://www.efficios.com
> > > > > >> > >>> > > > >
> > > > > >> > >>> > >
> > > > > >> > >>> > > --
> > > > > >> > >>> > > Mathieu Desnoyers
> > > > > >> > >>> > > Operating System Efficiency R&D Consultant
> > > > > >> > >>> > > EfficiOS Inc.
> > > > > >> > >>> > > http://www.efficios.com
> > > > > >> > >>> > >
> > > > > >> > >>>
> > > > > >> > >>> --
> > > > > >> > >>> Mathieu Desnoyers
> > > > > >> > >>> Operating System Efficiency R&D Consultant
> > > > > >> > >>> EfficiOS Inc.
> > > > > >> > >>> http://www.efficios.com
> > > > > >> > >>>
> > > > > >> > >>
> > > > > >> > >>
> > > > > >> > >
> > > > > >>
> > > > > >> --
> > > > > >> Mathieu Desnoyers
> > > > > >> Operating System Efficiency R&D Consultant
> > > > > >> EfficiOS Inc.
> > > > > >> http://www.efficios.com
> > > > > >>
> > > > > >
> > > > > >
> > > >
> > > > --
> > > > Mathieu Desnoyers
> > > > Operating System Efficiency R&D Consultant
> > > > EfficiOS Inc.
> > > > http://www.efficios.com
> > > >
> >
> > --
> > Mathieu Desnoyers
> > Operating System Efficiency R&D Consultant
> > EfficiOS Inc.
> > http://www.efficios.com
> >



> _______________________________________________
> 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] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Fu Juntang(David)]

Hi,Mathieu:
  I have found another UST bug in this multi-thread functions:
  in my SMP host(2 cpu cores),I have found that UST can only collect one
 thread trace logs running one core(CPU_1),but can not collect the 
 other thread trace logs running another core(CPU_0),is this a known
bug?
  if you need my debug logs, I can attach it to you. 

  thanks

--David

On Wed, 2010-08-11 at 11:39 -0400, Mathieu Desnoyers wrote:
> Ah, there was a bug in the test case I received. It was modifying 2
> strings shared between threads concurrently.
> 
> It made me think of a way to handle concurrently modified strings
> gracefully within both lttng and ust. I'll work on a patch. I plan to
> use strncpy and detect if the string size changed after the strlen
> performed for space reservation.
> 
> Here is the updated test case. It works now.
> 
> #include <ust/marker.h>
> #include <stdio.h>
> #include <pthread.h>
> 
> #define STR_SIZE	30
> 
> char funcA[STR_SIZE+10];
> char extraA[STR_SIZE+10];
> 
> char funcB[STR_SIZE+10];
> char extraB[STR_SIZE+10];
> 
> void *threadA(void *ptr);
> void *threadB(void *ptr);
> 
> int main() {
> 	int i=0;
> 
> 	pthread_t thread_id[2];
> 	srand(1000);
> 
> 	for (i=0; i < STR_SIZE; ++i) {
> 		funcA[i] = (i % (90-65)) + 65;
> 		extraA[i] = (i % (90-65)) + 65;
> 		funcB[i] = (i % (90-65)) + 65;
> 		extraB[i] = (i % (90-65)) + 65;
> 	}
> 	funcA[STR_SIZE-1] = '\0';
> 	extraA[STR_SIZE-1] = '\0';
> 	funcB[STR_SIZE-1] = '\0';
> 	extraB[STR_SIZE-1] = '\0';
> 
> 	printf("funcA:  %s\n", funcA);
> 	printf("extraA: %s\n", extraA);
> 	printf("funcB:  %s\n", funcB);
> 	printf("extraB: %s\n", extraB);
> 	pthread_create(&thread_id[0], NULL, threadA, (void*)NULL);
> 	pthread_create(&thread_id[1], NULL, threadB, (void*)NULL);
> 
> 	for (i=0; i < 2; ++i) {
> 		pthread_detach(thread_id[i]);
> 	}
> 	sleep(10);
> }
> 
> 
> void *threadA(void *ptr) {
> 	int i=0,count_prev=0,count=0, index;
> 	char save_func, save_extra;
> 	for (i=0; i < 500000; ++i) {
> //		if (i % 1000)
> //			sleep(1);
> 		index = rand() % (STR_SIZE-1) + 1;
> 		save_func = funcA[index];
> 		save_extra = extraA[index];
> 		funcA[index] = '\0';
> 		extraA[index] = '\0';
> 		trace_mark(ust, times_begins, "thread %d func %s depth %d extra %s", 1, funcA, 1, extraA);
> //		profile_time_begin("Hello");
> 		count += count_prev;
> 		count_prev = count;
> //		trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 1, func, 1, extra);
> //		profile_time_end("Goodbye");
> 		funcA[index] = save_func;
> 		extraA[index] = save_extra;
> 	}
> }
> 
> void *threadB(void *ptr) {
> 	int i=0,count_prev=0,count=0, index;
> 	char save_func, save_extra;
> 	for (i=0; i < 100000; ++i) {
> //		if (i % 1000)
> //			sleep(1);
> 		index = rand() % (STR_SIZE-1) + 1;
> 		save_func = funcB[index];
> 		save_extra = extraB[index];
> 		funcB[index] = '\0';
> 		extraB[index] = '\0';
> //		profile_time_begin("Hello");
> 		trace_mark(ust, times_begins, "thread %d func %s depth %d extra %s", 1, funcB, 1, extraB);
> 		count += count_prev;
> 		count_prev = count;
> //		profile_time_end("Goodbye");
> //		trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 1, func, 1, extra);
> 		funcB[index] = save_func;
> 		extraB[index] = save_extra;
> 	}
> }
> 
> * Mathieu Desnoyers (compudj at krystal.dyndns.org) wrote:
> > Hello,
> > 
> > The test case included in attachement reproduces reliably a problem with
> > UST. It generates randomly-sized strings, and I've noticed that the
> > string gets corrupted at some point. A README file in included with the
> > attachment.
> > 
> > I also got to a point where ustd segfaults very reliably on my machine.
> > I cannot take traces with it anymore.
> > 
> > Can you guys have a look ?
> > 
> > Thanks,
> > 
> > Mathieu
> > 
> > -- 
> > Mathieu Desnoyers
> > Operating System Efficiency R&D Consultant
> > EfficiOS Inc.
> > http://www.efficios.com
> 
> > Date: Tue, 10 Aug 2010 14:45:22 -0400
> > To: Mathieu Desnoyers <compudj at krystal.dyndns.org>
> > From: chris meyers <chris.meyers.fsu@gmail.com>
> > Subject: Re: [ltt-dev] ltt channel thread safe?
> > 
> > I made a simple test case that mimics the properties of my program that
> > produces the error (ie. multi-threaded and variable length strings mixed
> > with constant int's).
> > 
> > Check out the README in the archive.  Let me know if you have any questions!
> > 
> > Thanks,
> > -Chris
> > 
> > On Tue, Aug 10, 2010 at 11:46 AM, Mathieu Desnoyers <
> > compudj at krystal.dyndns.org> wrote:
> > 
> > > I think this looks like a data generation problem in UST.
> > >
> > > Can you send me your test program and a copy of a generated trace that
> > > contains the error, along with a full description of the system you
> > > gather the trace from and the system on which you run lttv ?
> > >
> > > It will be easier to debug if I can reproduce the problem myself.
> > >
> > > Thanks,
> > >
> > > Mathieu
> > >
> > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > So does it sound like maybe marker_update_fields_offsets() or add_type()
> > > is
> > > > at fault?
> > > >
> > > > -Chris
> > > >
> > > > On Tue, Aug 10, 2010 at 8:47 AM, Mathieu Desnoyers <
> > > > compudj at krystal.dyndns.org> wrote:
> > > >
> > > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > Ok sorry it's late.  The pasted output in the previous post should be
> > > the
> > > > > > below.  The debug printed hex data differs from when I print the
> > > buffer
> > > > > in
> > > > > > hex.  This is weird.
> > > > >
> > > > > I think because the debug and text dump outputs use a different file
> > > > > descriptor to output the text, and because there is a one event queue
> > > > > that is kept, there is a 1 or 2 events difference between the text dump
> > > > > output and the debug output.
> > > > >
> > > >
> > > > Ya, that makes it a bit more confusing :)
> > > >
> > > > >
> > > > > >
> > > > > > =========================
> > > > > > Info field lengths:
> > > > > > offset: 0 | size: 4
> > > > > > offset: 4 | size: 0
> > > > > > offset: 27 | size: 4
> > > > > > offset: 31 | size: 0
> > > > > >
> > > > > > 01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > 71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > 00 73 65 6C  65 63 74 28  29 20 62 6C  6F 63 6B 20
> > > > > > 74 69 6D 65  00
> > > > > > =========================
> > > > > > -------------------------------------
> > > > > > offset: 0 | size: 4
> > > > > > 01 00 00 00
> > > > > > -------------------------------------
> > > > > > -------------------------------------
> > > > > > offset: 4 | size: 0
> > > > > > 6E 65 5F 73  65 6C 65 63  74 5F 72 65  71 75 65 73
> > > > > > 74 5F 74 68  72 65 61 64  00 01 00 00  00 73 65 6C
> > > > > > 65 63 74 28  29 20 62 6C  6F 63 6B 20  74 69 6D 65
> > > > > > 00
> > > > >
> > > > > Hrm, it looks like the \0 here also belongs to the next integer.
> > > > >
> > > > > > -------------------------------------
> > > > > > -------------------------------------
> > > > > > offset: 27 | size: 4
> > > > > > 64 00 01 00
> > > > >
> > > > > So this is not the value you recorded, right ?
> > > > >
> > > > Correct, I recorded a 1.
> > > >
> > > > >
> > > > > Mathieu
> > > > >
> > > > > > -------------------------------------
> > > > > > -------------------------------------
> > > > > > offset: 31 | size: 0
> > > > > > 00 00 73 65  6C 65 63 74  28 29 20 62  6C 6F 63 6B
> > > > > > 20 74 69 6D  65 00
> > > > > > -------------------------------------
> > > > > > ust.time_end: 116791.642023291
> > > > > >
> > > > >
> > > (/home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0),
> > > > > > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > > Event header (tracefile
> > > > > >
> > > > >
> > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0
> > > > > > offset 3c0c5):
> > > > > >    3c0c5    66 FC 55 0C
> > > > > > tracefile.c ltt_update_event_size() data_size: 58
> > > > > > Event data (tracefile
> > > > > >
> > > > >
> > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0
> > > > > > offset 3c0c9):
> > > > > >    3c0c9    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > >  ....ne_select_re
> > > > > >    3c0d9    71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > >  quest_thread....
> > > > > >    3c0e9    00 6E 65 5F  73 65 6C 65  63 74 5F 72  65 71 75 65
> > > > > >  .ne_select_reque
> > > > > >    3c0f9    73 74 5F 74  68 72 65 61  64 00
> > > > > > st_thread.
> > > > > >
> > > > > > On Tue, Aug 10, 2010 at 1:31 AM, chris meyers <
> > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > >
> > > > > > > Thanks for the reply Pierre.  I still think my error is coming from
> > > > > lttv.
> > > > > > >
> > > > > > > Below is a trace with some printf's inserted.  In
> > > > > lttv_event_to_string() I
> > > > > > > iterate over all the 'struct marker_field' entries and output
> > > offset,
> > > > > into
> > > > > > > data, and size.  Then the data that corresponds to that offset is
> > > > > printed.
> > > > > > >  This can be cross-referenced against the two hex outputs above the
> > > > > print
> > > > > > > outs (the first hex output is from pre-existing debug code; the
> > > second
> > > > > hex
> > > > > > > output is to verify that the data buffer didn't change).  For some
> > > > > reason
> > > > > > > the second %lld (depth =) has a wrong offset.  Currently, I am
> > > > > investigating
> > > > > > > marker_update_fields_offsets() and add_type(), as these seem to be
> > > on
> > > > > the
> > > > > > > only two functions that deal with modifying the marker offset.
> > >  Maybe
> > > > > the
> > > > > > > string before 'depth' is "eating" too many bytes.  Any
> > > hints/help/ideas
> > > > > > > would be appreciated :)
> > > > > > >
> > > > > > > Event header (tracefile
> > > > > > >
> > > > >
> > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_1
> > > > > > > offset 3f39f):
> > > > > > >    3f39f    AB 66 D7 EA  01 00 36 00  AB 66 D7 B2  38 6A 00 00
> > > > > > > tracefile.c ltt_update_event_size() data_size: 54
> > > > > > > Event data (tracefile
> > > > > > >
> > > > >
> > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_1
> > > > > > > offset 3f3af):
> > > > > > >    3f3af    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > >  ....ne_select_re
> > > > > > >    3f3bf    70 6C 79 5F  74 68 72 65  61 64 00 01  00 00 00 6E
> > > > > > >  ply_thread.....n
> > > > > > >    3f3cf    65 5F 73 65  6C 65 63 74  5F 72 65 70  6C 79 5F 74
> > > > > > >  e_select_reply_t
> > > > > > >    3f3df    68 72 65 61  64 00
> > > > >  hread.
> > > > > > >
> > > > > > > =========================
> > > > > > > Info field lengths:
> > > > > > > offset: 0 | size: 4
> > > > > > > offset: 4 | size: 0
> > > > > > > offset: 27 | size: 4
> > > > > > > offset: 31 | size: 0
> > > > > > >
> > > > > > > 01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > 71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > > 00 73 65 6C  65 63 74 28  29 20 62 6C  6F 63 6B 20
> > > > > > > 74 69 6D 65  00
> > > > > > > =========================
> > > > > > > -------------------------------------
> > > > > > > offset: 0 | size: 4
> > > > > > > 01 00 00 00
> > > > > > > -------------------------------------
> > > > > > > -------------------------------------
> > > > > > > offset: 4 | size: 0
> > > > > > > 6E 65 5F 73  65 6C 65 63  74 5F 72 65  71 75 65 73
> > > > > > > 74 5F 74 68  72 65 61 64  00 01 00 00  00 73 65 6C
> > > > > > > 65 63 74 28  29 20 62 6C  6F 63 6B 20  74 69 6D 65
> > > > > > > 00
> > > > > > > -------------------------------------
> > > > > > > -------------------------------------
> > > > > > > offset: 27 | size: 4
> > > > > > > 64 00 01 00
> > > > > > > -------------------------------------
> > > > > > > -------------------------------------
> > > > > > > offset: 31 | size: 0
> > > > > > > 00 00 73 65  6C 65 63 74  28 29 20 62  6C 6F 63 6B
> > > > > > > 20 74 69 6D  65 00
> > > > > > > -------------------------------------
> > > > > > > ust.time_end: 116791.642023291
> > > > > > >
> > > > >
> > > (/home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0),
> > > > > > > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > > >
> > > > > > >
> > > > > > > On Mon, Aug 9, 2010 at 3:18 PM, Mathieu Desnoyers <
> > > > > > > compudj at krystal.dyndns.org> wrote:
> > > > > > >
> > > > > > >> * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > >> > debuging turned on.
> > > > > > >> > String: is the printf() added to lttv_print_field()
> > > > > > >> >
> > > > > > >> > Just eyeballing the debugging output from below, the log file
> > > seams
> > > > > > >> correct.
> > > > > > >> >  This further leads me to believe it is the output
> > > (lttv/textDump)
> > > > > that
> > > > > > >> is
> > > > > > >> > at fault.  Does the log entry seem correct to you?
> > > > > > >> >
> > > > > > >> > What I expected to be output:
> > > > > > >> > String: ne_select_request_thread
> > > > > > >> > String: ne_select_request_thread
> > > > > > >> > ust.time_end: 121283.601051208
> > > > > > >> >
> > > > > > >>
> > > > >
> > > (/home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0),
> > > > > > >> > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > >> > "ne_select_request_thread", depth = 65636, extra =
> > > > > > >> > "ne_select_request_thread" }
> > > > > > >> >
> > > > > > >> > ---------------------------------------------------------
> > > > > > >> >
> > > > > > >> > Actual output:
> > > > > > >> >
> > > > > > >> > String: ne_select_request_thread
> > > > > > >> > String:
> > > > > > >> > ust.time_end: 121283.601051208
> > > > > > >> >
> > > > > > >>
> > > > >
> > > (/home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0),
> > > > > > >> > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > >> > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > > >> > Event header (tracefile
> > > > > > >> >
> > > > > > >>
> > > > >
> > > /home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0
> > > > > > >> > offset 4b643):
> > > > > > >> >    4b643    A7 41 F5 09
> > > > > > >> > Event data (tracefile
> > > > > > >> >
> > > > > > >>
> > > > >
> > > /home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0
> > > > > > >> > offset 4b647):
> > > > > > >> >    4b647    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > >> >  ....ne_select_re
> > > > > > >> >    4b657    71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > >>
> > > > > > >> Is it me or the "64 00 01 00 00" part at the end above is
> > > unexpected ?
> > > > > > >>
> > > > > > >> We should have "64 00" which would be the end of string followed
> > > by
> > > > > the
> > > > > > >> final \0, and then the "00 01 00 00" which represents the 65536
> > > value.
> > > > > > >>
> > > > > > >> So I expect there might be a problem in UST where it forgets about
> > > > > doing
> > > > > > >> the +1 to taken into account the end of string \0 somewhere.
> > > > > > >>
> > > > > > >> Thanks,
> > > > > > >>
> > > > > > >> Mathieu
> > > > > > >>
> > > > > > >> >  quest_thread....
> > > > > > >> >    4b667    00 6E 65 5F  73 65 6C 65  63 74 5F 72  65 71 75 65
> > > > > > >> >  .ne_select_reque
> > > > > > >> >    4b677    73 74 5F 74  68 72 65 61  64 00
> > > > > > >> > st_thread.
> > > > > > >> >
> > > > > > >> >
> > > > > > >> > On Mon, Aug 9, 2010 at 11:08 AM, chris meyers <
> > > > > > >> chris.meyers.fsu at gmail.com>wrote:
> > > > > > >> >
> > > > > > >> > > Scratch that, the printf does not print out the correct data.
> > >  It
> > > > > > >> prints
> > > > > > >> > > the wrong data.
> > > > > > >> > >
> > > > > > >> > >
> > > > > > >> > > On Mon, Aug 9, 2010 at 11:06 AM, chris meyers <
> > > > > > >> chris.meyers.fsu at gmail.com>wrote:
> > > > > > >> > >
> > > > > > >> > >> The printf outputs the correct data (function names).
> > > > > > >> > >>
> > > > > > >> > >>
> > > > > > >> > >> On Mon, Aug 9, 2010 at 10:22 AM, Mathieu Desnoyers <
> > > > > > >> > >> compudj at krystal.dyndns.org> wrote:
> > > > > > >> > >>
> > > > > > >> > >>> Hrm, can you try adding some printfs in lttv
> > > > > > >> > >>>
> > > > > > >> > >>> lttv/lttv/print.c
> > > > > > >> > >>>
> > > > > > >> > >>> ltt_print_field()
> > > > > > >> > >>> within LTT_TYPE_STRING case of the switch.
> > > > > > >> > >>>
> > > > > > >> > >>> Thanks,
> > > > > > >> > >>>
> > > > > > >> > >>> Mathieu
> > > > > > >> > >>>
> > > > > > >> > >>> * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > >> > >>> > func_rand and extra_rand are two varying length "random"
> > > > > strings.
> > > > > > >>  This
> > > > > > >> > >>> > seems to be what causes the "garbling" output.  For some
> > > > > reason it
> > > > > > >> > >>> affects
> > > > > > >> > >>> > the value of depth (a constant set to 1).  I added a
> > > printf
> > > > > like
> > > > > > >> you
> > > > > > >> > >>> > mentioned and the correct values are printing out.  It
> > > seems
> > > > > that
> > > > > > >> the
> > > > > > >> > >>> > logging is correct.  I have a suspicion that the
> > > "textDump"
> > > > > module
> > > > > > >> in
> > > > > > >> > >>> lttv
> > > > > > >> > >>> > may be parsing incorrect.
> > > > > > >> > >>> >
> > > > > > >> > >>> > func_rand = ALLOC_RANDOM(rand() % 1024 + 1);
> > > > > > >> > >>> > extra_rand = ALLOC_RANDOM(rand() % 1024 + 1);
> > > > > > >> > >>> >
> > > > > > >> > >>> > trace_mark(ust, time_end, "thread %d func %s depth %d
> > > extra
> > > > > %s",
> > > > > > >> > >>> thread,
> > > > > > >> > >>> > func_rand, depth, extra_rand);
> > > > > > >> > >>> >
> > > > > > >> > >>> > On Sat, Aug 7, 2010 at 12:58 PM, Mathieu Desnoyers <
> > > > > > >> > >>> > compudj at krystal.dyndns.org> wrote:
> > > > > > >> > >>> >
> > > > > > >> > >>> > > Hrm, it might be caused by the fact that the
> > > __FUNCTION__ is
> > > > > > >> passed
> > > > > > >> > >>> > > through the trace_mark() macro. It could be a macro
> > > problem
> > > > > with
> > > > > > >> the
> > > > > > >> > >>> > > precompiler (odd behavior with __FUNCTION__ and
> > > defines).
> > > > > You
> > > > > > >> could
> > > > > > >> > >>> try
> > > > > > >> > >>> > > just outputting the result in the marker callback (the
> > > > > function
> > > > > > >> > >>> called
> > > > > > >> > >>> > > in marker.c) with printf and see if this is OK or not.
> > > > > > >> > >>> > >
> > > > > > >> > >>> > > Thanks,
> > > > > > >> > >>> > >
> > > > > > >> > >>> > > Mathieu
> > > > > > >> > >>> > >
> > > > > > >> > >>> > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > >> > >>> > > > I think I jumped the gun in saying that __func__
> > > worked.
> > > > > > >>  However,
> > > > > > >> > >>> I can
> > > > > > >> > >>> > > > confidently say that ca constant string, such as the
> > > one
> > > > > > >> below,
> > > > > > >> > >>> does not
> > > > > > >> > >>> > > > result in garbled output.  I will try dynamically
> > > > > generating
> > > > > > >> > >>> different
> > > > > > >> > >>> > > > length strings at runtime to log and see if that
> > > causes an
> > > > > > >> error.
> > > > > > >> > >>> > > >
> > > > > > >> > >>> > > > So to summarize thus far:
> > > > > > >> > >>> > > > __FUNCTION__ and __func__ both result in inconsistent
> > > > > output.
> > > > > > >> > >>> > > > Constant strings result in consistent output.
> > > > > > >> > >>> > > >
> > > > > > >> > >>> > > > trace_mark(ust, time_begin, "thread %d func %s depth
> > > %d
> > > > > extra
> > > > > > >> %s",
> > > > > > >> > >>> > > thread,
> > > > > > >> > >>> > > > "I like pie because it taste good", depth, "yummm i
> > > too
> > > > > like
> > > > > > >> pie
> > > > > > >> > >>> for
> > > > > > >> > >>> > > > dessert");
> > > > > > >> > >>> > > >
> > > > > > >> > >>> > > > quantify inconsistent: 260 out of 8197 (31%) log
> > > entries
> > > > > were
> > > > > > >> > >>> corrupt in
> > > > > > >> > >>> > > my
> > > > > > >> > >>> > > > case.
> > > > > > >> > >>> > > >
> > > > > > >> > >>> > > > -Chris
> > > > > > >> > >>> > > >
> > > > > > >> > >>> > > > On Sat, Aug 7, 2010 at 11:28 AM, Mathieu Desnoyers <
> > > > > > >> > >>> > > > compudj at krystal.dyndns.org> wrote:
> > > > > > >> > >>> > > >
> > > > > > >> > >>> > > > > What compiler do you use ? Can you reproduce with
> > > > > different
> > > > > > >> > >>> compiler
> > > > > > >> > >>> > > > > versions?
> > > > > > >> > >>> > > > >
> > > > > > >> > >>> > > > > Thanks,
> > > > > > >> > >>> > > > >
> > > > > > >> > >>> > > > > Mathieu
> > > > > > >> > >>> > > > >
> > > > > > >> > >>> > > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > >> > >>> > > > > > I don't know the exact reason why but __func__
> > > works
> > > > > and
> > > > > > >> > >>> __FUNCTION__
> > > > > > >> > >>> > > > > > doesn't.
> > > > > > >> > >>> > > > > >
> > > > > > >> > >>> > > > > > -Chris
> > > > > > >> > >>> > > > > >
> > > > > > >> > >>> > > > > > On Fri, Aug 6, 2010 at 11:47 PM, chris meyers <
> > > > > > >> > >>> > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > > >> > >>> > > > > >
> > > > > > >> > >>> > > > > > > #define LARGE_CONST 127LL
> > > > > > >> > >>> > > > > > > #define MY_STR "Hello"
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > > > > trace_mark(ust, time_end, "thread %lld func %s
> > > depth
> > > > > > >> %lld
> > > > > > >> > >>> extra
> > > > > > >> > >>> > > %s",
> > > > > > >> > >>> > > > > > > LARGE_CONST, MY_STR, LARGE_CONST, __FUNCTION__)
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > > > > Below is a snippet of the macro trace_marker
> > > > > expanded.
> > > > > > >>  My
> > > > > > >> > >>> macor
> > > > > > >> > >>> > > > > "MY_STR"
> > > > > > >> > >>> > > > > > > is replaced with Hello, while __FUNCTION__ is
> > > not
> > > > > > >> replaced.
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > > > > The expected output is inconsistent when I DO
> > > use
> > > > > > >> > >>> __FUNCTION__.
> > > > > > >> > >>> > > > > > > The expected output IS consistent when I do NOT
> > > use
> > > > > > >> > >>> __FUNCTION__.
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > > > > gcc -lust example.c -E
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > > > >  do { struct marker *m; struct registers regs;
> > > asm
> > > > > > >> volatile (
> > > > > > >> > >>> > > ".ifndef
> > > > > > >> > >>> > > > > > > __mstrtab_" "ust" "_" "time_end" "_channel_"
> > > "39"
> > > > > "\n\t"
> > > > > > >> > >>> ".section
> > > > > > >> > >>> > > > > > > __markers_strings,\"aw\", at progbits\n\t"
> > > "__mstrtab_"
> > > > > > >> "ust"
> > > > > > >> > >>> "_"
> > > > > > >> > >>> > > > > "time_end"
> > > > > > >> > >>> > > > > > > "_channel_" "39" ":\n\t" ".string \"" "ust"
> > > "\"\n\t"
> > > > > > >> > >>> "__mstrtab_"
> > > > > > >> > >>> > > "ust"
> > > > > > >> > >>> > > > > "_"
> > > > > > >> > >>> > > > > > > "time_end" "_name_" "39" ":\n\t" ".string \""
> > > > > "time_end"
> > > > > > >> > >>> "\"\n\t"
> > > > > > >> > >>> > > > > > > "__mstrtab_" "ust" "_" "time_end" "_format_"
> > > "39"
> > > > > > >> ":\n\t"
> > > > > > >> > >>> ".string
> > > > > > >> > >>> > > "
> > > > > > >> > >>> > > > > "\""
> > > > > > >> > >>> > > > > > > "thread %lld func %s depth %lld extra %s" "\""
> > > > > "\n\t"
> > > > > > >> > >>> > > ".previous\n\t"
> > > > > > >> > >>> > > > > > > ".endif\n\t" ); asm volatile ( ".section
> > > > > > >> > >>> > > > > __markers,\"aw\", at progbits\n\t"
> > > > > > >> > >>> > > > > > > ".balign 8\n\t" "2:\n\t" ".quad " "(__mstrtab_"
> > > > > "ust"
> > > > > > >> "_"
> > > > > > >> > >>> > > "time_end"
> > > > > > >> > >>> > > > > > > "_channel_" "39" ")\n\t" ".quad " "(__mstrtab_"
> > > > > "ust"
> > > > > > >> "_"
> > > > > > >> > >>> > > "time_end"
> > > > > > >> > >>> > > > > > > "_name_" "39" ")\n\t" ".quad " "(__mstrtab_"
> > > "ust"
> > > > > "_"
> > > > > > >> > >>> "time_end"
> > > > > > >> > >>> > > > > "_format_"
> > > > > > >> > >>> > > > > > > "39" ")\n\t" ".byte 0\n\t" ".byte 0\n\t" ".word
> > > > > 0\n\t"
> > > > > > >> ".word
> > > > > > >> > >>> > > 0\n\t"
> > > > > > >> > >>> > > > > > > ".balign " "64" " / 8\n\t" ".quad "
> > > > > > >> "(marker_probe_cb)\n\t"
> > > > > > >> > >>> ".quad
> > > > > > >> > >>> > > "
> > > > > > >> > >>> > > > > > > "(__mark_empty_function)\n\t" ".quad " "0\n\t"
> > > > > ".quad "
> > > > > > >> > >>> "0\n\t"
> > > > > > >> > >>> > > ".quad
> > > > > > >> > >>> > > > > "
> > > > > > >> > >>> > > > > > > "0\n\t" ".quad " "0\n\t" ".quad " "(1f)\n\t"
> > > > > > >> ".previous\n\t"
> > > > > > >> > >>> > > "1:\n\t"
> > > > > > >> > >>> > > > > "lea
> > > > > > >> > >>> > > > > > > 2b(%%rip)," "%[outptr]" "\n\t" : [outptr] "=r"
> > > (m)
> > > > > ); ;
> > > > > > >> do {
> > > > > > >> > >>> if (0)
> > > > > > >> > >>> > > > > > > ___mark_check_format("thread %lld func %s depth
> > > %lld
> > > > > > >> extra
> > > > > > >> > >>> %s",
> > > > > > >> > >>> > > 127LL,
> > > > > > >> > >>> > > > > > > "First", 127LL, __FUNCTION__); } while (0); if
> > > (!0)
> > > > > { if
> > > > > > >> > >>> > > > > > > (__builtin_expect(!!((m->state__imv)), 0))
> > > > > (m->call)(m,
> > > > > > >> > >>> ((void
> > > > > > >> > >>> > > *)0),
> > > > > > >> > >>> > > > > &regs,
> > > > > > >> > >>> > > > > > > 127LL, "First", 127LL, __FUNCTION__); } else {
> > > if
> > > > > > >> > >>> > > > > > > (__builtin_expect(!!((m->state__imv)), 0))
> > > > > (m->call)(m,
> > > > > > >> > >>> ((void
> > > > > > >> > >>> > > *)0),
> > > > > > >> > >>> > > > > &regs,
> > > > > > >> > >>> > > > > > > 127LL, "First", 127LL, __FUNCTION__); } } while
> > > (0);
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > > > > On Fri, Aug 6, 2010 at 5:10 PM, chris meyers <
> > > > > > >> > >>> > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > > > >> I am using the newest, development, version
> > > from
> > > > > the
> > > > > > >> git.  I
> > > > > > >> > >>> had
> > > > > > >> > >>> > > tried
> > > > > > >> > >>> > > > > the
> > > > > > >> > >>> > > > > > >> newest stable version with the same results.  I
> > > > > believe
> > > > > > >> the
> > > > > > >> > >>> newest
> > > > > > >> > >>> > > git
> > > > > > >> > >>> > > > > > >> commit has the patch that you are talking
> > > about.
> > > > > > >> > >>> > > > > > >>
> > > > > > >> > >>> > > > > > >> Thanks,
> > > > > > >> > >>> > > > > > >> -Chris
> > > > > > >> > >>> > > > > > >>
> > > > > > >> > >>> > > > > > >>
> > > > > > >> > >>> > > > > > >> On Fri, Aug 6, 2010 at 5:02 PM, Mathieu
> > > Desnoyers <
> > > > > > >> > >>> > > > > > >> compudj at krystal.dyndns.org> 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 ?
> > > > > > >> > >>> > > > > > >>>
> > > > > > >> > >>> > > > > > >>> 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
> > > > > > >> > >>> > > > > > >>>
> > > > > > >> > >>> > > > > > >>
> > > > > > >> > >>> > > > > > >>
> > > > > > >> > >>> > > > > > >
> > > > > > >> > >>> > > > >
> > > > > > >> > >>> > > > > --
> > > > > > >> > >>> > > > > Mathieu Desnoyers
> > > > > > >> > >>> > > > > Operating System Efficiency R&D Consultant
> > > > > > >> > >>> > > > > EfficiOS Inc.
> > > > > > >> > >>> > > > > http://www.efficios.com
> > > > > > >> > >>> > > > >
> > > > > > >> > >>> > >
> > > > > > >> > >>> > > --
> > > > > > >> > >>> > > Mathieu Desnoyers
> > > > > > >> > >>> > > Operating System Efficiency R&D Consultant
> > > > > > >> > >>> > > EfficiOS Inc.
> > > > > > >> > >>> > > http://www.efficios.com
> > > > > > >> > >>> > >
> > > > > > >> > >>>
> > > > > > >> > >>> --
> > > > > > >> > >>> Mathieu Desnoyers
> > > > > > >> > >>> Operating System Efficiency R&D Consultant
> > > > > > >> > >>> EfficiOS Inc.
> > > > > > >> > >>> http://www.efficios.com
> > > > > > >> > >>>
> > > > > > >> > >>
> > > > > > >> > >>
> > > > > > >> > >
> > > > > > >>
> > > > > > >> --
> > > > > > >> Mathieu Desnoyers
> > > > > > >> Operating System Efficiency R&D Consultant
> > > > > > >> EfficiOS Inc.
> > > > > > >> http://www.efficios.com
> > > > > > >>
> > > > > > >
> > > > > > >
> > > > >
> > > > > --
> > > > > Mathieu Desnoyers
> > > > > Operating System Efficiency R&D Consultant
> > > > > EfficiOS Inc.
> > > > > http://www.efficios.com
> > > > >
> > >
> > > --
> > > Mathieu Desnoyers
> > > Operating System Efficiency R&D Consultant
> > > EfficiOS Inc.
> > > http://www.efficios.com
> > >
> 
> 
> 
> > _______________________________________________
> > ltt-dev mailing list
> > ltt-dev at lists.casi.polymtl.ca
> > http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 
> 

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Mathieu Desnoyers]

* Fu Juntang(David) (juntang.fu at windriver.com) wrote:
> Hi,Mathieu:
>   I have found another UST bug in this multi-thread functions:
>   in my SMP host(2 cpu cores),I have found that UST can only collect one
>  thread trace logs running one core(CPU_1),but can not collect the 
>  other thread trace logs running another core(CPU_0),is this a known
> bug?
>   if you need my debug logs, I can attach it to you. 

can you send you /proc/cpuinfo and kernel version ?

Can you try putting a printf in 

ust/libust/buffer.c: get_n_cpus() to see how many CPUs the library
detects ?

What does your usttrace directory looks like ? (the subdir containing
the ust and metadata files... with ls -al)

Thanks,

Mathieu

> 
>   thanks
> 
> --David
> 
> On Wed, 2010-08-11 at 11:39 -0400, Mathieu Desnoyers wrote:
> > Ah, there was a bug in the test case I received. It was modifying 2
> > strings shared between threads concurrently.
> > 
> > It made me think of a way to handle concurrently modified strings
> > gracefully within both lttng and ust. I'll work on a patch. I plan to
> > use strncpy and detect if the string size changed after the strlen
> > performed for space reservation.
> > 
> > Here is the updated test case. It works now.
> > 
> > #include <ust/marker.h>
> > #include <stdio.h>
> > #include <pthread.h>
> > 
> > #define STR_SIZE	30
> > 
> > char funcA[STR_SIZE+10];
> > char extraA[STR_SIZE+10];
> > 
> > char funcB[STR_SIZE+10];
> > char extraB[STR_SIZE+10];
> > 
> > void *threadA(void *ptr);
> > void *threadB(void *ptr);
> > 
> > int main() {
> > 	int i=0;
> > 
> > 	pthread_t thread_id[2];
> > 	srand(1000);
> > 
> > 	for (i=0; i < STR_SIZE; ++i) {
> > 		funcA[i] = (i % (90-65)) + 65;
> > 		extraA[i] = (i % (90-65)) + 65;
> > 		funcB[i] = (i % (90-65)) + 65;
> > 		extraB[i] = (i % (90-65)) + 65;
> > 	}
> > 	funcA[STR_SIZE-1] = '\0';
> > 	extraA[STR_SIZE-1] = '\0';
> > 	funcB[STR_SIZE-1] = '\0';
> > 	extraB[STR_SIZE-1] = '\0';
> > 
> > 	printf("funcA:  %s\n", funcA);
> > 	printf("extraA: %s\n", extraA);
> > 	printf("funcB:  %s\n", funcB);
> > 	printf("extraB: %s\n", extraB);
> > 	pthread_create(&thread_id[0], NULL, threadA, (void*)NULL);
> > 	pthread_create(&thread_id[1], NULL, threadB, (void*)NULL);
> > 
> > 	for (i=0; i < 2; ++i) {
> > 		pthread_detach(thread_id[i]);
> > 	}
> > 	sleep(10);
> > }
> > 
> > 
> > void *threadA(void *ptr) {
> > 	int i=0,count_prev=0,count=0, index;
> > 	char save_func, save_extra;
> > 	for (i=0; i < 500000; ++i) {
> > //		if (i % 1000)
> > //			sleep(1);
> > 		index = rand() % (STR_SIZE-1) + 1;
> > 		save_func = funcA[index];
> > 		save_extra = extraA[index];
> > 		funcA[index] = '\0';
> > 		extraA[index] = '\0';
> > 		trace_mark(ust, times_begins, "thread %d func %s depth %d extra %s", 1, funcA, 1, extraA);
> > //		profile_time_begin("Hello");
> > 		count += count_prev;
> > 		count_prev = count;
> > //		trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 1, func, 1, extra);
> > //		profile_time_end("Goodbye");
> > 		funcA[index] = save_func;
> > 		extraA[index] = save_extra;
> > 	}
> > }
> > 
> > void *threadB(void *ptr) {
> > 	int i=0,count_prev=0,count=0, index;
> > 	char save_func, save_extra;
> > 	for (i=0; i < 100000; ++i) {
> > //		if (i % 1000)
> > //			sleep(1);
> > 		index = rand() % (STR_SIZE-1) + 1;
> > 		save_func = funcB[index];
> > 		save_extra = extraB[index];
> > 		funcB[index] = '\0';
> > 		extraB[index] = '\0';
> > //		profile_time_begin("Hello");
> > 		trace_mark(ust, times_begins, "thread %d func %s depth %d extra %s", 1, funcB, 1, extraB);
> > 		count += count_prev;
> > 		count_prev = count;
> > //		profile_time_end("Goodbye");
> > //		trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 1, func, 1, extra);
> > 		funcB[index] = save_func;
> > 		extraB[index] = save_extra;
> > 	}
> > }
> > 
> > * Mathieu Desnoyers (compudj at krystal.dyndns.org) wrote:
> > > Hello,
> > > 
> > > The test case included in attachement reproduces reliably a problem with
> > > UST. It generates randomly-sized strings, and I've noticed that the
> > > string gets corrupted at some point. A README file in included with the
> > > attachment.
> > > 
> > > I also got to a point where ustd segfaults very reliably on my machine.
> > > I cannot take traces with it anymore.
> > > 
> > > Can you guys have a look ?
> > > 
> > > Thanks,
> > > 
> > > Mathieu
> > > 
> > > -- 
> > > Mathieu Desnoyers
> > > Operating System Efficiency R&D Consultant
> > > EfficiOS Inc.
> > > http://www.efficios.com
> > 
> > > Date: Tue, 10 Aug 2010 14:45:22 -0400
> > > To: Mathieu Desnoyers <compudj at krystal.dyndns.org>
> > > From: chris meyers <chris.meyers.fsu@gmail.com>
> > > Subject: Re: [ltt-dev] ltt channel thread safe?
> > > 
> > > I made a simple test case that mimics the properties of my program that
> > > produces the error (ie. multi-threaded and variable length strings mixed
> > > with constant int's).
> > > 
> > > Check out the README in the archive.  Let me know if you have any questions!
> > > 
> > > Thanks,
> > > -Chris
> > > 
> > > On Tue, Aug 10, 2010 at 11:46 AM, Mathieu Desnoyers <
> > > compudj at krystal.dyndns.org> wrote:
> > > 
> > > > I think this looks like a data generation problem in UST.
> > > >
> > > > Can you send me your test program and a copy of a generated trace that
> > > > contains the error, along with a full description of the system you
> > > > gather the trace from and the system on which you run lttv ?
> > > >
> > > > It will be easier to debug if I can reproduce the problem myself.
> > > >
> > > > Thanks,
> > > >
> > > > Mathieu
> > > >
> > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > So does it sound like maybe marker_update_fields_offsets() or add_type()
> > > > is
> > > > > at fault?
> > > > >
> > > > > -Chris
> > > > >
> > > > > On Tue, Aug 10, 2010 at 8:47 AM, Mathieu Desnoyers <
> > > > > compudj at krystal.dyndns.org> wrote:
> > > > >
> > > > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > Ok sorry it's late.  The pasted output in the previous post should be
> > > > the
> > > > > > > below.  The debug printed hex data differs from when I print the
> > > > buffer
> > > > > > in
> > > > > > > hex.  This is weird.
> > > > > >
> > > > > > I think because the debug and text dump outputs use a different file
> > > > > > descriptor to output the text, and because there is a one event queue
> > > > > > that is kept, there is a 1 or 2 events difference between the text dump
> > > > > > output and the debug output.
> > > > > >
> > > > >
> > > > > Ya, that makes it a bit more confusing :)
> > > > >
> > > > > >
> > > > > > >
> > > > > > > =========================
> > > > > > > Info field lengths:
> > > > > > > offset: 0 | size: 4
> > > > > > > offset: 4 | size: 0
> > > > > > > offset: 27 | size: 4
> > > > > > > offset: 31 | size: 0
> > > > > > >
> > > > > > > 01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > 71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > > 00 73 65 6C  65 63 74 28  29 20 62 6C  6F 63 6B 20
> > > > > > > 74 69 6D 65  00
> > > > > > > =========================
> > > > > > > -------------------------------------
> > > > > > > offset: 0 | size: 4
> > > > > > > 01 00 00 00
> > > > > > > -------------------------------------
> > > > > > > -------------------------------------
> > > > > > > offset: 4 | size: 0
> > > > > > > 6E 65 5F 73  65 6C 65 63  74 5F 72 65  71 75 65 73
> > > > > > > 74 5F 74 68  72 65 61 64  00 01 00 00  00 73 65 6C
> > > > > > > 65 63 74 28  29 20 62 6C  6F 63 6B 20  74 69 6D 65
> > > > > > > 00
> > > > > >
> > > > > > Hrm, it looks like the \0 here also belongs to the next integer.
> > > > > >
> > > > > > > -------------------------------------
> > > > > > > -------------------------------------
> > > > > > > offset: 27 | size: 4
> > > > > > > 64 00 01 00
> > > > > >
> > > > > > So this is not the value you recorded, right ?
> > > > > >
> > > > > Correct, I recorded a 1.
> > > > >
> > > > > >
> > > > > > Mathieu
> > > > > >
> > > > > > > -------------------------------------
> > > > > > > -------------------------------------
> > > > > > > offset: 31 | size: 0
> > > > > > > 00 00 73 65  6C 65 63 74  28 29 20 62  6C 6F 63 6B
> > > > > > > 20 74 69 6D  65 00
> > > > > > > -------------------------------------
> > > > > > > ust.time_end: 116791.642023291
> > > > > > >
> > > > > >
> > > > (/home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0),
> > > > > > > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > > > Event header (tracefile
> > > > > > >
> > > > > >
> > > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0
> > > > > > > offset 3c0c5):
> > > > > > >    3c0c5    66 FC 55 0C
> > > > > > > tracefile.c ltt_update_event_size() data_size: 58
> > > > > > > Event data (tracefile
> > > > > > >
> > > > > >
> > > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0
> > > > > > > offset 3c0c9):
> > > > > > >    3c0c9    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > >  ....ne_select_re
> > > > > > >    3c0d9    71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > >  quest_thread....
> > > > > > >    3c0e9    00 6E 65 5F  73 65 6C 65  63 74 5F 72  65 71 75 65
> > > > > > >  .ne_select_reque
> > > > > > >    3c0f9    73 74 5F 74  68 72 65 61  64 00
> > > > > > > st_thread.
> > > > > > >
> > > > > > > On Tue, Aug 10, 2010 at 1:31 AM, chris meyers <
> > > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > > >
> > > > > > > > Thanks for the reply Pierre.  I still think my error is coming from
> > > > > > lttv.
> > > > > > > >
> > > > > > > > Below is a trace with some printf's inserted.  In
> > > > > > lttv_event_to_string() I
> > > > > > > > iterate over all the 'struct marker_field' entries and output
> > > > offset,
> > > > > > into
> > > > > > > > data, and size.  Then the data that corresponds to that offset is
> > > > > > printed.
> > > > > > > >  This can be cross-referenced against the two hex outputs above the
> > > > > > print
> > > > > > > > outs (the first hex output is from pre-existing debug code; the
> > > > second
> > > > > > hex
> > > > > > > > output is to verify that the data buffer didn't change).  For some
> > > > > > reason
> > > > > > > > the second %lld (depth =) has a wrong offset.  Currently, I am
> > > > > > investigating
> > > > > > > > marker_update_fields_offsets() and add_type(), as these seem to be
> > > > on
> > > > > > the
> > > > > > > > only two functions that deal with modifying the marker offset.
> > > >  Maybe
> > > > > > the
> > > > > > > > string before 'depth' is "eating" too many bytes.  Any
> > > > hints/help/ideas
> > > > > > > > would be appreciated :)
> > > > > > > >
> > > > > > > > Event header (tracefile
> > > > > > > >
> > > > > >
> > > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_1
> > > > > > > > offset 3f39f):
> > > > > > > >    3f39f    AB 66 D7 EA  01 00 36 00  AB 66 D7 B2  38 6A 00 00
> > > > > > > > tracefile.c ltt_update_event_size() data_size: 54
> > > > > > > > Event data (tracefile
> > > > > > > >
> > > > > >
> > > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_1
> > > > > > > > offset 3f3af):
> > > > > > > >    3f3af    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > >  ....ne_select_re
> > > > > > > >    3f3bf    70 6C 79 5F  74 68 72 65  61 64 00 01  00 00 00 6E
> > > > > > > >  ply_thread.....n
> > > > > > > >    3f3cf    65 5F 73 65  6C 65 63 74  5F 72 65 70  6C 79 5F 74
> > > > > > > >  e_select_reply_t
> > > > > > > >    3f3df    68 72 65 61  64 00
> > > > > >  hread.
> > > > > > > >
> > > > > > > > =========================
> > > > > > > > Info field lengths:
> > > > > > > > offset: 0 | size: 4
> > > > > > > > offset: 4 | size: 0
> > > > > > > > offset: 27 | size: 4
> > > > > > > > offset: 31 | size: 0
> > > > > > > >
> > > > > > > > 01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > > 71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > > > 00 73 65 6C  65 63 74 28  29 20 62 6C  6F 63 6B 20
> > > > > > > > 74 69 6D 65  00
> > > > > > > > =========================
> > > > > > > > -------------------------------------
> > > > > > > > offset: 0 | size: 4
> > > > > > > > 01 00 00 00
> > > > > > > > -------------------------------------
> > > > > > > > -------------------------------------
> > > > > > > > offset: 4 | size: 0
> > > > > > > > 6E 65 5F 73  65 6C 65 63  74 5F 72 65  71 75 65 73
> > > > > > > > 74 5F 74 68  72 65 61 64  00 01 00 00  00 73 65 6C
> > > > > > > > 65 63 74 28  29 20 62 6C  6F 63 6B 20  74 69 6D 65
> > > > > > > > 00
> > > > > > > > -------------------------------------
> > > > > > > > -------------------------------------
> > > > > > > > offset: 27 | size: 4
> > > > > > > > 64 00 01 00
> > > > > > > > -------------------------------------
> > > > > > > > -------------------------------------
> > > > > > > > offset: 31 | size: 0
> > > > > > > > 00 00 73 65  6C 65 63 74  28 29 20 62  6C 6F 63 6B
> > > > > > > > 20 74 69 6D  65 00
> > > > > > > > -------------------------------------
> > > > > > > > ust.time_end: 116791.642023291
> > > > > > > >
> > > > > >
> > > > (/home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0),
> > > > > > > > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > > > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > > > >
> > > > > > > >
> > > > > > > > On Mon, Aug 9, 2010 at 3:18 PM, Mathieu Desnoyers <
> > > > > > > > compudj at krystal.dyndns.org> wrote:
> > > > > > > >
> > > > > > > >> * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > >> > debuging turned on.
> > > > > > > >> > String: is the printf() added to lttv_print_field()
> > > > > > > >> >
> > > > > > > >> > Just eyeballing the debugging output from below, the log file
> > > > seams
> > > > > > > >> correct.
> > > > > > > >> >  This further leads me to believe it is the output
> > > > (lttv/textDump)
> > > > > > that
> > > > > > > >> is
> > > > > > > >> > at fault.  Does the log entry seem correct to you?
> > > > > > > >> >
> > > > > > > >> > What I expected to be output:
> > > > > > > >> > String: ne_select_request_thread
> > > > > > > >> > String: ne_select_request_thread
> > > > > > > >> > ust.time_end: 121283.601051208
> > > > > > > >> >
> > > > > > > >>
> > > > > >
> > > > (/home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0),
> > > > > > > >> > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > > >> > "ne_select_request_thread", depth = 65636, extra =
> > > > > > > >> > "ne_select_request_thread" }
> > > > > > > >> >
> > > > > > > >> > ---------------------------------------------------------
> > > > > > > >> >
> > > > > > > >> > Actual output:
> > > > > > > >> >
> > > > > > > >> > String: ne_select_request_thread
> > > > > > > >> > String:
> > > > > > > >> > ust.time_end: 121283.601051208
> > > > > > > >> >
> > > > > > > >>
> > > > > >
> > > > (/home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0),
> > > > > > > >> > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > > >> > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > > > >> > Event header (tracefile
> > > > > > > >> >
> > > > > > > >>
> > > > > >
> > > > /home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0
> > > > > > > >> > offset 4b643):
> > > > > > > >> >    4b643    A7 41 F5 09
> > > > > > > >> > Event data (tracefile
> > > > > > > >> >
> > > > > > > >>
> > > > > >
> > > > /home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0
> > > > > > > >> > offset 4b647):
> > > > > > > >> >    4b647    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > >> >  ....ne_select_re
> > > > > > > >> >    4b657    71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > > >>
> > > > > > > >> Is it me or the "64 00 01 00 00" part at the end above is
> > > > unexpected ?
> > > > > > > >>
> > > > > > > >> We should have "64 00" which would be the end of string followed
> > > > by
> > > > > > the
> > > > > > > >> final \0, and then the "00 01 00 00" which represents the 65536
> > > > value.
> > > > > > > >>
> > > > > > > >> So I expect there might be a problem in UST where it forgets about
> > > > > > doing
> > > > > > > >> the +1 to taken into account the end of string \0 somewhere.
> > > > > > > >>
> > > > > > > >> Thanks,
> > > > > > > >>
> > > > > > > >> Mathieu
> > > > > > > >>
> > > > > > > >> >  quest_thread....
> > > > > > > >> >    4b667    00 6E 65 5F  73 65 6C 65  63 74 5F 72  65 71 75 65
> > > > > > > >> >  .ne_select_reque
> > > > > > > >> >    4b677    73 74 5F 74  68 72 65 61  64 00
> > > > > > > >> > st_thread.
> > > > > > > >> >
> > > > > > > >> >
> > > > > > > >> > On Mon, Aug 9, 2010 at 11:08 AM, chris meyers <
> > > > > > > >> chris.meyers.fsu at gmail.com>wrote:
> > > > > > > >> >
> > > > > > > >> > > Scratch that, the printf does not print out the correct data.
> > > >  It
> > > > > > > >> prints
> > > > > > > >> > > the wrong data.
> > > > > > > >> > >
> > > > > > > >> > >
> > > > > > > >> > > On Mon, Aug 9, 2010 at 11:06 AM, chris meyers <
> > > > > > > >> chris.meyers.fsu at gmail.com>wrote:
> > > > > > > >> > >
> > > > > > > >> > >> The printf outputs the correct data (function names).
> > > > > > > >> > >>
> > > > > > > >> > >>
> > > > > > > >> > >> On Mon, Aug 9, 2010 at 10:22 AM, Mathieu Desnoyers <
> > > > > > > >> > >> compudj at krystal.dyndns.org> wrote:
> > > > > > > >> > >>
> > > > > > > >> > >>> Hrm, can you try adding some printfs in lttv
> > > > > > > >> > >>>
> > > > > > > >> > >>> lttv/lttv/print.c
> > > > > > > >> > >>>
> > > > > > > >> > >>> ltt_print_field()
> > > > > > > >> > >>> within LTT_TYPE_STRING case of the switch.
> > > > > > > >> > >>>
> > > > > > > >> > >>> Thanks,
> > > > > > > >> > >>>
> > > > > > > >> > >>> Mathieu
> > > > > > > >> > >>>
> > > > > > > >> > >>> * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > >> > >>> > func_rand and extra_rand are two varying length "random"
> > > > > > strings.
> > > > > > > >>  This
> > > > > > > >> > >>> > seems to be what causes the "garbling" output.  For some
> > > > > > reason it
> > > > > > > >> > >>> affects
> > > > > > > >> > >>> > the value of depth (a constant set to 1).  I added a
> > > > printf
> > > > > > like
> > > > > > > >> you
> > > > > > > >> > >>> > mentioned and the correct values are printing out.  It
> > > > seems
> > > > > > that
> > > > > > > >> the
> > > > > > > >> > >>> > logging is correct.  I have a suspicion that the
> > > > "textDump"
> > > > > > module
> > > > > > > >> in
> > > > > > > >> > >>> lttv
> > > > > > > >> > >>> > may be parsing incorrect.
> > > > > > > >> > >>> >
> > > > > > > >> > >>> > func_rand = ALLOC_RANDOM(rand() % 1024 + 1);
> > > > > > > >> > >>> > extra_rand = ALLOC_RANDOM(rand() % 1024 + 1);
> > > > > > > >> > >>> >
> > > > > > > >> > >>> > trace_mark(ust, time_end, "thread %d func %s depth %d
> > > > extra
> > > > > > %s",
> > > > > > > >> > >>> thread,
> > > > > > > >> > >>> > func_rand, depth, extra_rand);
> > > > > > > >> > >>> >
> > > > > > > >> > >>> > On Sat, Aug 7, 2010 at 12:58 PM, Mathieu Desnoyers <
> > > > > > > >> > >>> > compudj at krystal.dyndns.org> wrote:
> > > > > > > >> > >>> >
> > > > > > > >> > >>> > > Hrm, it might be caused by the fact that the
> > > > __FUNCTION__ is
> > > > > > > >> passed
> > > > > > > >> > >>> > > through the trace_mark() macro. It could be a macro
> > > > problem
> > > > > > with
> > > > > > > >> the
> > > > > > > >> > >>> > > precompiler (odd behavior with __FUNCTION__ and
> > > > defines).
> > > > > > You
> > > > > > > >> could
> > > > > > > >> > >>> try
> > > > > > > >> > >>> > > just outputting the result in the marker callback (the
> > > > > > function
> > > > > > > >> > >>> called
> > > > > > > >> > >>> > > in marker.c) with printf and see if this is OK or not.
> > > > > > > >> > >>> > >
> > > > > > > >> > >>> > > Thanks,
> > > > > > > >> > >>> > >
> > > > > > > >> > >>> > > Mathieu
> > > > > > > >> > >>> > >
> > > > > > > >> > >>> > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > >> > >>> > > > I think I jumped the gun in saying that __func__
> > > > worked.
> > > > > > > >>  However,
> > > > > > > >> > >>> I can
> > > > > > > >> > >>> > > > confidently say that ca constant string, such as the
> > > > one
> > > > > > > >> below,
> > > > > > > >> > >>> does not
> > > > > > > >> > >>> > > > result in garbled output.  I will try dynamically
> > > > > > generating
> > > > > > > >> > >>> different
> > > > > > > >> > >>> > > > length strings at runtime to log and see if that
> > > > causes an
> > > > > > > >> error.
> > > > > > > >> > >>> > > >
> > > > > > > >> > >>> > > > So to summarize thus far:
> > > > > > > >> > >>> > > > __FUNCTION__ and __func__ both result in inconsistent
> > > > > > output.
> > > > > > > >> > >>> > > > Constant strings result in consistent output.
> > > > > > > >> > >>> > > >
> > > > > > > >> > >>> > > > trace_mark(ust, time_begin, "thread %d func %s depth
> > > > %d
> > > > > > extra
> > > > > > > >> %s",
> > > > > > > >> > >>> > > thread,
> > > > > > > >> > >>> > > > "I like pie because it taste good", depth, "yummm i
> > > > too
> > > > > > like
> > > > > > > >> pie
> > > > > > > >> > >>> for
> > > > > > > >> > >>> > > > dessert");
> > > > > > > >> > >>> > > >
> > > > > > > >> > >>> > > > quantify inconsistent: 260 out of 8197 (31%) log
> > > > entries
> > > > > > were
> > > > > > > >> > >>> corrupt in
> > > > > > > >> > >>> > > my
> > > > > > > >> > >>> > > > case.
> > > > > > > >> > >>> > > >
> > > > > > > >> > >>> > > > -Chris
> > > > > > > >> > >>> > > >
> > > > > > > >> > >>> > > > On Sat, Aug 7, 2010 at 11:28 AM, Mathieu Desnoyers <
> > > > > > > >> > >>> > > > compudj at krystal.dyndns.org> wrote:
> > > > > > > >> > >>> > > >
> > > > > > > >> > >>> > > > > What compiler do you use ? Can you reproduce with
> > > > > > different
> > > > > > > >> > >>> compiler
> > > > > > > >> > >>> > > > > versions?
> > > > > > > >> > >>> > > > >
> > > > > > > >> > >>> > > > > Thanks,
> > > > > > > >> > >>> > > > >
> > > > > > > >> > >>> > > > > Mathieu
> > > > > > > >> > >>> > > > >
> > > > > > > >> > >>> > > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > >> > >>> > > > > > I don't know the exact reason why but __func__
> > > > works
> > > > > > and
> > > > > > > >> > >>> __FUNCTION__
> > > > > > > >> > >>> > > > > > doesn't.
> > > > > > > >> > >>> > > > > >
> > > > > > > >> > >>> > > > > > -Chris
> > > > > > > >> > >>> > > > > >
> > > > > > > >> > >>> > > > > > On Fri, Aug 6, 2010 at 11:47 PM, chris meyers <
> > > > > > > >> > >>> > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > > > >> > >>> > > > > >
> > > > > > > >> > >>> > > > > > > #define LARGE_CONST 127LL
> > > > > > > >> > >>> > > > > > > #define MY_STR "Hello"
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > > > > trace_mark(ust, time_end, "thread %lld func %s
> > > > depth
> > > > > > > >> %lld
> > > > > > > >> > >>> extra
> > > > > > > >> > >>> > > %s",
> > > > > > > >> > >>> > > > > > > LARGE_CONST, MY_STR, LARGE_CONST, __FUNCTION__)
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > > > > Below is a snippet of the macro trace_marker
> > > > > > expanded.
> > > > > > > >>  My
> > > > > > > >> > >>> macor
> > > > > > > >> > >>> > > > > "MY_STR"
> > > > > > > >> > >>> > > > > > > is replaced with Hello, while __FUNCTION__ is
> > > > not
> > > > > > > >> replaced.
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > > > > The expected output is inconsistent when I DO
> > > > use
> > > > > > > >> > >>> __FUNCTION__.
> > > > > > > >> > >>> > > > > > > The expected output IS consistent when I do NOT
> > > > use
> > > > > > > >> > >>> __FUNCTION__.
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > > > > gcc -lust example.c -E
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > > > >  do { struct marker *m; struct registers regs;
> > > > asm
> > > > > > > >> volatile (
> > > > > > > >> > >>> > > ".ifndef
> > > > > > > >> > >>> > > > > > > __mstrtab_" "ust" "_" "time_end" "_channel_"
> > > > "39"
> > > > > > "\n\t"
> > > > > > > >> > >>> ".section
> > > > > > > >> > >>> > > > > > > __markers_strings,\"aw\", at progbits\n\t"
> > > > "__mstrtab_"
> > > > > > > >> "ust"
> > > > > > > >> > >>> "_"
> > > > > > > >> > >>> > > > > "time_end"
> > > > > > > >> > >>> > > > > > > "_channel_" "39" ":\n\t" ".string \"" "ust"
> > > > "\"\n\t"
> > > > > > > >> > >>> "__mstrtab_"
> > > > > > > >> > >>> > > "ust"
> > > > > > > >> > >>> > > > > "_"
> > > > > > > >> > >>> > > > > > > "time_end" "_name_" "39" ":\n\t" ".string \""
> > > > > > "time_end"
> > > > > > > >> > >>> "\"\n\t"
> > > > > > > >> > >>> > > > > > > "__mstrtab_" "ust" "_" "time_end" "_format_"
> > > > "39"
> > > > > > > >> ":\n\t"
> > > > > > > >> > >>> ".string
> > > > > > > >> > >>> > > "
> > > > > > > >> > >>> > > > > "\""
> > > > > > > >> > >>> > > > > > > "thread %lld func %s depth %lld extra %s" "\""
> > > > > > "\n\t"
> > > > > > > >> > >>> > > ".previous\n\t"
> > > > > > > >> > >>> > > > > > > ".endif\n\t" ); asm volatile ( ".section
> > > > > > > >> > >>> > > > > __markers,\"aw\", at progbits\n\t"
> > > > > > > >> > >>> > > > > > > ".balign 8\n\t" "2:\n\t" ".quad " "(__mstrtab_"
> > > > > > "ust"
> > > > > > > >> "_"
> > > > > > > >> > >>> > > "time_end"
> > > > > > > >> > >>> > > > > > > "_channel_" "39" ")\n\t" ".quad " "(__mstrtab_"
> > > > > > "ust"
> > > > > > > >> "_"
> > > > > > > >> > >>> > > "time_end"
> > > > > > > >> > >>> > > > > > > "_name_" "39" ")\n\t" ".quad " "(__mstrtab_"
> > > > "ust"
> > > > > > "_"
> > > > > > > >> > >>> "time_end"
> > > > > > > >> > >>> > > > > "_format_"
> > > > > > > >> > >>> > > > > > > "39" ")\n\t" ".byte 0\n\t" ".byte 0\n\t" ".word
> > > > > > 0\n\t"
> > > > > > > >> ".word
> > > > > > > >> > >>> > > 0\n\t"
> > > > > > > >> > >>> > > > > > > ".balign " "64" " / 8\n\t" ".quad "
> > > > > > > >> "(marker_probe_cb)\n\t"
> > > > > > > >> > >>> ".quad
> > > > > > > >> > >>> > > "
> > > > > > > >> > >>> > > > > > > "(__mark_empty_function)\n\t" ".quad " "0\n\t"
> > > > > > ".quad "
> > > > > > > >> > >>> "0\n\t"
> > > > > > > >> > >>> > > ".quad
> > > > > > > >> > >>> > > > > "
> > > > > > > >> > >>> > > > > > > "0\n\t" ".quad " "0\n\t" ".quad " "(1f)\n\t"
> > > > > > > >> ".previous\n\t"
> > > > > > > >> > >>> > > "1:\n\t"
> > > > > > > >> > >>> > > > > "lea
> > > > > > > >> > >>> > > > > > > 2b(%%rip)," "%[outptr]" "\n\t" : [outptr] "=r"
> > > > (m)
> > > > > > ); ;
> > > > > > > >> do {
> > > > > > > >> > >>> if (0)
> > > > > > > >> > >>> > > > > > > ___mark_check_format("thread %lld func %s depth
> > > > %lld
> > > > > > > >> extra
> > > > > > > >> > >>> %s",
> > > > > > > >> > >>> > > 127LL,
> > > > > > > >> > >>> > > > > > > "First", 127LL, __FUNCTION__); } while (0); if
> > > > (!0)
> > > > > > { if
> > > > > > > >> > >>> > > > > > > (__builtin_expect(!!((m->state__imv)), 0))
> > > > > > (m->call)(m,
> > > > > > > >> > >>> ((void
> > > > > > > >> > >>> > > *)0),
> > > > > > > >> > >>> > > > > &regs,
> > > > > > > >> > >>> > > > > > > 127LL, "First", 127LL, __FUNCTION__); } else {
> > > > if
> > > > > > > >> > >>> > > > > > > (__builtin_expect(!!((m->state__imv)), 0))
> > > > > > (m->call)(m,
> > > > > > > >> > >>> ((void
> > > > > > > >> > >>> > > *)0),
> > > > > > > >> > >>> > > > > &regs,
> > > > > > > >> > >>> > > > > > > 127LL, "First", 127LL, __FUNCTION__); } } while
> > > > (0);
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > > > > On Fri, Aug 6, 2010 at 5:10 PM, chris meyers <
> > > > > > > >> > >>> > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > > > >> I am using the newest, development, version
> > > > from
> > > > > > the
> > > > > > > >> git.  I
> > > > > > > >> > >>> had
> > > > > > > >> > >>> > > tried
> > > > > > > >> > >>> > > > > the
> > > > > > > >> > >>> > > > > > >> newest stable version with the same results.  I
> > > > > > believe
> > > > > > > >> the
> > > > > > > >> > >>> newest
> > > > > > > >> > >>> > > git
> > > > > > > >> > >>> > > > > > >> commit has the patch that you are talking
> > > > about.
> > > > > > > >> > >>> > > > > > >>
> > > > > > > >> > >>> > > > > > >> Thanks,
> > > > > > > >> > >>> > > > > > >> -Chris
> > > > > > > >> > >>> > > > > > >>
> > > > > > > >> > >>> > > > > > >>
> > > > > > > >> > >>> > > > > > >> On Fri, Aug 6, 2010 at 5:02 PM, Mathieu
> > > > Desnoyers <
> > > > > > > >> > >>> > > > > > >> compudj at krystal.dyndns.org> 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 ?
> > > > > > > >> > >>> > > > > > >>>
> > > > > > > >> > >>> > > > > > >>> 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
> > > > > > > >> > >>> > > > > > >>>
> > > > > > > >> > >>> > > > > > >>
> > > > > > > >> > >>> > > > > > >>
> > > > > > > >> > >>> > > > > > >
> > > > > > > >> > >>> > > > >
> > > > > > > >> > >>> > > > > --
> > > > > > > >> > >>> > > > > Mathieu Desnoyers
> > > > > > > >> > >>> > > > > Operating System Efficiency R&D Consultant
> > > > > > > >> > >>> > > > > EfficiOS Inc.
> > > > > > > >> > >>> > > > > http://www.efficios.com
> > > > > > > >> > >>> > > > >
> > > > > > > >> > >>> > >
> > > > > > > >> > >>> > > --
> > > > > > > >> > >>> > > Mathieu Desnoyers
> > > > > > > >> > >>> > > Operating System Efficiency R&D Consultant
> > > > > > > >> > >>> > > EfficiOS Inc.
> > > > > > > >> > >>> > > http://www.efficios.com
> > > > > > > >> > >>> > >
> > > > > > > >> > >>>
> > > > > > > >> > >>> --
> > > > > > > >> > >>> Mathieu Desnoyers
> > > > > > > >> > >>> Operating System Efficiency R&D Consultant
> > > > > > > >> > >>> EfficiOS Inc.
> > > > > > > >> > >>> http://www.efficios.com
> > > > > > > >> > >>>
> > > > > > > >> > >>
> > > > > > > >> > >>
> > > > > > > >> > >
> > > > > > > >>
> > > > > > > >> --
> > > > > > > >> Mathieu Desnoyers
> > > > > > > >> Operating System Efficiency R&D Consultant
> > > > > > > >> EfficiOS Inc.
> > > > > > > >> http://www.efficios.com
> > > > > > > >>
> > > > > > > >
> > > > > > > >
> > > > > >
> > > > > > --
> > > > > > Mathieu Desnoyers
> > > > > > Operating System Efficiency R&D Consultant
> > > > > > EfficiOS Inc.
> > > > > > http://www.efficios.com
> > > > > >
> > > >
> > > > --
> > > > Mathieu Desnoyers
> > > > Operating System Efficiency R&D Consultant
> > > > EfficiOS Inc.
> > > > http://www.efficios.com
> > > >
> > 
> > 
> > 
> > > _______________________________________________
> > > 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] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Fu Juntang(David)]

Hi,Mathieu:
  Please see my answer inline:

On Thu, 2010-08-12 at 09:40 -0400, Mathieu Desnoyers wrote:
> * Fu Juntang(David) (juntang.fu at windriver.com) wrote:
> > Hi,Mathieu:
> >   I have found another UST bug in this multi-thread functions:
> >   in my SMP host(2 cpu cores),I have found that UST can only collect one
> >  thread trace logs running one core(CPU_1),but can not collect the 
> >  other thread trace logs running another core(CPU_0),is this a known
> > bug?
> >   if you need my debug logs, I can attach it to you. 
> 
> can you send you /proc/cpuinfo and kernel version ?
> 
$uname -a
Linux desktop 2.6.33.4 #1 SMP Mon May 31 16:28:08 CST 2010 i686
GNU/Linux

$ cat /proc/cpuinfo 
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 15
model name	: Intel(R) Core(TM)2 Duo CPU     E6750  @ 2.66GHz
stepping	: 11
cpu MHz		: 2659.765
cache size	: 4096 KB
physical id	: 0
siblings	: 2
core id		: 0
cpu cores	: 2
apicid		: 0
initial apicid	: 0
fdiv_bug	: no
hlt_bug		: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 10
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov
pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe nx lm
constant_tsc arch_perfmon pebs bts aperfmperf pni dtes64 monitor ds_cpl
vmx smx est tm2 ssse3 cx16 xtpr pdcm lahf_lm tpr_shadow vnmi
flexpriority
bogomips	: 5319.53
clflush size	: 64
cache_alignment	: 64
address sizes	: 36 bits physical, 48 bits virtual
power management:

processor	: 1
vendor_id	: GenuineIntel
cpu family	: 6
model		: 15
model name	: Intel(R) Core(TM)2 Duo CPU     E6750  @ 2.66GHz
stepping	: 11
cpu MHz		: 2659.765
cache size	: 4096 KB
physical id	: 0
siblings	: 2
core id		: 1
cpu cores	: 2
apicid		: 1
initial apicid	: 1
fdiv_bug	: no
hlt_bug		: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 10
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov
pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe nx lm
constant_tsc arch_perfmon pebs bts aperfmperf pni dtes64 monitor ds_cpl
vmx smx est tm2 ssse3 cx16 xtpr pdcm lahf_lm tpr_shadow vnmi
flexpriority
bogomips	: 5319.58
clflush size	: 64
cache_alignment	: 64
address sizes	: 36 bits physical, 48 bits virtual
power management:
> Can you try putting a printf in 
> 
> ust/libust/buffer.c: get_n_cpus() to see how many CPUs the library
> detects ?
> 
yes,sure, the output says that it detects 2 cpus

> What does your usttrace directory looks like ? (the subdir containing
> the ust and metadata files... with ls -al)
> 
total 24
drwxr-xr-x 2 david david 4096 2010-08-13 15:30 .
drwxr-xr-x 3 david david 4096 2010-08-13 15:30 ..
-rw------- 1 david david 4096 2010-08-13 15:30 metadata_0
-rw------- 1 david david 4096 2010-08-13 15:30 metadata_1
-rw------- 1 david david 4096 2010-08-13 15:30 ust_0
-rw------- 1 david david 4096 2010-08-13 15:30 ust_1

 thanks

--David

> Thanks,
> 
> Mathieu
> 
> > 
> >   thanks
> > 
> > --David
> > 
> > On Wed, 2010-08-11 at 11:39 -0400, Mathieu Desnoyers wrote:
> > > Ah, there was a bug in the test case I received. It was modifying 2
> > > strings shared between threads concurrently.
> > > 
> > > It made me think of a way to handle concurrently modified strings
> > > gracefully within both lttng and ust. I'll work on a patch. I plan to
> > > use strncpy and detect if the string size changed after the strlen
> > > performed for space reservation.
> > > 
> > > Here is the updated test case. It works now.
> > > 
> > > #include <ust/marker.h>
> > > #include <stdio.h>
> > > #include <pthread.h>
> > > 
> > > #define STR_SIZE	30
> > > 
> > > char funcA[STR_SIZE+10];
> > > char extraA[STR_SIZE+10];
> > > 
> > > char funcB[STR_SIZE+10];
> > > char extraB[STR_SIZE+10];
> > > 
> > > void *threadA(void *ptr);
> > > void *threadB(void *ptr);
> > > 
> > > int main() {
> > > 	int i=0;
> > > 
> > > 	pthread_t thread_id[2];
> > > 	srand(1000);
> > > 
> > > 	for (i=0; i < STR_SIZE; ++i) {
> > > 		funcA[i] = (i % (90-65)) + 65;
> > > 		extraA[i] = (i % (90-65)) + 65;
> > > 		funcB[i] = (i % (90-65)) + 65;
> > > 		extraB[i] = (i % (90-65)) + 65;
> > > 	}
> > > 	funcA[STR_SIZE-1] = '\0';
> > > 	extraA[STR_SIZE-1] = '\0';
> > > 	funcB[STR_SIZE-1] = '\0';
> > > 	extraB[STR_SIZE-1] = '\0';
> > > 
> > > 	printf("funcA:  %s\n", funcA);
> > > 	printf("extraA: %s\n", extraA);
> > > 	printf("funcB:  %s\n", funcB);
> > > 	printf("extraB: %s\n", extraB);
> > > 	pthread_create(&thread_id[0], NULL, threadA, (void*)NULL);
> > > 	pthread_create(&thread_id[1], NULL, threadB, (void*)NULL);
> > > 
> > > 	for (i=0; i < 2; ++i) {
> > > 		pthread_detach(thread_id[i]);
> > > 	}
> > > 	sleep(10);
> > > }
> > > 
> > > 
> > > void *threadA(void *ptr) {
> > > 	int i=0,count_prev=0,count=0, index;
> > > 	char save_func, save_extra;
> > > 	for (i=0; i < 500000; ++i) {
> > > //		if (i % 1000)
> > > //			sleep(1);
> > > 		index = rand() % (STR_SIZE-1) + 1;
> > > 		save_func = funcA[index];
> > > 		save_extra = extraA[index];
> > > 		funcA[index] = '\0';
> > > 		extraA[index] = '\0';
> > > 		trace_mark(ust, times_begins, "thread %d func %s depth %d extra %s", 1, funcA, 1, extraA);
> > > //		profile_time_begin("Hello");
> > > 		count += count_prev;
> > > 		count_prev = count;
> > > //		trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 1, func, 1, extra);
> > > //		profile_time_end("Goodbye");
> > > 		funcA[index] = save_func;
> > > 		extraA[index] = save_extra;
> > > 	}
> > > }
> > > 
> > > void *threadB(void *ptr) {
> > > 	int i=0,count_prev=0,count=0, index;
> > > 	char save_func, save_extra;
> > > 	for (i=0; i < 100000; ++i) {
> > > //		if (i % 1000)
> > > //			sleep(1);
> > > 		index = rand() % (STR_SIZE-1) + 1;
> > > 		save_func = funcB[index];
> > > 		save_extra = extraB[index];
> > > 		funcB[index] = '\0';
> > > 		extraB[index] = '\0';
> > > //		profile_time_begin("Hello");
> > > 		trace_mark(ust, times_begins, "thread %d func %s depth %d extra %s", 1, funcB, 1, extraB);
> > > 		count += count_prev;
> > > 		count_prev = count;
> > > //		profile_time_end("Goodbye");
> > > //		trace_mark(ust, time_end, "thread %d func %s depth %d extra %s", 1, func, 1, extra);
> > > 		funcB[index] = save_func;
> > > 		extraB[index] = save_extra;
> > > 	}
> > > }
> > > 
> > > * Mathieu Desnoyers (compudj at krystal.dyndns.org) wrote:
> > > > Hello,
> > > > 
> > > > The test case included in attachement reproduces reliably a problem with
> > > > UST. It generates randomly-sized strings, and I've noticed that the
> > > > string gets corrupted at some point. A README file in included with the
> > > > attachment.
> > > > 
> > > > I also got to a point where ustd segfaults very reliably on my machine.
> > > > I cannot take traces with it anymore.
> > > > 
> > > > Can you guys have a look ?
> > > > 
> > > > Thanks,
> > > > 
> > > > Mathieu
> > > > 
> > > > -- 
> > > > Mathieu Desnoyers
> > > > Operating System Efficiency R&D Consultant
> > > > EfficiOS Inc.
> > > > http://www.efficios.com
> > > 
> > > > Date: Tue, 10 Aug 2010 14:45:22 -0400
> > > > To: Mathieu Desnoyers <compudj at krystal.dyndns.org>
> > > > From: chris meyers <chris.meyers.fsu@gmail.com>
> > > > Subject: Re: [ltt-dev] ltt channel thread safe?
> > > > 
> > > > I made a simple test case that mimics the properties of my program that
> > > > produces the error (ie. multi-threaded and variable length strings mixed
> > > > with constant int's).
> > > > 
> > > > Check out the README in the archive.  Let me know if you have any questions!
> > > > 
> > > > Thanks,
> > > > -Chris
> > > > 
> > > > On Tue, Aug 10, 2010 at 11:46 AM, Mathieu Desnoyers <
> > > > compudj at krystal.dyndns.org> wrote:
> > > > 
> > > > > I think this looks like a data generation problem in UST.
> > > > >
> > > > > Can you send me your test program and a copy of a generated trace that
> > > > > contains the error, along with a full description of the system you
> > > > > gather the trace from and the system on which you run lttv ?
> > > > >
> > > > > It will be easier to debug if I can reproduce the problem myself.
> > > > >
> > > > > Thanks,
> > > > >
> > > > > Mathieu
> > > > >
> > > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > So does it sound like maybe marker_update_fields_offsets() or add_type()
> > > > > is
> > > > > > at fault?
> > > > > >
> > > > > > -Chris
> > > > > >
> > > > > > On Tue, Aug 10, 2010 at 8:47 AM, Mathieu Desnoyers <
> > > > > > compudj at krystal.dyndns.org> wrote:
> > > > > >
> > > > > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > > Ok sorry it's late.  The pasted output in the previous post should be
> > > > > the
> > > > > > > > below.  The debug printed hex data differs from when I print the
> > > > > buffer
> > > > > > > in
> > > > > > > > hex.  This is weird.
> > > > > > >
> > > > > > > I think because the debug and text dump outputs use a different file
> > > > > > > descriptor to output the text, and because there is a one event queue
> > > > > > > that is kept, there is a 1 or 2 events difference between the text dump
> > > > > > > output and the debug output.
> > > > > > >
> > > > > >
> > > > > > Ya, that makes it a bit more confusing :)
> > > > > >
> > > > > > >
> > > > > > > >
> > > > > > > > =========================
> > > > > > > > Info field lengths:
> > > > > > > > offset: 0 | size: 4
> > > > > > > > offset: 4 | size: 0
> > > > > > > > offset: 27 | size: 4
> > > > > > > > offset: 31 | size: 0
> > > > > > > >
> > > > > > > > 01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > > 71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > > > 00 73 65 6C  65 63 74 28  29 20 62 6C  6F 63 6B 20
> > > > > > > > 74 69 6D 65  00
> > > > > > > > =========================
> > > > > > > > -------------------------------------
> > > > > > > > offset: 0 | size: 4
> > > > > > > > 01 00 00 00
> > > > > > > > -------------------------------------
> > > > > > > > -------------------------------------
> > > > > > > > offset: 4 | size: 0
> > > > > > > > 6E 65 5F 73  65 6C 65 63  74 5F 72 65  71 75 65 73
> > > > > > > > 74 5F 74 68  72 65 61 64  00 01 00 00  00 73 65 6C
> > > > > > > > 65 63 74 28  29 20 62 6C  6F 63 6B 20  74 69 6D 65
> > > > > > > > 00
> > > > > > >
> > > > > > > Hrm, it looks like the \0 here also belongs to the next integer.
> > > > > > >
> > > > > > > > -------------------------------------
> > > > > > > > -------------------------------------
> > > > > > > > offset: 27 | size: 4
> > > > > > > > 64 00 01 00
> > > > > > >
> > > > > > > So this is not the value you recorded, right ?
> > > > > > >
> > > > > > Correct, I recorded a 1.
> > > > > >
> > > > > > >
> > > > > > > Mathieu
> > > > > > >
> > > > > > > > -------------------------------------
> > > > > > > > -------------------------------------
> > > > > > > > offset: 31 | size: 0
> > > > > > > > 00 00 73 65  6C 65 63 74  28 29 20 62  6C 6F 63 6B
> > > > > > > > 20 74 69 6D  65 00
> > > > > > > > -------------------------------------
> > > > > > > > ust.time_end: 116791.642023291
> > > > > > > >
> > > > > > >
> > > > > (/home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0),
> > > > > > > > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > > > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > > > > Event header (tracefile
> > > > > > > >
> > > > > > >
> > > > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0
> > > > > > > > offset 3c0c5):
> > > > > > > >    3c0c5    66 FC 55 0C
> > > > > > > > tracefile.c ltt_update_event_size() data_size: 58
> > > > > > > > Event data (tracefile
> > > > > > > >
> > > > > > >
> > > > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0
> > > > > > > > offset 3c0c9):
> > > > > > > >    3c0c9    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > >  ....ne_select_re
> > > > > > > >    3c0d9    71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > > >  quest_thread....
> > > > > > > >    3c0e9    00 6E 65 5F  73 65 6C 65  63 74 5F 72  65 71 75 65
> > > > > > > >  .ne_select_reque
> > > > > > > >    3c0f9    73 74 5F 74  68 72 65 61  64 00
> > > > > > > > st_thread.
> > > > > > > >
> > > > > > > > On Tue, Aug 10, 2010 at 1:31 AM, chris meyers <
> > > > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > > > >
> > > > > > > > > Thanks for the reply Pierre.  I still think my error is coming from
> > > > > > > lttv.
> > > > > > > > >
> > > > > > > > > Below is a trace with some printf's inserted.  In
> > > > > > > lttv_event_to_string() I
> > > > > > > > > iterate over all the 'struct marker_field' entries and output
> > > > > offset,
> > > > > > > into
> > > > > > > > > data, and size.  Then the data that corresponds to that offset is
> > > > > > > printed.
> > > > > > > > >  This can be cross-referenced against the two hex outputs above the
> > > > > > > print
> > > > > > > > > outs (the first hex output is from pre-existing debug code; the
> > > > > second
> > > > > > > hex
> > > > > > > > > output is to verify that the data buffer didn't change).  For some
> > > > > > > reason
> > > > > > > > > the second %lld (depth =) has a wrong offset.  Currently, I am
> > > > > > > investigating
> > > > > > > > > marker_update_fields_offsets() and add_type(), as these seem to be
> > > > > on
> > > > > > > the
> > > > > > > > > only two functions that deal with modifying the marker offset.
> > > > >  Maybe
> > > > > > > the
> > > > > > > > > string before 'depth' is "eating" too many bytes.  Any
> > > > > hints/help/ideas
> > > > > > > > > would be appreciated :)
> > > > > > > > >
> > > > > > > > > Event header (tracefile
> > > > > > > > >
> > > > > > >
> > > > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_1
> > > > > > > > > offset 3f39f):
> > > > > > > > >    3f39f    AB 66 D7 EA  01 00 36 00  AB 66 D7 B2  38 6A 00 00
> > > > > > > > > tracefile.c ltt_update_event_size() data_size: 54
> > > > > > > > > Event data (tracefile
> > > > > > > > >
> > > > > > >
> > > > > /home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_1
> > > > > > > > > offset 3f3af):
> > > > > > > > >    3f3af    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > > >  ....ne_select_re
> > > > > > > > >    3f3bf    70 6C 79 5F  74 68 72 65  61 64 00 01  00 00 00 6E
> > > > > > > > >  ply_thread.....n
> > > > > > > > >    3f3cf    65 5F 73 65  6C 65 63 74  5F 72 65 70  6C 79 5F 74
> > > > > > > > >  e_select_reply_t
> > > > > > > > >    3f3df    68 72 65 61  64 00
> > > > > > >  hread.
> > > > > > > > >
> > > > > > > > > =========================
> > > > > > > > > Info field lengths:
> > > > > > > > > offset: 0 | size: 4
> > > > > > > > > offset: 4 | size: 0
> > > > > > > > > offset: 27 | size: 4
> > > > > > > > > offset: 31 | size: 0
> > > > > > > > >
> > > > > > > > > 01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > > > 71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > > > > 00 73 65 6C  65 63 74 28  29 20 62 6C  6F 63 6B 20
> > > > > > > > > 74 69 6D 65  00
> > > > > > > > > =========================
> > > > > > > > > -------------------------------------
> > > > > > > > > offset: 0 | size: 4
> > > > > > > > > 01 00 00 00
> > > > > > > > > -------------------------------------
> > > > > > > > > -------------------------------------
> > > > > > > > > offset: 4 | size: 0
> > > > > > > > > 6E 65 5F 73  65 6C 65 63  74 5F 72 65  71 75 65 73
> > > > > > > > > 74 5F 74 68  72 65 61 64  00 01 00 00  00 73 65 6C
> > > > > > > > > 65 63 74 28  29 20 62 6C  6F 63 6B 20  74 69 6D 65
> > > > > > > > > 00
> > > > > > > > > -------------------------------------
> > > > > > > > > -------------------------------------
> > > > > > > > > offset: 27 | size: 4
> > > > > > > > > 64 00 01 00
> > > > > > > > > -------------------------------------
> > > > > > > > > -------------------------------------
> > > > > > > > > offset: 31 | size: 0
> > > > > > > > > 00 00 73 65  6C 65 63 74  28 29 20 62  6C 6F 63 6B
> > > > > > > > > 20 74 69 6D  65 00
> > > > > > > > > -------------------------------------
> > > > > > > > > ust.time_end: 116791.642023291
> > > > > > > > >
> > > > > > >
> > > > > (/home/meyers/.usttraces/lappy-20100809110524281530617/24301_5503426455776039818/ust_0),
> > > > > > > > > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > > > > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > > > > >
> > > > > > > > >
> > > > > > > > > On Mon, Aug 9, 2010 at 3:18 PM, Mathieu Desnoyers <
> > > > > > > > > compudj at krystal.dyndns.org> wrote:
> > > > > > > > >
> > > > > > > > >> * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > > >> > debuging turned on.
> > > > > > > > >> > String: is the printf() added to lttv_print_field()
> > > > > > > > >> >
> > > > > > > > >> > Just eyeballing the debugging output from below, the log file
> > > > > seams
> > > > > > > > >> correct.
> > > > > > > > >> >  This further leads me to believe it is the output
> > > > > (lttv/textDump)
> > > > > > > that
> > > > > > > > >> is
> > > > > > > > >> > at fault.  Does the log entry seem correct to you?
> > > > > > > > >> >
> > > > > > > > >> > What I expected to be output:
> > > > > > > > >> > String: ne_select_request_thread
> > > > > > > > >> > String: ne_select_request_thread
> > > > > > > > >> > ust.time_end: 121283.601051208
> > > > > > > > >> >
> > > > > > > > >>
> > > > > > >
> > > > > (/home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0),
> > > > > > > > >> > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > > > >> > "ne_select_request_thread", depth = 65636, extra =
> > > > > > > > >> > "ne_select_request_thread" }
> > > > > > > > >> >
> > > > > > > > >> > ---------------------------------------------------------
> > > > > > > > >> >
> > > > > > > > >> > Actual output:
> > > > > > > > >> >
> > > > > > > > >> > String: ne_select_request_thread
> > > > > > > > >> > String:
> > > > > > > > >> > ust.time_end: 121283.601051208
> > > > > > > > >> >
> > > > > > > > >>
> > > > > > >
> > > > > (/home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0),
> > > > > > > > >> > 0, 0, , , 0, 0x0, MODE_UNKNOWN { thread = 1, func =
> > > > > > > > >> > "ne_select_request_thread", depth = 65636, extra = "" }
> > > > > > > > >> > Event header (tracefile
> > > > > > > > >> >
> > > > > > > > >>
> > > > > > >
> > > > > /home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0
> > > > > > > > >> > offset 4b643):
> > > > > > > > >> >    4b643    A7 41 F5 09
> > > > > > > > >> > Event data (tracefile
> > > > > > > > >> >
> > > > > > > > >>
> > > > > > >
> > > > > /home/meyers/.usttraces/lappy-20100809140046866290643/27438_5503471647422514846/ust_0
> > > > > > > > >> > offset 4b647):
> > > > > > > > >> >    4b647    01 00 00 00  6E 65 5F 73  65 6C 65 63  74 5F 72 65
> > > > > > > > >> >  ....ne_select_re
> > > > > > > > >> >    4b657    71 75 65 73  74 5F 74 68  72 65 61 64  00 01 00 00
> > > > > > > > >>
> > > > > > > > >> Is it me or the "64 00 01 00 00" part at the end above is
> > > > > unexpected ?
> > > > > > > > >>
> > > > > > > > >> We should have "64 00" which would be the end of string followed
> > > > > by
> > > > > > > the
> > > > > > > > >> final \0, and then the "00 01 00 00" which represents the 65536
> > > > > value.
> > > > > > > > >>
> > > > > > > > >> So I expect there might be a problem in UST where it forgets about
> > > > > > > doing
> > > > > > > > >> the +1 to taken into account the end of string \0 somewhere.
> > > > > > > > >>
> > > > > > > > >> Thanks,
> > > > > > > > >>
> > > > > > > > >> Mathieu
> > > > > > > > >>
> > > > > > > > >> >  quest_thread....
> > > > > > > > >> >    4b667    00 6E 65 5F  73 65 6C 65  63 74 5F 72  65 71 75 65
> > > > > > > > >> >  .ne_select_reque
> > > > > > > > >> >    4b677    73 74 5F 74  68 72 65 61  64 00
> > > > > > > > >> > st_thread.
> > > > > > > > >> >
> > > > > > > > >> >
> > > > > > > > >> > On Mon, Aug 9, 2010 at 11:08 AM, chris meyers <
> > > > > > > > >> chris.meyers.fsu at gmail.com>wrote:
> > > > > > > > >> >
> > > > > > > > >> > > Scratch that, the printf does not print out the correct data.
> > > > >  It
> > > > > > > > >> prints
> > > > > > > > >> > > the wrong data.
> > > > > > > > >> > >
> > > > > > > > >> > >
> > > > > > > > >> > > On Mon, Aug 9, 2010 at 11:06 AM, chris meyers <
> > > > > > > > >> chris.meyers.fsu at gmail.com>wrote:
> > > > > > > > >> > >
> > > > > > > > >> > >> The printf outputs the correct data (function names).
> > > > > > > > >> > >>
> > > > > > > > >> > >>
> > > > > > > > >> > >> On Mon, Aug 9, 2010 at 10:22 AM, Mathieu Desnoyers <
> > > > > > > > >> > >> compudj at krystal.dyndns.org> wrote:
> > > > > > > > >> > >>
> > > > > > > > >> > >>> Hrm, can you try adding some printfs in lttv
> > > > > > > > >> > >>>
> > > > > > > > >> > >>> lttv/lttv/print.c
> > > > > > > > >> > >>>
> > > > > > > > >> > >>> ltt_print_field()
> > > > > > > > >> > >>> within LTT_TYPE_STRING case of the switch.
> > > > > > > > >> > >>>
> > > > > > > > >> > >>> Thanks,
> > > > > > > > >> > >>>
> > > > > > > > >> > >>> Mathieu
> > > > > > > > >> > >>>
> > > > > > > > >> > >>> * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > > >> > >>> > func_rand and extra_rand are two varying length "random"
> > > > > > > strings.
> > > > > > > > >>  This
> > > > > > > > >> > >>> > seems to be what causes the "garbling" output.  For some
> > > > > > > reason it
> > > > > > > > >> > >>> affects
> > > > > > > > >> > >>> > the value of depth (a constant set to 1).  I added a
> > > > > printf
> > > > > > > like
> > > > > > > > >> you
> > > > > > > > >> > >>> > mentioned and the correct values are printing out.  It
> > > > > seems
> > > > > > > that
> > > > > > > > >> the
> > > > > > > > >> > >>> > logging is correct.  I have a suspicion that the
> > > > > "textDump"
> > > > > > > module
> > > > > > > > >> in
> > > > > > > > >> > >>> lttv
> > > > > > > > >> > >>> > may be parsing incorrect.
> > > > > > > > >> > >>> >
> > > > > > > > >> > >>> > func_rand = ALLOC_RANDOM(rand() % 1024 + 1);
> > > > > > > > >> > >>> > extra_rand = ALLOC_RANDOM(rand() % 1024 + 1);
> > > > > > > > >> > >>> >
> > > > > > > > >> > >>> > trace_mark(ust, time_end, "thread %d func %s depth %d
> > > > > extra
> > > > > > > %s",
> > > > > > > > >> > >>> thread,
> > > > > > > > >> > >>> > func_rand, depth, extra_rand);
> > > > > > > > >> > >>> >
> > > > > > > > >> > >>> > On Sat, Aug 7, 2010 at 12:58 PM, Mathieu Desnoyers <
> > > > > > > > >> > >>> > compudj at krystal.dyndns.org> wrote:
> > > > > > > > >> > >>> >
> > > > > > > > >> > >>> > > Hrm, it might be caused by the fact that the
> > > > > __FUNCTION__ is
> > > > > > > > >> passed
> > > > > > > > >> > >>> > > through the trace_mark() macro. It could be a macro
> > > > > problem
> > > > > > > with
> > > > > > > > >> the
> > > > > > > > >> > >>> > > precompiler (odd behavior with __FUNCTION__ and
> > > > > defines).
> > > > > > > You
> > > > > > > > >> could
> > > > > > > > >> > >>> try
> > > > > > > > >> > >>> > > just outputting the result in the marker callback (the
> > > > > > > function
> > > > > > > > >> > >>> called
> > > > > > > > >> > >>> > > in marker.c) with printf and see if this is OK or not.
> > > > > > > > >> > >>> > >
> > > > > > > > >> > >>> > > Thanks,
> > > > > > > > >> > >>> > >
> > > > > > > > >> > >>> > > Mathieu
> > > > > > > > >> > >>> > >
> > > > > > > > >> > >>> > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > > >> > >>> > > > I think I jumped the gun in saying that __func__
> > > > > worked.
> > > > > > > > >>  However,
> > > > > > > > >> > >>> I can
> > > > > > > > >> > >>> > > > confidently say that ca constant string, such as the
> > > > > one
> > > > > > > > >> below,
> > > > > > > > >> > >>> does not
> > > > > > > > >> > >>> > > > result in garbled output.  I will try dynamically
> > > > > > > generating
> > > > > > > > >> > >>> different
> > > > > > > > >> > >>> > > > length strings at runtime to log and see if that
> > > > > causes an
> > > > > > > > >> error.
> > > > > > > > >> > >>> > > >
> > > > > > > > >> > >>> > > > So to summarize thus far:
> > > > > > > > >> > >>> > > > __FUNCTION__ and __func__ both result in inconsistent
> > > > > > > output.
> > > > > > > > >> > >>> > > > Constant strings result in consistent output.
> > > > > > > > >> > >>> > > >
> > > > > > > > >> > >>> > > > trace_mark(ust, time_begin, "thread %d func %s depth
> > > > > %d
> > > > > > > extra
> > > > > > > > >> %s",
> > > > > > > > >> > >>> > > thread,
> > > > > > > > >> > >>> > > > "I like pie because it taste good", depth, "yummm i
> > > > > too
> > > > > > > like
> > > > > > > > >> pie
> > > > > > > > >> > >>> for
> > > > > > > > >> > >>> > > > dessert");
> > > > > > > > >> > >>> > > >
> > > > > > > > >> > >>> > > > quantify inconsistent: 260 out of 8197 (31%) log
> > > > > entries
> > > > > > > were
> > > > > > > > >> > >>> corrupt in
> > > > > > > > >> > >>> > > my
> > > > > > > > >> > >>> > > > case.
> > > > > > > > >> > >>> > > >
> > > > > > > > >> > >>> > > > -Chris
> > > > > > > > >> > >>> > > >
> > > > > > > > >> > >>> > > > On Sat, Aug 7, 2010 at 11:28 AM, Mathieu Desnoyers <
> > > > > > > > >> > >>> > > > compudj at krystal.dyndns.org> wrote:
> > > > > > > > >> > >>> > > >
> > > > > > > > >> > >>> > > > > What compiler do you use ? Can you reproduce with
> > > > > > > different
> > > > > > > > >> > >>> compiler
> > > > > > > > >> > >>> > > > > versions?
> > > > > > > > >> > >>> > > > >
> > > > > > > > >> > >>> > > > > Thanks,
> > > > > > > > >> > >>> > > > >
> > > > > > > > >> > >>> > > > > Mathieu
> > > > > > > > >> > >>> > > > >
> > > > > > > > >> > >>> > > > > * chris meyers (chris.meyers.fsu at gmail.com) wrote:
> > > > > > > > >> > >>> > > > > > I don't know the exact reason why but __func__
> > > > > works
> > > > > > > and
> > > > > > > > >> > >>> __FUNCTION__
> > > > > > > > >> > >>> > > > > > doesn't.
> > > > > > > > >> > >>> > > > > >
> > > > > > > > >> > >>> > > > > > -Chris
> > > > > > > > >> > >>> > > > > >
> > > > > > > > >> > >>> > > > > > On Fri, Aug 6, 2010 at 11:47 PM, chris meyers <
> > > > > > > > >> > >>> > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > > > > >> > >>> > > > > >
> > > > > > > > >> > >>> > > > > > > #define LARGE_CONST 127LL
> > > > > > > > >> > >>> > > > > > > #define MY_STR "Hello"
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > > > > trace_mark(ust, time_end, "thread %lld func %s
> > > > > depth
> > > > > > > > >> %lld
> > > > > > > > >> > >>> extra
> > > > > > > > >> > >>> > > %s",
> > > > > > > > >> > >>> > > > > > > LARGE_CONST, MY_STR, LARGE_CONST, __FUNCTION__)
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > > > > Below is a snippet of the macro trace_marker
> > > > > > > expanded.
> > > > > > > > >>  My
> > > > > > > > >> > >>> macor
> > > > > > > > >> > >>> > > > > "MY_STR"
> > > > > > > > >> > >>> > > > > > > is replaced with Hello, while __FUNCTION__ is
> > > > > not
> > > > > > > > >> replaced.
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > > > > The expected output is inconsistent when I DO
> > > > > use
> > > > > > > > >> > >>> __FUNCTION__.
> > > > > > > > >> > >>> > > > > > > The expected output IS consistent when I do NOT
> > > > > use
> > > > > > > > >> > >>> __FUNCTION__.
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > > > > gcc -lust example.c -E
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > > > >  do { struct marker *m; struct registers regs;
> > > > > asm
> > > > > > > > >> volatile (
> > > > > > > > >> > >>> > > ".ifndef
> > > > > > > > >> > >>> > > > > > > __mstrtab_" "ust" "_" "time_end" "_channel_"
> > > > > "39"
> > > > > > > "\n\t"
> > > > > > > > >> > >>> ".section
> > > > > > > > >> > >>> > > > > > > __markers_strings,\"aw\", at progbits\n\t"
> > > > > "__mstrtab_"
> > > > > > > > >> "ust"
> > > > > > > > >> > >>> "_"
> > > > > > > > >> > >>> > > > > "time_end"
> > > > > > > > >> > >>> > > > > > > "_channel_" "39" ":\n\t" ".string \"" "ust"
> > > > > "\"\n\t"
> > > > > > > > >> > >>> "__mstrtab_"
> > > > > > > > >> > >>> > > "ust"
> > > > > > > > >> > >>> > > > > "_"
> > > > > > > > >> > >>> > > > > > > "time_end" "_name_" "39" ":\n\t" ".string \""
> > > > > > > "time_end"
> > > > > > > > >> > >>> "\"\n\t"
> > > > > > > > >> > >>> > > > > > > "__mstrtab_" "ust" "_" "time_end" "_format_"
> > > > > "39"
> > > > > > > > >> ":\n\t"
> > > > > > > > >> > >>> ".string
> > > > > > > > >> > >>> > > "
> > > > > > > > >> > >>> > > > > "\""
> > > > > > > > >> > >>> > > > > > > "thread %lld func %s depth %lld extra %s" "\""
> > > > > > > "\n\t"
> > > > > > > > >> > >>> > > ".previous\n\t"
> > > > > > > > >> > >>> > > > > > > ".endif\n\t" ); asm volatile ( ".section
> > > > > > > > >> > >>> > > > > __markers,\"aw\", at progbits\n\t"
> > > > > > > > >> > >>> > > > > > > ".balign 8\n\t" "2:\n\t" ".quad " "(__mstrtab_"
> > > > > > > "ust"
> > > > > > > > >> "_"
> > > > > > > > >> > >>> > > "time_end"
> > > > > > > > >> > >>> > > > > > > "_channel_" "39" ")\n\t" ".quad " "(__mstrtab_"
> > > > > > > "ust"
> > > > > > > > >> "_"
> > > > > > > > >> > >>> > > "time_end"
> > > > > > > > >> > >>> > > > > > > "_name_" "39" ")\n\t" ".quad " "(__mstrtab_"
> > > > > "ust"
> > > > > > > "_"
> > > > > > > > >> > >>> "time_end"
> > > > > > > > >> > >>> > > > > "_format_"
> > > > > > > > >> > >>> > > > > > > "39" ")\n\t" ".byte 0\n\t" ".byte 0\n\t" ".word
> > > > > > > 0\n\t"
> > > > > > > > >> ".word
> > > > > > > > >> > >>> > > 0\n\t"
> > > > > > > > >> > >>> > > > > > > ".balign " "64" " / 8\n\t" ".quad "
> > > > > > > > >> "(marker_probe_cb)\n\t"
> > > > > > > > >> > >>> ".quad
> > > > > > > > >> > >>> > > "
> > > > > > > > >> > >>> > > > > > > "(__mark_empty_function)\n\t" ".quad " "0\n\t"
> > > > > > > ".quad "
> > > > > > > > >> > >>> "0\n\t"
> > > > > > > > >> > >>> > > ".quad
> > > > > > > > >> > >>> > > > > "
> > > > > > > > >> > >>> > > > > > > "0\n\t" ".quad " "0\n\t" ".quad " "(1f)\n\t"
> > > > > > > > >> ".previous\n\t"
> > > > > > > > >> > >>> > > "1:\n\t"
> > > > > > > > >> > >>> > > > > "lea
> > > > > > > > >> > >>> > > > > > > 2b(%%rip)," "%[outptr]" "\n\t" : [outptr] "=r"
> > > > > (m)
> > > > > > > ); ;
> > > > > > > > >> do {
> > > > > > > > >> > >>> if (0)
> > > > > > > > >> > >>> > > > > > > ___mark_check_format("thread %lld func %s depth
> > > > > %lld
> > > > > > > > >> extra
> > > > > > > > >> > >>> %s",
> > > > > > > > >> > >>> > > 127LL,
> > > > > > > > >> > >>> > > > > > > "First", 127LL, __FUNCTION__); } while (0); if
> > > > > (!0)
> > > > > > > { if
> > > > > > > > >> > >>> > > > > > > (__builtin_expect(!!((m->state__imv)), 0))
> > > > > > > (m->call)(m,
> > > > > > > > >> > >>> ((void
> > > > > > > > >> > >>> > > *)0),
> > > > > > > > >> > >>> > > > > &regs,
> > > > > > > > >> > >>> > > > > > > 127LL, "First", 127LL, __FUNCTION__); } else {
> > > > > if
> > > > > > > > >> > >>> > > > > > > (__builtin_expect(!!((m->state__imv)), 0))
> > > > > > > (m->call)(m,
> > > > > > > > >> > >>> ((void
> > > > > > > > >> > >>> > > *)0),
> > > > > > > > >> > >>> > > > > &regs,
> > > > > > > > >> > >>> > > > > > > 127LL, "First", 127LL, __FUNCTION__); } } while
> > > > > (0);
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > > > > On Fri, Aug 6, 2010 at 5:10 PM, chris meyers <
> > > > > > > > >> > >>> > > > > chris.meyers.fsu at gmail.com>wrote:
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > > > >> I am using the newest, development, version
> > > > > from
> > > > > > > the
> > > > > > > > >> git.  I
> > > > > > > > >> > >>> had
> > > > > > > > >> > >>> > > tried
> > > > > > > > >> > >>> > > > > the
> > > > > > > > >> > >>> > > > > > >> newest stable version with the same results.  I
> > > > > > > believe
> > > > > > > > >> the
> > > > > > > > >> > >>> newest
> > > > > > > > >> > >>> > > git
> > > > > > > > >> > >>> > > > > > >> commit has the patch that you are talking
> > > > > about.
> > > > > > > > >> > >>> > > > > > >>
> > > > > > > > >> > >>> > > > > > >> Thanks,
> > > > > > > > >> > >>> > > > > > >> -Chris
> > > > > > > > >> > >>> > > > > > >>
> > > > > > > > >> > >>> > > > > > >>
> > > > > > > > >> > >>> > > > > > >> On Fri, Aug 6, 2010 at 5:02 PM, Mathieu
> > > > > Desnoyers <
> > > > > > > > >> > >>> > > > > > >> compudj at krystal.dyndns.org> 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 ?
> > > > > > > > >> > >>> > > > > > >>>
> > > > > > > > >> > >>> > > > > > >>> 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
> > > > > > > > >> > >>> > > > > > >>>
> > > > > > > > >> > >>> > > > > > >>
> > > > > > > > >> > >>> > > > > > >>
> > > > > > > > >> > >>> > > > > > >
> > > > > > > > >> > >>> > > > >
> > > > > > > > >> > >>> > > > > --
> > > > > > > > >> > >>> > > > > Mathieu Desnoyers
> > > > > > > > >> > >>> > > > > Operating System Efficiency R&D Consultant
> > > > > > > > >> > >>> > > > > EfficiOS Inc.
> > > > > > > > >> > >>> > > > > http://www.efficios.com
> > > > > > > > >> > >>> > > > >
> > > > > > > > >> > >>> > >
> > > > > > > > >> > >>> > > --
> > > > > > > > >> > >>> > > Mathieu Desnoyers
> > > > > > > > >> > >>> > > Operating System Efficiency R&D Consultant
> > > > > > > > >> > >>> > > EfficiOS Inc.
> > > > > > > > >> > >>> > > http://www.efficios.com
> > > > > > > > >> > >>> > >
> > > > > > > > >> > >>>
> > > > > > > > >> > >>> --
> > > > > > > > >> > >>> Mathieu Desnoyers
> > > > > > > > >> > >>> Operating System Efficiency R&D Consultant
> > > > > > > > >> > >>> EfficiOS Inc.
> > > > > > > > >> > >>> http://www.efficios.com
> > > > > > > > >> > >>>
> > > > > > > > >> > >>
> > > > > > > > >> > >>
> > > > > > > > >> > >
> > > > > > > > >>
> > > > > > > > >> --
> > > > > > > > >> Mathieu Desnoyers
> > > > > > > > >> Operating System Efficiency R&D Consultant
> > > > > > > > >> EfficiOS Inc.
> > > > > > > > >> http://www.efficios.com
> > > > > > > > >>
> > > > > > > > >
> > > > > > > > >
> > > > > > >
> > > > > > > --
> > > > > > > Mathieu Desnoyers
> > > > > > > Operating System Efficiency R&D Consultant
> > > > > > > EfficiOS Inc.
> > > > > > > http://www.efficios.com
> > > > > > >
> > > > >
> > > > > --
> > > > > Mathieu Desnoyers
> > > > > Operating System Efficiency R&D Consultant
> > > > > EfficiOS Inc.
> > > > > http://www.efficios.com
> > > > >
> > > 
> > > 
> > > 
> > > > _______________________________________________
> > > > ltt-dev mailing list
> > > > ltt-dev at lists.casi.polymtl.ca
> > > > http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> > > 
> > > 
> > 
> 

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Mathieu Desnoyers]

* Fu Juntang(David) (juntang.fu at windriver.com) wrote:
> Hi,Mathieu:
>   Please see my answer inline:
> 
> On Thu, 2010-08-12 at 09:40 -0400, Mathieu Desnoyers wrote:
> > * Fu Juntang(David) (juntang.fu at windriver.com) wrote:
> > > Hi,Mathieu:
> > >   I have found another UST bug in this multi-thread functions:
> > >   in my SMP host(2 cpu cores),I have found that UST can only collect one
> > >  thread trace logs running one core(CPU_1),but can not collect the 
> > >  other thread trace logs running another core(CPU_0),is this a known
> > > bug?
> > >   if you need my debug logs, I can attach it to you. 
> > 
[...]
> > Can you try putting a printf in 
> > 
> > ust/libust/buffer.c: get_n_cpus() to see how many CPUs the library
> > detects ?
> > 
> yes,sure, the output says that it detects 2 cpus
> 
> > What does your usttrace directory looks like ? (the subdir containing
> > the ust and metadata files... with ls -al)
> > 
> total 24
> drwxr-xr-x 2 david david 4096 2010-08-13 15:30 .
> drwxr-xr-x 3 david david 4096 2010-08-13 15:30 ..
> -rw------- 1 david david 4096 2010-08-13 15:30 metadata_0
> -rw------- 1 david david 4096 2010-08-13 15:30 metadata_1
> -rw------- 1 david david 4096 2010-08-13 15:30 ust_0
> -rw------- 1 david david 4096 2010-08-13 15:30 ust_1
> 

It all looks fine so far. Note that the Linux scheduler can decide to
schedule your 2 threads on the same CPU. How do you detect that there is
a "problem": is it that events you are writing from a specific thread
are missing or that you expect events on CPU 1 and don't have any ?

The latter case could be normal.

Thanks,

Mathieu

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

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Fu Juntang(David)]

Hi,Mathieu:
  
> It all looks fine so far. Note that the Linux scheduler can decide to
> schedule your 2 threads on the same CPU. How do you detect that there is
> a "problem": is it that events you are writing from a specific thread
> are missing or that you expect events on CPU 1 and don't have any ?
> 
I can monitor which cpu core my threads are running on by the function:
  sched_getcpu()
.
the events are missing in other core.

thanks


On Fri, 2010-08-13 at 08:24 -0400, Mathieu Desnoyers wrote:
> * Fu Juntang(David) (juntang.fu at windriver.com) wrote:
> > Hi,Mathieu:
> >   Please see my answer inline:
> > 
> > On Thu, 2010-08-12 at 09:40 -0400, Mathieu Desnoyers wrote:
> > > * Fu Juntang(David) (juntang.fu at windriver.com) wrote:
> > > > Hi,Mathieu:
> > > >   I have found another UST bug in this multi-thread functions:
> > > >   in my SMP host(2 cpu cores),I have found that UST can only collect one
> > > >  thread trace logs running one core(CPU_1),but can not collect the 
> > > >  other thread trace logs running another core(CPU_0),is this a known
> > > > bug?
> > > >   if you need my debug logs, I can attach it to you. 
> > > 
> [...]
> > > Can you try putting a printf in 
> > > 
> > > ust/libust/buffer.c: get_n_cpus() to see how many CPUs the library
> > > detects ?
> > > 
> > yes,sure, the output says that it detects 2 cpus
> > 
> > > What does your usttrace directory looks like ? (the subdir containing
> > > the ust and metadata files... with ls -al)
> > > 
> > total 24
> > drwxr-xr-x 2 david david 4096 2010-08-13 15:30 .
> > drwxr-xr-x 3 david david 4096 2010-08-13 15:30 ..
> > -rw------- 1 david david 4096 2010-08-13 15:30 metadata_0
> > -rw------- 1 david david 4096 2010-08-13 15:30 metadata_1
> > -rw------- 1 david david 4096 2010-08-13 15:30 ust_0
> > -rw------- 1 david david 4096 2010-08-13 15:30 ust_1
> > 
> 
> It all looks fine so far. Note that the Linux scheduler can decide to
> schedule your 2 threads on the same CPU. How do you detect that there is
> a "problem": is it that events you are writing from a specific thread
> are missing or that you expect events on CPU 1 and don't have any ?
> 
> The latter case could be normal.
> 
> Thanks,
> 
> Mathieu
> 

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Mathieu Desnoyers]

* Fu Juntang(David) (juntang.fu at windriver.com) wrote:
> Hi,Mathieu:
>   has the issue any update?
>   
>   please see my test case and the trace logs(in the attachment), from
>  the trace log,we can see we can only see the trace datas from cpu_0:
>   ust.myevent: 18161.506516049
> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 2 }
> ust.myevent: 18163.506594856
> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 3 }
> ust.myevent: 18165.506667869
> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 5 }
> ust.myevent: 18167.506735881
> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 7 }
> ust.myevent: 18169.506818732
> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 8 }
> ust.myevent: 18171.506903062
> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 10 }
> End trace set
> 
>  we missed the trace logs:
>  trace_mark(ust, myevent, "secondthread %d", number);

Oh, you created two events with same channel and same name, but with a
different first parameter name. This should be forbidden. UST should
take care of checking for these duplicate markers with non-matching
parameters.

libust marker.c is checking for this, as it should:

static int set_marker(struct marker_entry *entry, struct marker *elem,
                int active)
{
        int ret = 0;
        WARN_ON(strcmp(entry->name, elem->name) != 0);

        if (entry->format) {
                if (strcmp(entry->format, elem->format) != 0) {
			DBG("Format mismatch for probe %s (%s), marker (%s)",
                                entry->name,
                                entry->format,
                                elem->format);
                        return -EPERM;
                }
        } else {

Pierre-Marc, why it this only showing the warning if UST_DEBUG is
defined ? This should always spit out the warning.

Thanks,

Mathieu


> 
>   thanks
> 
> --Juntang Fu(David)
> 
> On Fri, 2010-08-13 at 08:24 -0400, Mathieu Desnoyers wrote:
> > * Fu Juntang(David) (juntang.fu at windriver.com) wrote:
> > > Hi,Mathieu:
> > >   Please see my answer inline:
> > > 
> > > On Thu, 2010-08-12 at 09:40 -0400, Mathieu Desnoyers wrote:
> > > > * Fu Juntang(David) (juntang.fu at windriver.com) wrote:
> > > > > Hi,Mathieu:
> > > > >   I have found another UST bug in this multi-thread functions:
> > > > >   in my SMP host(2 cpu cores),I have found that UST can only collect one
> > > > >  thread trace logs running one core(CPU_1),but can not collect the 
> > > > >  other thread trace logs running another core(CPU_0),is this a known
> > > > > bug?
> > > > >   if you need my debug logs, I can attach it to you. 
> > > > 
> > [...]
> > > > Can you try putting a printf in 
> > > > 
> > > > ust/libust/buffer.c: get_n_cpus() to see how many CPUs the library
> > > > detects ?
> > > > 
> > > yes,sure, the output says that it detects 2 cpus
> > > 
> > > > What does your usttrace directory looks like ? (the subdir containing
> > > > the ust and metadata files... with ls -al)
> > > > 
> > > total 24
> > > drwxr-xr-x 2 david david 4096 2010-08-13 15:30 .
> > > drwxr-xr-x 3 david david 4096 2010-08-13 15:30 ..
> > > -rw------- 1 david david 4096 2010-08-13 15:30 metadata_0
> > > -rw------- 1 david david 4096 2010-08-13 15:30 metadata_1
> > > -rw------- 1 david david 4096 2010-08-13 15:30 ust_0
> > > -rw------- 1 david david 4096 2010-08-13 15:30 ust_1
> > > 
> > 
> > It all looks fine so far. Note that the Linux scheduler can decide to
> > schedule your 2 threads on the same CPU. How do you detect that there is
> > a "problem": is it that events you are writing from a specific thread
> > are missing or that you expect events on CPU 1 and don't have any ?
> > 
> > The latter case could be normal.
> > 
> > Thanks,
> > 
> > Mathieu
> > 
> 


> #include<stdio.h>
> #include<pthread.h>
> #include<sys/time.h>
> #include<string.h>
> 
> #include <ust/marker.h>
> 
> #define _GNU_SOURCE
> #include <utmpx.h>
> 
> #define MAX 10
> 
> pthread_t thread[2];
> pthread_mutex_t mut;
> 
> int number=0,i;
> 
> void thread1()
> {
>   int cpu;
> 
>   cpu = sched_getcpu();
>   printf("thread1:I'm thread 1 and cpu is: %d\n", cpu);
>   for(i=0;i<MAX;i++)
>   {
>     pthread_mutex_lock(&mut);
>     number++;
>     trace_mark(ust, myevent, "firstthread %d", number);
>     pthread_mutex_unlock(&mut);
>     //trace_mark(ust, myevent, "firstthread %d", number);
>     sleep(2);
>   }
>   pthread_exit(NULL);
> }
> void *thread2()
> {
>   int cpu ;
> 
>   cpu = sched_getcpu();
>   printf("thread2:I'm thread2 and cpu is:%d\n", cpu);
>   for(i=0;i<MAX;i++)
>   {
>     pthread_mutex_lock(&mut);
>     number++;
>     trace_mark(ust, myevent, "secondthread %d", number);
>     pthread_mutex_unlock(&mut);
>     //trace_mark(ust, myevent, "secondthread %d", number);
>     sleep(3);
>   }
>   pthread_exit(NULL);
> }
> void thread_create(void)
> {
>   int temp;
>   memset(&thread,0,sizeof(thread)); 
>   
>   if((temp=pthread_create(&thread[0],NULL,thread1,NULL))!=0)
>      printf("thread 1 create failed!\n");
>   else
>     if((temp=pthread_create(&thread[1],NULL,thread2,NULL))!=0) 
>       printf("thead 2 created failed!\n");
> }
> void thread_wait(void)
> {
>   if(thread[0]!=0)
>   { 
>     pthread_join(thread[0],NULL);
>   }
>   if(thread[1]!=0)
>   { 
>     pthread_join(thread[1],NULL);
>   }
> }
> int main()
> {
>   pthread_mutex_init(&mut,NULL);
>   thread_create();
>   thread_wait();
>   return 0;
> }
> 


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

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Pierre-Marc Fournier]

On 08/27/2010 01:01 PM, Mathieu Desnoyers wrote:
> * Fu Juntang(David) (juntang.fu at windriver.com) wrote:
>> Hi,Mathieu:
>>    has the issue any update?
>>
>>    please see my test case and the trace logs(in the attachment), from
>>   the trace log,we can see we can only see the trace datas from cpu_0:
>>    ust.myevent: 18161.506516049
>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 2 }
>> ust.myevent: 18163.506594856
>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 3 }
>> ust.myevent: 18165.506667869
>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 5 }
>> ust.myevent: 18167.506735881
>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 7 }
>> ust.myevent: 18169.506818732
>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 8 }
>> ust.myevent: 18171.506903062
>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 10 }
>> End trace set
>>
>>   we missed the trace logs:
>>   trace_mark(ust, myevent, "secondthread %d", number);
>
> Oh, you created two events with same channel and same name, but with a
> different first parameter name. This should be forbidden. UST should
> take care of checking for these duplicate markers with non-matching
> parameters.
>
> libust marker.c is checking for this, as it should:
>
> static int set_marker(struct marker_entry *entry, struct marker *elem,
>                  int active)
> {
>          int ret = 0;
>          WARN_ON(strcmp(entry->name, elem->name) != 0);
>
>          if (entry->format) {
>                  if (strcmp(entry->format, elem->format) != 0) {
> 			DBG("Format mismatch for probe %s (%s), marker (%s)",
>                                  entry->name,
>                                  entry->format,
>                                  elem->format);
>                          return -EPERM;
>                  }
>          } else {
>
> Pierre-Marc, why it this only showing the warning if UST_DEBUG is
> defined ? This should always spit out the warning.
>

Agreed, it should probably be a WARN or ERR.

pmf

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[Mathieu Desnoyers]

* Pierre-Marc Fournier (pierre-marc.fournier at polymtl.ca) wrote:
> On 08/27/2010 01:01 PM, Mathieu Desnoyers wrote:
>> * Fu Juntang(David) (juntang.fu at windriver.com) wrote:
>>> Hi,Mathieu:
>>>    has the issue any update?
>>>
>>>    please see my test case and the trace logs(in the attachment), from
>>>   the trace log,we can see we can only see the trace datas from cpu_0:
>>>    ust.myevent: 18161.506516049
>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 2 }
>>> ust.myevent: 18163.506594856
>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 3 }
>>> ust.myevent: 18165.506667869
>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 5 }
>>> ust.myevent: 18167.506735881
>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 7 }
>>> ust.myevent: 18169.506818732
>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 8 }
>>> ust.myevent: 18171.506903062
>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 10 }
>>> End trace set
>>>
>>>   we missed the trace logs:
>>>   trace_mark(ust, myevent, "secondthread %d", number);
>>
>> Oh, you created two events with same channel and same name, but with a
>> different first parameter name. This should be forbidden. UST should
>> take care of checking for these duplicate markers with non-matching
>> parameters.
>>
>> libust marker.c is checking for this, as it should:
>>
>> static int set_marker(struct marker_entry *entry, struct marker *elem,
>>                  int active)
>> {
>>          int ret = 0;
>>          WARN_ON(strcmp(entry->name, elem->name) != 0);
>>
>>          if (entry->format) {
>>                  if (strcmp(entry->format, elem->format) != 0) {
>> 			DBG("Format mismatch for probe %s (%s), marker (%s)",
>>                                  entry->name,
>>                                  entry->format,
>>                                  elem->format);
>>                          return -EPERM;
>>                  }
>>          } else {
>>
>> Pierre-Marc, why it this only showing the warning if UST_DEBUG is
>> defined ? This should always spit out the warning.
>>
>
> Agreed, it should probably be a WARN or ERR.

Nils/David, do you want to make a patch for this ?

pmf, I guess handing me a commit access might be handy.

Thanks!

Mathieu

>
> pmf
>

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

[ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?]

[David Goulet]

Incoming patch.

Cheers
David

On 10-09-09 12:40 PM, Mathieu Desnoyers wrote:
> * Pierre-Marc Fournier (pierre-marc.fournier at polymtl.ca) wrote:
>> On 08/27/2010 01:01 PM, Mathieu Desnoyers wrote:
>>> * Fu Juntang(David) (juntang.fu at windriver.com) wrote:
>>>> Hi,Mathieu:
>>>>     has the issue any update?
>>>>
>>>>     please see my test case and the trace logs(in the attachment), from
>>>>    the trace log,we can see we can only see the trace datas from cpu_0:
>>>>     ust.myevent: 18161.506516049
>>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 2 }
>>>> ust.myevent: 18163.506594856
>>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 3 }
>>>> ust.myevent: 18165.506667869
>>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 5 }
>>>> ust.myevent: 18167.506735881
>>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 7 }
>>>> ust.myevent: 18169.506818732
>>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 8 }
>>>> ust.myevent: 18171.506903062
>>>> (/home/Large_Space/Part_B/LogStore/LTTngLog_wrlinux-4.0/UST/UST_Logs/multi-thread/david-desktop-20100811163524864824113/11520_5504068123890634635/ust_0), 0, 0, , , 0, 0x0, MODE_UNKNOWN { firstthread = 10 }
>>>> End trace set
>>>>
>>>>    we missed the trace logs:
>>>>    trace_mark(ust, myevent, "secondthread %d", number);
>>>
>>> Oh, you created two events with same channel and same name, but with a
>>> different first parameter name. This should be forbidden. UST should
>>> take care of checking for these duplicate markers with non-matching
>>> parameters.
>>>
>>> libust marker.c is checking for this, as it should:
>>>
>>> static int set_marker(struct marker_entry *entry, struct marker *elem,
>>>                   int active)
>>> {
>>>           int ret = 0;
>>>           WARN_ON(strcmp(entry->name, elem->name) != 0);
>>>
>>>           if (entry->format) {
>>>                   if (strcmp(entry->format, elem->format) != 0) {
>>> 			DBG("Format mismatch for probe %s (%s), marker (%s)",
>>>                                   entry->name,
>>>                                   entry->format,
>>>                                   elem->format);
>>>                           return -EPERM;
>>>                   }
>>>           } else {
>>>
>>> Pierre-Marc, why it this only showing the warning if UST_DEBUG is
>>> defined ? This should always spit out the warning.
>>>
>>
>> Agreed, it should probably be a WARN or ERR.
>
> Nils/David, do you want to make a patch for this ?
>
> pmf, I guess handing me a commit access might be handy.
>
> Thanks!
>
> Mathieu
>
>>
>> pmf
>>
>

-- 
David Goulet
LTTng project, DORSAL Lab.

PGP/GPG : 1024D/16BD8563
BE3C 672B 9331 9796 291A  14C6 4AF7 C14B 16BD 8563