[ltt-dev] Unable to stop trace when started with -a option

[Dany Madden]

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.casi.polymtl.ca/pipermail/lttng-dev/attachments/20090716/22f784a7/attachment-0003.htm>