From mboxrd@z Thu Jan 1 00:00:00 1970 From: compudj@krystal.dyndns.org (Mathieu Desnoyers) Date: Wed, 11 Aug 2010 11:39:45 -0400 Subject: [ltt-dev] (forw) [chris.meyers.fsu@gmail.com: Re: ltt channel thread safe?] In-Reply-To: <20100810210701.GA22197@Krystal> References: <20100810210701.GA22197@Krystal> Message-ID: <20100811153945.GA2928@Krystal> 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 #include #include #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 > From: chris meyers > 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