[ltt-dev] Unable to stop trace when started with -a option
Mathieu Desnoyers
compudj at krystal.dyndns.org
Thu Jul 23 15:38:46 EDT 2009
* Mathieu Desnoyers (compudj at krystal.dyndns.org) wrote:
> * Dany Madden (dany.r.madden at gmail.com) wrote:
> [...]
>
Can you have a look at ltt-control 0.69 ? I fixed the O_APPEND issue by
using lseek SEEK_END instead. I did not modify the error handling, so
other splice errors could possibly still cause trace destruction to hang.
Thanks,
Mathieu
> OK, part of the problem is lttd which should not use O_APPEND, because
> it is not supported by splice(). The other part of the problem is that
> lttd seems to exit from the splice error leaving a reference to the
> subbuffers. e.g.
>
> ltt-armall
>
> #First trace
> lttctl -C trace
> lttd -t /tmp/trace -c /mnt/debugfs/ltt/trace -v &
> #works ok
> sleep 5
> lttctl -D trace
>
> #Second trace
> lttctl -C trace
> lttd -t /tmp/trace -c /mnt/debugfs/ltt/trace -v -a
>
> Gives:
>
> Appending to file /tmp/trace/metadata_1 as requested
> Channel file : /mnt/debugfs/ltt/trace/metadata_0
> Opening file.
> Appending to file /tmp/trace/metadata_0 as requested
> Data received
> Normal read on fd 5
> cookie : 0
> splice chan to pipe offset 0
> splice chan to pipe ret 65536
> splice pipe to file -1
> Error in file splice: Invalid argument
> Data received
> Normal read on fd 325
> cookie : 0
> splice chan to pipe offset 0
>
> Which matches:
>
> fs/splice.c:
>
> static long do_splice_from(struct pipe_inode_info *pipe, struct file *out,
> loff_t *ppos, size_t len, unsigned int flags)
> ...
> if (unlikely(out->f_flags & O_APPEND))
> return -EINVAL;
>
> Can you have a closer look at the lttd error handling for splice errors?
> Once we fix this issue to handle it gracefully, we'll have to find
> another way to support file append without O_APPEND.
>
> Thanks,
>
> Mathieu
>
>
> > Dany
> >
> > On Tue, Jul 21, 2009 at 5:07 PM, Mathieu Desnoyers <
> > compudj at krystal.dyndns.org> wrote:
> >
> > > * Dany Madden (dany.r.madden at gmail.com) wrote:
> > > > Hello,
> > > >
> > > > I wanted to follow up on my post from last week. Is this a bug in lttctl
> > > or
> > > > is there something wrong with the way I am calling lttctl? Any
> > > suggestions
> > > > on how to get to the bottom of this issue is much appreciated.
> > > >
> > >
> > > Hrm, this problem still applies to the current LTTng.
> > >
> > > I'd bet splice() has problems with O_APPEND. Can you have a look into
> > > this ? It could be caused by the splice actor implementation found in
> > > LTTng.
> > >
> > > Thanks,
> > >
> > > Mathieu
> > >
> > > > Thanks,
> > > > Dany
> > > >
> > > > On Thu, Jul 16, 2009 at 8:25 AM, Dany Madden <dany.r.madden at gmail.com
> > > >wrote:
> > > >
> > > > > Hi,
> > > > >
> > > > > When I started a trace with the -a option, destroying the trace later
> > > would
> > > > > hang. These are the ltt versions that I am using:
> > > > >
> > > > > lttv: 0.12.7
> > > > > lttng: 0.72 (patched in sles11 2.6.27.19 kernel)
> > > > > lttcontrol: 0.64
> > > > >
> > > > > It appears that lttctl is waiting on lttd to die, but lttd is waiting
> > > for
> > > > > something else to finish. Please see sysrq-t output below.
> > > > >
> > > > > Restart tracing with append option -a
> > > > >
> > > > > ------------------------------------------------------
> > > > >
> > > > > punetest3:~ # lttctl -C -w /tmp/trace1 trace2 -a
> > > > > Linux Trace Toolkit Trace Control 0.64-14012009
> > > > >
> > > > > Controlling trace : trace2
> > > > >
> > > > > lttctl: Creating trace
> > > > >
> > > > > lttctl: Forking lttd
> > > > > Linux Trace Toolkit Trace Daemon 0.64-14012009
> > > > >
> > > > > Reading from debugfs directory : /sys/kernel/debug/ltt/trace2
> > > > > Writing to trace directory : /tmp/trace1
> > > > >
> > > > > lttctl: Starting trace
> > > > > punetest3:~ # echo $?
> > > > >
> > > > > 0
> > > > >
> > > > > Stop tracing hangs
> > > > > ----------------------------------------
> > > > > punetest3:~ # lttctl -D trace1
> > > > > Linux Trace Toolkit Trace Control 0.64-14012009
> > > > >
> > > > > Controlling trace : trace1
> > > > >
> > > > > lttctl: Pausing trace
> > > > >
> > > > > lttctl: Destroying trace
> > > > > ^C
> > > > >
> > > > > ---> Ran it thru gdb
> > > > >
> > > > > Program received signal SIGINT, Interrupt.
> > > > > 0xffffe430 in __kernel_vsyscall ()
> > > > > (gdb) bt
> > > > > #0 0xffffe430 in __kernel_vsyscall ()
> > > > > #1 0xb7f34bb3 in write () from /lib/libc.so.6
> > > > >
> > > > > #2 0xb7fd013c in lttctl_sendop (fname=0xbfffe5cc
> > > > > "/sys/kernel/debug/ltt/destroy_trace", op=0xbffff843 "trace3") at
> > > > > liblttctl.c:120
> > > > > #3 0xb7fd0ecb in lttctl_destroy_trace (name=0xbffff843 "trace3") at
> > > > >
> > > > > liblttctl.c:284
> > > > > #4 0x080498d6 in main (argc=1667330676, argv=0x4c003365) at
> > > lttctl.c:823
> > > > >
> > > > > --> It hangs in lttctl_sendop() while doing write.
> > > > >
> > > > > lttctl_sendop (fname=0xbfffe5bc "/sys/kernel/debug/ltt/destroy_trace",
> > > > >
> > > > > op=0xbffff83c "trace7")
> > > > > at liblttctl.c:108
> > > > > 108 if (!fname) {
> > > > > (gdb)
> > > > > 105 {
> > > > > (gdb)
> > > > > 108 if (!fname) {
> > > > > (gdb)
> > > > > 113 fd = open(fname, O_WRONLY);
> > > > > (gdb)
> > > > >
> > > > > 114 if (fd == -1) {
> > > > > (gdb)
> > > > > 113 fd = open(fname, O_WRONLY);
> > > > > (gdb)
> > > > > 114 if (fd == -1) {
> > > > > (gdb)
> > > > > 120 if (write(fd, op, strlen(op)) == -1) {
> > > > > (gdb) p fd
> > > > > $3 = <value optimized out>
> > > > >
> > > > > (gdb) p op
> > > > > $4 = 0xbffff83c "trace7"
> > > > > (gdb) p strlen(op)
> > > > > $5 = 6
> > > > > (gdb) c
> > > > > Continuing.
> > > > >
> > > > > ----> Output from sysrq-t
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: lttd S 00000000 0 3979
> > > 1
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: f6373e20 00000086 0000000c
> > > 00000000
> > > > > 00000000 00013e36 c05bd67c c05c0380
> > > > > Jul 15 17:47:27 elm3b36 kernel: c05c0380 c05c0380 c05c0380
> > > f785f2c0
> > > > > f785f534 c2225380 00000002 c017f8b0
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: b7e8b000 b7e8bbd8 f6373ea8
> > > f785f534
> > > > > ffffef5d c05521d8 00000001 00000000
> > > > > Jul 15 17:47:27 elm3b36 kernel: Call Trace:
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c0147cd9>] futex_wait+0x207/0x3d0
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c01490e5>] do_futex+0x7a/0x8c9
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c0149a33>] sys_futex+0xff/0x112
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c0104de2>] syscall_call+0x7/0xb
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<ffffe430>] 0xffffe430
> > > > > Jul 15 17:47:27 elm3b36 kernel: =======================
> > > > > Jul 15 17:47:27 elm3b36 kernel: lttd S c1000000 0 3980
> > > 1
> > > > > Jul 15 17:47:27 elm3b36 kernel: f6375dc0 00000086 0007f4a0
> > > c1000000
> > > > >
> > > > > b7ff1c40 00011668 c05bd67c c05c0380
> > > > > Jul 15 17:47:27 elm3b36 kernel: c05c0380 c05c0380 c05c0380
> > > f7bb62b0
> > > > > f7bb6524 c221b380 00000001 00000000
> > > > > Jul 15 17:47:27 elm3b36 kernel: f6f60848 f6354b7c 00000000
> > > f7bb6524
> > > > >
> > > > > 000005b7 00000004 00000004 00000000
> > > > > Jul 15 17:47:27 elm3b36 kernel: Call Trace:
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c01989e3>] pipe_wait+0x50/0x6e
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c01afe80>]
> > > splice_to_pipe+0x164/0x1e9
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c023db08>]
> > > subbuf_splice_actor+0x167/0x172
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c023db40>]
> > > > > ltt_relay_file_splice_read+0x2d/0x6b
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c01af28c>] do_splice_to+0x56/0x64
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c01af419>] sys_splice+0x17f/0x1de
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c0104ceb>]
> > > sysenter_do_call+0x12/0x2f
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<ffffe430>] 0xffffe430
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: =======================
> > > > > Jul 15 17:47:27 elm3b36 kernel: lttctl S 00000086 0 3981
> > > 3869
> > > > > Jul 15 17:47:27 elm3b36 kernel: f6c03d10 00000082 00000001
> > > 00000086
> > > > > f6375c7c 0001f77c c05bd67c c05c0380
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: c05c0380 c05c0380 c05c0380
> > > f74dc3b0
> > > > > f74dc624 c222f380 00000003 f624f790
> > > > > Jul 15 17:47:27 elm3b36 kernel: 00000282 00000003 f624f790
> > > f74dc624
> > > > > 000005b3 c05ce964 f79b4c00 00000000
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: Call Trace:
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c023bbdc>]
> > > __ltt_trace_destroy+0xdc/0xfb
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c023be4d>]
> > > ltt_trace_destroy+0x2d/0x77
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<f89cd070>]
> > > destroy_trace_write+0x70/0x13b
> > > > >
> > > > > [ltt_trace_control]
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c019337c>] vfs_write+0x8b/0x13d
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c0193526>] sys_write+0x45/0x94
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<c0104de2>] syscall_call+0x7/0xb
> > > > >
> > > > > Jul 15 17:47:27 elm3b36 kernel: [<ffffe430>] 0xffffe430
> > > > >
> > > > >
> > > > >
> > > > > --
> > > > > -----
> > > > > ~ 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