[ltt-dev] issues with lttv 0.12.7

Mathieu Desnoyers compudj at krystal.dyndns.org
Wed Jul 1 17:12:00 EDT 2009


* Mathieu Desnoyers (compudj at krystal.dyndns.org) wrote:
> * Dany Madden (dany.r.madden at gmail.com) wrote:
> > Hi Mathieu,
> > 
> > As you suggested, I've tested <lttv --memory -m textDump -t /tmp/trace1>
> > command with glib 2.21.2 and lttv-0.12.16-19062009. I still see the same
> > segfault and bt. Any more suggestions? :)
> > 
> 
> ./configure CFLAGS=-g && make && make install
> 
> gdb lttv.real
> (gdb) set args --debug -v --fatal --memory -m textDump -t /tmp/trace
> ...
> bt full
> 
> should provide useful output.. but it looks like there is something
> wrong with the glib memory profiler due to our extensive use of the
> gquarks. Maybe we overflow one of its tables...
> 
> One thing to try would be to allocate the strings ourself elsewhere and
> use g_quark_from_static_string. It seems particularly important in
> ltt/marker.c, where we generate a quark for each channel, event and
> field name. refs :
> 
> http://library.gnome.org/devel/glib/unstable/glib-Memory-Allocation.html
> http://library.gnome.org/devel/glib/unstable/glib-Quarks.html
> 

OK, what we get is :

(process:12835): GLib-WARNING **: realloc(0x631710, 8192): memory has
been freed 7566456 times already

If I run it with --fatal, I see that a g_quark_from_string is causing
this warning. It looks like the GQuarks are therefore reallocating their
string table quite often.

Now removing --fatal lets the execution continue until we get :


GLib Memory statistics (successful operations):
 blocks of | allocated  | freed      | allocated  | freed      | n_bytes   
  n_bytes  | n_times by | n_times by | n_times by | n_times by | remaining 
           | malloc()   | free()     | realloc()  | realloc()  |           
===========|============|============|============|============|===========
         1 |         11 |          2 |          0 |          0 |         +9
...
      4088 |          0 |          0 |          1 |          0 |      +4088
   >  4096 |          1 |          0 |         44 |          0 |        ***
GLib Memory statistics (failing operations):
 blocks of | allocated  | freed      | allocated  | freed      | n_bytes   
  n_bytes  | n_times by | n_times by | n_times by | n_times by | remaining 
           | malloc()   | free()     | realloc()  | realloc()  |           
===========|============|============|============|============|===========
   >  4096 |          0 |          0 |          1 |          0 |        ***
Total bytes: allocated=969592, zero-initialized=20380 (2.10%), freed=640269 (66.03%), remaining=329323

GLib-ERROR **: /tmp/buildd/glib2.0-2.16.3/glib/gmem.c:175: failed to allocate 8192 bytes
aborting...

So it looks like the allocator profiler refuses to allocate a 8kB memory
region. Looking at the table above, I notice that it stops at 4k...
something really looks fishy in the glib profiler... ;)

I would bet it does not handle 8kB allocations correctly or something
like that. It definitely seems to be related to the heavy usage of
GQuarks LTTV does. I would recommend creating a small program which
allocates tons of different GQuarks and to try it with the glib memory
profiler to see how badly it breaks.

Mathieu


> Thanks,
> 
> Mathieu
> 
> 
> > Dany
> > 
> > On Mon, Jun 29, 2009 at 8:20 AM, Mathieu Desnoyers <
> > compudj at krystal.dyndns.org> wrote:
> > 
> > > * Dany Madden (dany.r.madden at gmail.com) wrote:
> > > ...
> > >
> > 
> > >
> > > ISSUE3: lttv --memory causes segmentation fault. This is the gdb
> > backtrace:
> > > (gdb) run --memory -m textDump -t /tmp/trace1
> > > Starting program: /usr/bin/lttv.real --memory -m textDump -t /tmp/trace1
> > > [Thread debugging using libthread_db enabled]
> > > ** Message: Memory summary before main
> > > GLib Memory statistics (successful operations):
> > >  blocks of | allocated  | freed      | allocated  | freed      | n_bytes
> > >   n_bytes  | n_times by | n_times by | n_times by | n_times by | remaining
> > >            | malloc()   | free()     | realloc()  | realloc()  |
> > >
> > ===========|============|============|============|============|===========
> > >          4 |          0 |          0 |          1 |          1 |
> > +0
> > >         12 |          1 |          0 |          0 |          0 |
> >  +12
> > >         15 |          2 |          0 |          0 |          0 |
> >  +30
> > >         16 |          0 |          0 |          2 |          1 |
> >  +16
> > >         27 |          2 |          2 |          0 |          0 |
> > +0
> > >         32 |          0 |          1 |          1 |          0 |
> > +0
> > >         36 |          1 |          0 |          0 |          0 |
> >  +36
> > >         64 |          0 |          1 |          1 |          0 |
> > +0
> > > GLib Memory statistics (failing operations):
> > >  --- none ---
> > > Total bytes: allocated=264, zero-initialized=48 (18.18%), freed=170
> > > (64.39%), remaining=94
> > >
> > > Program received signal SIGSEGV, Segmentation fault.
> > > 0xb7daed7b in realloc () from /lib/libc.so.6
> > > (gdb) bt
> > > #0  0xb7daed7b in realloc () from /lib/libc.so.6
> > > #1  0xb7ef5bb3 in profiler_try_realloc (mem=0x806d018, n_bytes=4096) at
> > > gmem.c:559
> > > #2  0xb7ef6779 in profiler_realloc (mem=0x806d018, n_bytes=4096) at
> > > gmem.c:581
> > > #3  0xb7ef604a in IA__g_realloc (mem=0x806d018, n_bytes=4096) at
> > gmem.c:170
> > > #4  0xb7ed7b89 in IA__g_quark_from_string (string=0x80bcde8 "syscall 115")
> > > at gdataset.c:683
> > > #5  0x0805db85 in init (self=0x80b0200, ts=0x8078f28) at state.c:1915
> > > #6  0x08060d0f in init (self=0x80b0200, ts=0x8078f28) at stats.c:200
> > > #7  0xb7cda173 in process_traceset (hook_data=0x0, call_data=0x0) at
> > > batchAnalysis.c:83
> > > #8  0x08054346 in lttv_hooks_call (h=0x806f478, call_data=0x0) at
> > hook.c:272
> > > #9  0x08052a8d in main (argc=6, argv=0xbffff684) at main.c:219
> > >
> > 
> > Hrm, maybe a problem at the glib level ? You should try :
> > > - with a newer lttv version
> > > - with an updated glib
> > >
> > > to see if the problem persists.
> > 
> > 
> > I am still seeing the same bt with lttv-0.12.16-19062009 and glib 2.21.2
> > ...
> > 
> > 
> > > >
> > > > ---> These modules are built into the kernel:
> > > > ltt-marker-control
> > > > ltt-tracer
> > > > ltt-serialize
> > > > ltt-relay
> > > >
> > > > ---> These are the modules that I loaded:
> > > > xracer5:~ # lsmod | grep ltt
> > > > ltt_type_serializer     2332  4 trap_trace,syscall_trace,mm_
> > > > trace,kernel_trace
> > > > ltt_trace_control       8400  0
> > > > ltt_statedump           8104  0
> > > > xracer5:~ # lsmod | grep trace
> > > > ltt_type_serializer     2332  4
> > > > trap_trace,syscall_trace,mm_trace,kernel_trace
> > > > ipc_trace               2048  4
> > > > kernel_trace           11112  31
> > > > ltt_trace_control       8400  0
> > > > mm_trace                4832  12
> > > > fs_trace                5176  16
> > > > syscall_trace           1584  2
> > > > trap_trace              1560  2
> > > >
> > > > ---> I ran ltt-armall
> > > > xracer5:/dany # ltt-armall
> > > > Connecting all markers
> > > > Connecting fd_state file_descriptor
> > > > Connecting fs buffer_wait_end
> > > > Connecting fs buffer_wait_start
> > > > Connecting fs close
> > > > Connecting fs exec
> > > > Connecting fs ioctl
> > > > Connecting fs llseek
> > > > Connecting fs lseek
> > > > Connecting fs open
> > > > Connecting fs pollfd
> > > > Connecting fs pread64
> > > > Connecting fs pwrite64
> > > > Connecting fs read
> > > > Connecting fs readv
> > > > Connecting fs select
> > > > Connecting fs write
> > > > Connecting fs writev
> > > > Connecting global_state statedump_end
> > > > Connecting input input_event
> > > > Connecting ipc call
> > > > Connecting ipc msg_create
> > > > Connecting ipc sem_create
> > > > Connecting ipc shm_create
> > > > Connecting irq_state idt_table
> > > > Connecting irq_state interrupt
> > > > Connecting kernel irq_entry
> > > > Connecting kernel irq_exit
> > > > Connecting kernel kthread_create
> > > > Connecting kernel kthread_stop
> > > > Connecting kernel kthread_stop_ret
> > > > Connecting kernel module_free
> > > > Connecting kernel module_load
> > > > Connecting kernel printk
> > > > Connecting kernel process_exit
> > > > Connecting kernel process_fork
> > > > Connecting kernel process_free
> > > > Connecting kernel process_wait
> > > > Connecting kernel sched_migrate_task
> > > > Connecting kernel sched_schedule
> > > > Connecting kernel sched_try_wakeup
> > > > Connecting kernel sched_wait_task
> > > > Connecting kernel sched_wakeup_new_task
> > > > Connecting kernel send_signal
> > > > Connecting kernel softirq_entry
> > > > Connecting kernel softirq_exit
> > > > Connecting kernel softirq_raise
> > > > Connecting kernel syscall_entry
> > > > Connecting kernel syscall_exit
> > > > Connecting kernel tasklet_high_entry
> > > > Connecting kernel tasklet_high_exit
> > > > Connecting kernel tasklet_low_entry
> > > > Connecting kernel tasklet_low_exit
> > > > Connecting kernel timer_itimer_expired
> > > > Connecting kernel timer_itimer_set
> > > > Connecting kernel timer_set
> > > > Connecting kernel timer_timeout
> > > > Connecting kernel timer_update_time
> > > > Connecting kernel trap_entry
> > > > Connecting kernel trap_exit
> > > > Connecting kernel vprintk
> > > > Connecting mm handle_fault_entry
> > > > Connecting mm handle_fault_exit
> > > > Connecting mm huge_page_alloc
> > > > Connecting mm huge_page_free
> > > > Connecting mm page_alloc
> > > > Connecting mm page_free
> > > > Connecting mm swap_file_close
> > > > Connecting mm swap_file_open
> > > > Connecting mm swap_in
> > > > Connecting mm swap_out
> > > > Connecting mm wait_on_page_end
> > > > Connecting mm wait_on_page_start
> > > > Connecting module_state list_module
> > > > Connecting netif_state network_ip_interface
> > > > Connecting netif_state network_ipv4_interface
> > > > Connecting softirq_state softirq_vec
> > > > Connecting swap_state statedump_swap_files
> > > > Connecting syscall_state sys_call_table
> > > > Connecting task_state process_state
> > > > Connecting vm_state vm_map
> > > > Connecting high-rate markers to tap
> > > >
> > > > ---> compiled and ran this ltttest program
> > > > #include <stdio.h>
> > > > void write_to_console(int id)
> > > > {
> > > >      printf("%d:Hello\n", id);
> > > >      sleep(1); /* Force the process to give up the CPU */
> > > >      printf(" %d:World!\n", id);
> > > > }
> > > >
> > > > int main(void)
> > > > {
> > > >         printf("parent pid:%d\n", getpid());
> > > >         if(!fork())
> > > >                 write_to_console(1);
> > > >         else
> > > >                 if(!fork())
> > > >                          write_to_console(2);
> > > >
> > > >        sleep(5);
> > > >         return 0;
> > > > }
> > > >
> > > > ---> lttctl -C -w /tmp/trace1 trace1
> > > > ---> ./ltttest
> > > > ---> lttctl -D trace1
> > > > ---> lttv -m textDump -e state.pid=3933 -e event.name=fork -t
> > > > /tmp/trace1
> > > >
> > > >
> > > > ** (process:3938): WARNING **: No channel for marker named
> > > > userspace.thread_brand found
> > > >
> > > > ** (process:3938): WARNING **: No channel for marker named
> > > > block._blk_request_issue found
> > > >
> > > > ** (process:3938): WARNING **: No channel for marker named
> > > > block._blk_request_complete found
> > > >
> > > > ** (process:3938): WARNING **: No channel for marker named
> > > > userspace.function_entry found
> > > >
> > > > ** (process:3938): WARNING **: No channel for marker named
> > > > userspace.function_exit found
> > > > Trace set contains 1 traces
> > > >
> > > > ....
> > > >
> > > > ---> lttv --memory -m textDump -e
> > > > event.name=page_alloc -t /tmp/trace1/
> > > > ** Message: Memory summary before main
> > > > GLib Memory statistics (successful operations):
> > > >  blocks of | allocated  | freed      | allocated  | freed      | n_bytes
> > > >   n_bytes  | n_times by | n_times by | n_times by | n_times by |
> > > remaining
> > > >            | malloc()   | free()     | realloc()  | realloc()  |
> > > >
> > > ===========|============|============|============|============|===========
> > > >          4 |          0 |          0 |          1 |          1 |
> > > +0
> > > >         12 |          1 |          0 |          0 |          0 |
> > >  +12
> > > >         15 |          2 |          0 |          0 |          0 |
> > >  +30
> > > >         16 |          0 |          0 |          2 |          1 |
> > >  +16
> > > >         27 |          2 |          2 |          0 |          0 |
> > > +0
> > > >         32 |          0 |          1 |          1 |          0 |
> > > +0
> > > >         36 |          1 |          0 |          0 |          0 |
> > >  +36
> > > >         64 |          0 |          1 |          1 |          0 |
> > > +0
> > > > GLib Memory statistics (failing operations):
> > > >  --- none ---
> > > > Total bytes: allocated=264, zero-initialized=48 (18.18%), freed=170
> > > > (64.39%),
> > > > remaining=94
> > > > /usr/bin/lttv: line 15:  6494 Segmentation fault      $0.real $*
> > > >
> > > > xracer5:~ # echo $?
> > > > 139
> > > >
> > > >
> > > > ---> lttv -m textDump -t
> > > > /tmp/trace1/ --fatal
> > > >
> > > > ** WARNING **: No channel for marker named userspace.thread_brand found
> > > > aborting...
> > > > /usr/bin/lttv: line 15:  6463 Aborted                 $0.real $*
> > > >
> > > > xracer5:~# echo $?
> > > > 134
> > > >
> > > >
> > > > -----
> > > > ~ Dany Madden
> > > >
> > > >
> > > >
> > > > --
> > > > -----
> > > > ~ Dany Madden
> > >
> > > > _______________________________________________
> > > > ltt-dev mailing list
> > > > ltt-dev at lists.casi.polymtl.ca
> > > > http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> > >
> > >
> > > --
> > > Mathieu Desnoyers
> > > OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68
> > >
> > 
> > 
> > 
> > -- 
> > -----
> > ~ Dany Madden
> 
> -- 
> Mathieu Desnoyers
> OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68
> 
> _______________________________________________
> ltt-dev mailing list
> ltt-dev at lists.casi.polymtl.ca
> http://lists.casi.polymtl.ca/cgi-bin/mailman/listinfo/ltt-dev
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68




More information about the lttng-dev mailing list