[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