Re: splice/tee bugs?

Jens,

Thanks. I applied your patch against 2.6.17(.0), and did some
testing using my modified version of your test program, using
the same command line: ls *.c | ktee r | wc, and also running
several instances of the program in parallel using the
command line:

find . | ktee r | wc

which in my test directory produces this output:

tee returned 65536
splice returned 65536
tee returned 65536
splice returned 65536
tee returned 53248
splice returned 53248
tee returned 57344
splice returned 57344
tee returned 7245
splice returned 7245
tee returned 0
6212 6213 248909

Things look good so far: runs produce the results I expect, and
no OOPSes (which Luiz Fernando reported when running multiple
instances in parallel, but I didn't see myself because I didn't
try doing that with vanilla 2.6.17) and no command-line hangs.

So far, so good.

The most notable differences between my program and yours
are:

* I print some debugging info to stderr.

* I don't pass SPLICE_F_NONBLOCK to tee().
[...]
On different runs I see:

a) No output from ls through the pipeline:

tee returned 0
0 0 0

I am no longer seeing results like this. So am I correct in
understanding that tee() should only return 0 on EOF?

tee() can still return 0 without SPLICE_F_NONBLOCK being set, if the
pipes are changed in between the _prep calls and link_pipe(). There's
really nothing we can do about that. There's no EOF condition for
link_pipe(), as it purely operates on pipes. A 0 return means that we
had no data to splice and could not wait for data, either because it
would be a locking violation or because it simply doesn't make sense to
wait (eg no writers attached to the pipe). It will only return EAGAIN
for a non-blocking tee() now though.

Okay.

[...]

c) Occasionally the command line just hangs, producing no output.
In this case I can't kill it with ^C or ^\. This is a
hard-to-reproduce behaviour on my (x86) system, but I have
seen it several times by now.

I no longer see this behaviour (at least so far, after quite a
bit of testing).

Good, it should be fixed with the blocking removal from link_pipe().

One slight strangeness. Most of the time, the
"find . | ktee r | wc" command line takes about 0.1 seconds to
execute, but about 1 time in 5 on my x86 system, it takes about
1.5 to 2 seconds to execute. Any ideas about what's happening
there?

That is pretty odd. Any chance you can do a quick sysrq-t and see where
find/ktee/wc is stuck when this happens? You should not be seeing that,
naturally, I'll see if I can reproduce that here. How much data does
find . return in your example?

See the start of this message.

One sysrq-t output output below.

Cheers,

Michael


find D B9099C00 0 14170 4167 14171 (NOTLB)
ca279d04 00118054 00000008 b9099c00 003d0ca2 e7b0b9f8 00000009 d307f688
d307f580 c0459dc0 c1507620 b9099c00 003d0ca2 00000000 00000000 00118054
00000001 00001000 c015010e e647f5ac e647f5b8 00000046 00000000 00000000
Call Trace:
<c015010e> __getblk+0x1d/0x225
<c03e1e7c> io_schedule+0x26/0x30
<c0150874> sync_buffer+0x37/0x3a
<c03e25fd> __wait_on_bit+0x33/0x59
<c015083d> sync_buffer+0x0/0x3a
<c03e2695> out_of_line_wait_on_bit+0x72/0x7a
<c015083d> sync_buffer+0x0/0x3a
<c0127dd5> wake_bit_function+0x0/0x34
<c019e39b> search_by_key+0x133/0xd91
<c0110a1c> do_page_fault+0x0/0x532
<c0189e2d> search_by_entry_key+0x20/0x22f
<c015dc76> filldir64+0x8e/0xc3
<c019e214> pathrelse+0x1b/0x2f
<c019388c> reiserfs_readdir+0x3e3/0x3fb
<c0193895> reiserfs_readdir+0x3ec/0x3fb
<c018d6e5> reiserfs_update_sd_size+0x67/0x24c
<c01a55c9> journal_begin+0x9c/0xdc
<c0196cb0> reiserfs_dirty_inode+0x5a/0x76
<c016bacc> __mark_inode_dirty+0x2d/0x15e
<c015dd9a> vfs_readdir+0x58/0x6f
<c015de14> sys_getdents64+0x63/0xa8
<c015dbe8> filldir64+0x0/0xc3
<c010287f> syscall_call+0x7/0xb
ktee S FCFCA100 0 14171 4167 14172 14170 (NOTLB)
ccad7f40 d4a13668 d4a13668 fcfca100 003d0ca2 e75553a0 00000009 d0fd8648
d0fd8540 e7a9c030 c1507620 fcfca100 003d0ca2 00000000 00000000 cde230cc
e75552dc 00000000 00000202 ccad7f68 00000000 e4930a00 00000000 ccad7f68
Call Trace:
<c0158a0d> pipe_wait+0x6b/0x8c
<c0132e9d> audit_syscall_entry+0x104/0x12b
<c0127d9b> autoremove_wake_function+0x0/0x3a
<c017026b> sys_tee+0x149/0x3af
<c010287f> syscall_call+0x7/0xb
wc S B8CC9300 0 14172 4167 14171 (NOTLB)
d012dec0 e70be2ac e70be304 b8cc9300 003d0ca2 0000011b 00000009 d07d6178
d07d6070 d4bbea50 c1507620 b8cc9300 003d0ca2 00000000 00000000 c045f800
00000000 00000246 00000202 d012dee8 00000000 d1f5ca00 bfa2a386 d012dee8
Call Trace:
<c0158a0d> pipe_wait+0x6b/0x8c
<c0127d9b> autoremove_wake_function+0x0/0x3a
<c01590fb> pipe_readv+0x2c9/0x339
<c013f60a> __handle_mm_fault+0x27c/0x73c
<c013f771> __handle_mm_fault+0x3e3/0x73c
<c0159191> pipe_read+0x26/0x2a
<c014ea2b> vfs_read+0x87/0x11b
<c014ee76> sys_read+0x3b/0x64
<c010287f> syscall_call+0x7/0xb



--
Michael Kerrisk
maintainer of Linux man pages Sections 2, 3, 4, 5, and 7

Want to help with man page maintenance?
Grab the latest tarball at
ftp://ftp.win.tue.nl/pub/linux-local/manpages/,
read the HOWTOHELP file and grep the source
files for 'FIXME'.
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Relevant Pages

  • Re: Terminal services commandline utilities denied from programmatic access?
    ... appears that it tries to execute a wow64 qwinsta.exe on a 64 bit windows. ... and then receive the text response in a pipe. ... I have verified that 'qwinsta' is installed, and the above command works properly when manually typed from an "Administrator:" command prompt. ... the routine in my library fails to access 'qwinsta' when executed from within a test program - I receive the following output: ...
    (microsoft.public.windows.terminal_services)
  • Interesting experience with execution traces
    ... surprised about the behaviour of the enterstep / leavestep commands. ... Invoke command for every tcl command which is executed inside the ... just before the actual execution takes place ... ... trace add execution sum ...
    (comp.lang.tcl)
  • Re: Disable trace and track verbs
    ... I understand what u are saying, but URLscan will not ... intercept that command yet as IIS will still respond to ... an OPTIONS and TRACE command even with it disabled. ...
    (microsoft.public.inetserver.iis.security)
  • Re: Tcl the misunderstood
    ... an article I wrote in order to promote Tcl, ... Anyway, I definitely lacked "trace" examples, maybe even combined with Tk ... entry widgets. ... understanding the power of the 'after' command. ...
    (comp.lang.tcl)
  • Re: trace error
    ... Yes, more or less, I think, with a write trace on::errorInfo. ... last time I asked for core support on a traceback more ... better than a write trace on::errorInfo. ... What *is* really an unwinding step for this: each time a command ...
    (comp.lang.tcl)