Re: missing data in traces

Jan Altenberg <[email protected]> Wed, 19 Dec 2007 09:05:54 +0100
Newsgroups gmane.linux.kernel.tracing
Message-ID <[email protected]>
Hi,

> 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.

Cheers,
	Jan