Re: missing data in traces

Mathieu Desnoyers <[email protected]> Thu, 20 Dec 2007 10:46:42 -0500
Newsgroups gmane.linux.kernel.tracing
Message-ID <20071220154642.GA28680@Krystal>
* Jan Altenberg ([email protected]) wrote:
> Hi,
> 
> sorry for the late response. I'm kind of busy at the moment.
> 

Ok, I see the problem.. working on a fix.

> > >> Unfortunately, rendering this populated trace data is causing a new
> > >> segfault in the viewer:
> > >>
> > >> Core was generated by `/usr/local/bin/lttv.real -m guievents -m
> > >> guifilter -m guicontrolflow -m resourc'.
> > >> Program terminated with signal 11, Segmentation fault.
> > >> #0  0x0000000000414686 in irq_entry (hook_data=<value optimized out>,
> > >>     call_data=<value optimized out>) at state.c:1981
> > >> 1981      g_array_set_size(irqst->mode_stack, irqst->mode_stack->len + 1);
> > >> (gdb) bt
> > >> #0  0x0000000000414686 in irq_entry (hook_data=<value optimized out>,
> > >>     call_data=<value optimized out>) at state.c:1981
> > >> #1  0x000000000040ca6f in lttv_hooks_call_merge (h1=0xa84460,
> > >>     call_data1=0xa843a0, h2=0xab01d8, call_data2=0xa843a0) at hook.c:333
> > >> #2  0x0000000000418a93 in lttv_process_traceset_middle (self=0x9cb7e0, end=
> > >>       {tv_sec = 999, tv_nsec = 587766197}, nb_events=6000, end_position=0x0)
> > >>     at tracecontext.c:768
> > >> #3  0x00002b9228cb59c6 in execute_events_requests (tab=0x8b48b0)
> > >>     at callbacks.c:1446
> > >> #4  0x00002b9226e40fca in g_main_context_dispatch ()
> > >>    from /opt/gnome/lib64/libglib-2.0.so.0
> > >> #5  0x00002b9226e44055 in g_str_equal () from
> > >> /opt/gnome/lib64/libglib-2.0.so.0
> > >> #6  0x00002b9226e44365 in g_main_loop_run ()
> > >>    from /opt/gnome/lib64/libglib-2.0.so.0
> > >> #7  0x00002b9227685563 in gtk_main () from
> > >> /opt/gnome/lib64/libgtk-x11-2.0.so.0
> > >> #8  0x00002b9228cb2096 in window_creation_hook (
> > >>     hook_data=<value optimized out>, call_data=<value optimized out>)
> > >>     at init_module.c:129
> > >> #9  0x000000000040cb0a in lttv_hooks_call (h=0x531158, call_data=0x0)
> > >>     at hook.c:272
> > >> #10 0x000000000040b09d in main (argc=13, argv=0x7fff840bc168) at main.c:219
> > >>
> > >> This one isnt as obvious to me as the last one, so I have no patch to
> > >> offer.  Any advice is appreciated!
> > >>     
> > >
> > > Hmmmm, I think I ran into that a few days ago on one of my machines.
> > > What happened on my machine was:
> > >
> > > irq_entry()
> > > {
> > > ...
> > >
> > > /* update irq status */
> > >   s->cpu_state->last_irq = irq;
> > >   irq_push_mode(&ts->irq_states[irq], LTTV_IRQ_BUSY);
> > > }
> > >
> > > irq_entry calls irq_push_mode for the current irq number:
> > >
> > > static void irq_push_mode(LttvIRQState *irqst, LttvIRQMode state)
> > > {
> > >   g_array_set_size(irqst->mode_stack, irqst->mode_stack->len + 1);
> > > -> That's the call, which causes LTTV to segfault.
> > >
> > > irq_states is a garray, which gets created by:
> > > nb_irq = tcs->nb_irqs
> > > ...
> > > tcs->irq_states = g_new(LttvIRQState, nb_irq);
> > > ...
> > >
> > > nb_irqs gets initialized in create_name_tables:
> > > name_tables->nb_irqs = 256;
> > >
> > > Now lets have a look at the interrupt table of my testbox:
> > >            CPU0       CPU1       
> > >   0:         44          0   IO-APIC-edge      timer
> > >   1:          0       1726   IO-APIC-edge      i8042
> > >   7:          0          0   IO-APIC-edge      parport0
> > >   9:          0          0   IO-APIC-fasteoi   acpi
> > >  12:          6      11139   IO-APIC-edge      i8042
> > >  14:          0         37   IO-APIC-edge      ide0
> > >  18:          0          3   IO-APIC-fasteoi   ohci1394
> > >  21:          0          0   IO-APIC-fasteoi   sata_nv
> > >  22:         67      69032   IO-APIC-fasteoi   sata_nv, HDA Intel
> > >  23:          0          0   IO-APIC-fasteoi   ohci_hcd:usb1
> > > 1279:        132     150698   PCI-MSI-edge      eth0
> > >
> > > eth0 has an interrupt number > 255!
> > >
> > > So, irq_entry will call
> > > irq_push_mode(&ts->irq_states[1279], LTTV_IRQ_BUSY);
> > > which causes a segfault.
> > >
> > >   
> > I think you may be on to something.  My system has an eth0 at 4342!
> 
> CCed Mathieu.
> 
> Just to make sure, your facing the same issue: Could you try, what
> happens with attached patch?
> 
> ---
>  lttv/lttv/state.c |    6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)
> 
> Index: lttv-0.10.0-pre5-05122007/lttv/lttv/state.c
> ===================================================================
> --- lttv-0.10.0-pre5-05122007.orig/lttv/lttv/state.c
> +++ lttv-0.10.0-pre5-05122007/lttv/lttv/state.c
> @@ -1829,9 +1829,9 @@ create_name_tables(LttvTraceState *tcs) 
>      }
>      */
>  
> -    name_tables->nb_irqs = 256;
> -    name_tables->irq_names = g_new(GQuark, 256);
> -    for(i = 0 ; i < 256 ; i++) {
> +    name_tables->nb_irqs = 5000;
> +    name_tables->irq_names = g_new(GQuark, 5000);
> +    for(i = 0 ; i < 5000 ; i++) {
>        g_string_printf(fe_name, "irq %d", i);
>        name_tables->irq_names[i] = g_quark_from_string(fe_name->str);
>      }
> 
> 
> _______________________________________________
> Ltt-dev mailing list
> [email protected]
> http://listserv.shafik.org/mailman/listinfo/ltt-dev
> 

-- 
Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68