Tcl Source Code

If (for example) a file is fed to a socket using [chan copy], where input from the file is always available and output is only sometimes available, [chan copy] seems to buffer input in memory without regard for the disparity between input and output.

The effect of this is that, for a very large file, all memory can be consumed in buffered content, and tcl can fail on memory allocation.

Perhaps [chan copy] should have regard to the output file's buffer, and not seek to fill more than that buffer specifies.  This won't solve the memory exhaustion problem, but might be a sound way to indicate expected performance of the output chan.

allow_comments - 1

Fix committed to HEAD and tcl-8.5-branch.
Added docs and testcases to ferrieux's patch, and fixed a bug in it (*).

(*) The ForwardedOutput branch in ForwardProc had extended error handling, however the caller in ReflectOutput was not updated (equivalent to code in ReflectInput). This led to an overwrite of mutex data, and subsequent crash. Found and fixed with the new test cases.

File Added - 366040: 86.patch

File Added - 366039: 85.patch

File Added - 365897: mychan.tcl

Also attaching a enhanced mychan.tcl showing the use of [chan pending output] in the proper generation of EAGAIN without loss nor duplication of data. This fact is verified by spawning:

    ./tclsh mychan.tcl | sh -c "sleep 1;cat > /tmp/big"

(which fills buffers, then stalls for one second, then restarts, and ends)
and verifying that /tmp/big has the exact expected size of 1000000 bytes.

File Added - 365894: refchan-eagain.patch

Attaching the natural pure-code patch doing exactly that. Restores full symmetry between handling of [read] and [write] verbs.  Verified that it fixes the issue, and passes the (old) test suite.

I'd like a hand to update the doc and test suite though :}

Agree totally with being consistent with read side.

We had a similar thing on the read side. It is now clear that I should have checked the write side for equivalent problems, and my blithe assumptions that there should not be such was wrong. Here is the ChangeLog entry.

2009-08-06  Andreas Kupries  <[email protected]>

* doc/refchan.n [Bug 2827000]: Extended the implementation of
* generic/tclIORChan.c: reflective channels (TIP 219, method
* tests/ioCmd.test: 'read'), enabling handlers to signal EAGAIN to
indicate 'no data, but not at EOF either', and other system
errors. Updated documentation, extended testsuite (New test cases
iocmd*-23.{9,10}).

If either EAGAIN  or EWOULDBLOCK work for the write-side I would prefer EAGAIN, and signaling as a literal error of this kind, i.e.

    return -code error EAGAIN, or
    error EGAIN

Just to be consistent with the read side, in both method and value of signaling. Of these two I am more wedded to consistency in the method of signaling, i.e. throwing an error instead of using in-band signaling through a special return value for the #of written chars. I.e. if EWOULDBLOCK is considered to be the better signal value, then let us go with that.

I'm wondering whether parsing the errorcode would be a practical thing. Or returning a literal "EWOULDBLOCK" instead of the number of bytes. Or whether to return a 0 (a totally short read).

I don't really know. :-)

Any opinion regarding the one I proposed ?

Now that the real issue is just about homed in on, and appears to be because of an API problem, it's valid to consider what changes are required.

Got it.  The hole in the reflection API consists, as suspected earlier, in the inability for the reflected channel to tell its writer EWOULDBLOCK. Indeed, proper async fcopy function requires that the output channel get its BG_FLUSH_SCHEDULED switched on, which tells fcopy to refrain from writing until a fileevent writable fires.

But for this flag to be set,  in FlushChannel at tclIO.c+2346, an errorCode==EWOULDBLOCK (or EAGAIN) must be detected.

While this occurs routinely for normal, fd-based channels, so such thing can happen for a reflected channel, which is a pure script thing...

To keep the API simple, I suggest to simply define the -1 return value from [write] to mean EWOULDBLOCK. A typical refchan like colin's would use [chan pending output] on its underlying (nonblocking & unbuffered) fd to decide whether or not to  send this signal upstream.

colin -- your oflow uses a synchronous fcopy, hence doesn't exhibit the problem because in that case fcopy uses only blocking IO and no fileevents.

Back to my script, I suspect it shows a problem in the current refchan interface with the two-state async-fcopy state machine (alternating readable and writable fileevents), because the initial state allows for a write, and depends on a "short write" to switch state and register a writable fileevent; *and* the refchan API currently doesn't allow for short writes...

Then the memory-filling effect in your case is crystalline: fcopy stays in its initial "goahead and write until you get short writes" state, and the underlying nonblocking [puts] accumulates in the lower channel' buffers.

File Added - 365592: mychan.tcl

Attached mychan.tcl which reproduces something strange though different.

It is a trivial refchan only implementing all verbs but just logging in most cases. It has no underlying fd, it just swallows what's given to [write]. With [write] returning either the full input data size (infinitely fast sink) or -1 (blocking ?), the fcopy runs at full speed. With 0 an error is reported immediately. Strangely, no other verbs than initialize, write and configure are called. This regardless of the blocking mode of the reflected channel.

Andreas, can you explain this ? I know that internally [fcopy] makes use of writable fileevents on its sink, but no such thing reaches the refchan...

File Added - 365590: oflow.tcl

attached oflow.tcl which does *not* reproduce the problem.  What is observed, in either the socket or pipe cases is a finite stream of write requests, no pending output on the raw chan.

Attached the file for posterity.

File Added - 365589: Chan.tcl

http://code.google.com/p/wub/source/browse/trunk/Wub/Chan.tcl and specifically the IChan object in r2290 of this object turned out to be used in the exhibition of this bug.

Yes, but if you do the little extra work needed for the in vitro test I'm requesting, I (and probably Andreas) will have excellent material to chew on, instead or reasoning in abstracto. Single-stepping through gdb beats RTFS... Until then, you're alone :}

Ferrieux, now that the problem has been isolated to some code in a refchan, it should be easier to reason about the cause.  If it transpires that the refchan itself is faulty, then we have demonstrated no-cause and can close the bug.  Failing that, we can hunt it in the refchan core (by producing a case.)

Now that we know this, can you try building an in vitro case with (a transportable version of) this wrapper on top of a simple fcopy reading from /dev/null, and writing to a blocked pipe ([chan pipe] with nobody reading the read side) ?

The experiment in the wild (removing a refchan wrapper from the [fcopy] data path) stopped the allocation exhaustion.

Which leaves three possibilities:

(a) the particular refchan implementation in question accumulates data proportional to the data flowing through it,
(b) the refchan does not signal congestion to its caller properly,
(c) there is something wrong with using refchans for [fcopy]

Ferrieux pointed out that a reflected chan was in the path.  I've just removed it from Wub (using the raw underlying channel in its stead.)

I expect this will eliminate the error, is consistent with Ferrieux's not having reproduced it, and will also narrow the search for underlying cause a bit.  If this stops the error, then it's in my refchan, or in refchan itself, or both.

Much easier than blindly trying to reduce an app to the minimal case.

While Colin explained on the chat that the script was huge, can you try to extract a smaller part reproducing ?

In the backtrace at frame #16 I see ReflectOutput: this is an interesting suspect.

So, to help build a small repro script, can you extract from whatever 3-meg script you have, the refchan that is stuck onto the channel to which fcopy is writing ?

Please attach here a script exhibiting the behavior.

Hello.

Here is the backtrace:

http://shadoura.com/bt.log

This backtrace was made after a big file (~1GiB) was requested from Wub.

allow_comments - 0

Reopening for chromebel_ to provide additional evidence.

allow_comments - 1

This Tracker item was closed automatically by the system. It was
previously set to a Pending status, and the original submitter
did not respond within 14 days (the time period specified by
the administrator of this Tracker).

Waiting for reporter to provide more details - can't reproduce - putting this on the back-burner.

Just tried, no difference on my system :/
Can you trim down to a simple script, replacing the output socket by something else that's blocking (like my stdout | sleep 9999 example) ?

One possibly important detail is that the output (socket) chan in the case we (think) we observe causing this is configured non-blocking, binary.  Does this make any difference?

Hum, cannot seem to repro (Linux Fedora 12, unthreaded, 8.6 HEAD).

FWIW,  [chan copy]'s mechanism is one of alternating readable and writable fileevents, precisely to avoid accumulating data as you describe.

I've tried both sync and async fcopy, reading from a local file and outputting to a blocked stdout (tclsh script.tcl | sleep 9999), in both cases Tcl stops reading shortly after the beginning (typically after reading 68K of input).