[ltt-dev] (forw) [chris.meyers.fsu at gmail.com: Re: ltt channel thread safe?]
Mathieu Desnoyers
compudj at krystal.dyndns.org
Thu Aug 12 09:40:28 EDT 2010
* 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 at 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),
> > > > > > > >> > >>> > > > > ®s,
> > > > > > > >> > >>> > > > > > > 127LL, "First", 127LL, __FUNCTION__); } else {
> > > > if
> > > > > > > >> > >>> > > > > > > (__builtin_expect(!!((m->state__imv)), 0))
> > > > > > (m->call)(m,
> > > > > > > >> > >>> ((void
> > > > > > > >> > >>> > > *)0),
> > > > > > > >> > >>> > > > > ®s,
> > > > > > > >> > >>> > > > > > > 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
More information about the lttng-dev
mailing list