Attachment "F022d.tail" to
ticket [462317ffff]
added by
kogorman
2001-09-18 01:54:06.
This is an extract of a system call trace for expect5.32 and tcl8.4a3, with time() and wait4() calls removed.
It was run on RedHat 7.1
The 'Kevin:' strings identify printfs that I've added to the code.
Blank lines and comments in ALLCAPS are my insertions from trying to make sense of this.
Contact: [email protected] (805) 650-6274
BUG:
Near the end, a read is issued which blocks. This seems to be caused by a timer which
was set up some time before, and not removed.
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8077ff0: exp6 armed=1\r\n", 57) = 57
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x809d970: exp20 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x807e128: exp8 armed=1\r\n", 57) = 57
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8093170: exp16 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x808dd70: exp14 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8098570: exp18 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8083570: exp10 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x80a2d70: exp22 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8088970: exp12 armed=0\r\n", 58) = 58
THIS TIMER WILL CAUSE THE NOTIFY CALL BEFORE THE BLOCKING READ
15:56:32 write(1, "Kevin: tclIO.c UpdateInterest(0x8088a28) creates handler for ChannelTimerProc(0x8088a28)\n", 89) = 89
15:56:32 gettimeofday({1000680992, 188562}, {420, 0}) = 0
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8073220: exp4 armed=1\r\n", 57) = 57
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() entry\n", 42) = 42
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() begins ServiceEvent checks\n", 63) = 63
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x80732d8,2) entered\n", 54) = 54
15:56:32 write(1, "Kevin: exp_channelhandler called, 4, mask = 2\n", 46) = 46
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x80732d8,2) done\n", 51) = 51
15:56:32 write(1, "Kevin: tclNotify.c Tcl_ServiceEvent serviced one event\n", 55) = 55
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() serviced a queued event \n", 61) = 61
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() returns 1\n", 46) = 46
15:56:32 write(1, "Kevin blocking read: 4\n", 23) = 23
15:56:32 read(4, "\fS_NAME\t\t\t NUMWAIT\r\n------------------------- ----------\r\nSupplier#000004223\t\t 21\r\nSupplier#000"..., 4096) = 4095
15:56:32 write(5, "0\n\nServer 1 at 1000679112: Result: kstat.complete_parsing: 0\n\nServer 1 at 1000679112: Result: kstat."..., 4096) = 4096
15:56:32 gettimeofday({1000680992, 354246}, {420, 0}) = 0
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8077ff0: exp6 armed=1\r\n", 57) = 57
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x809d970: exp20 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x807e128: exp8 armed=1\r\n", 57) = 57
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8093170: exp16 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x808dd70: exp14 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8098570: exp18 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8083570: exp10 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x80a2d70: exp22 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8088970: exp12 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8073220: exp4 armed=0\r\n", 57) = 57
15:56:32 write(1, "Kevin: tclIO.c UpdateInterest(0x80732d8) creates handler for ChannelTimerProc(0x80732d8)\n", 89) = 89
15:56:32 gettimeofday({1000680992, 354994}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() entry\n", 42) = 42
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() begins ServiceEvent checks\n", 63) = 63
15:56:32 gettimeofday({1000680992, 355155}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclIO.c ChannelTimerProc(0x8083628) creates handler, calls notify\n", 73) = 73
15:56:32 gettimeofday({1000680992, 355262}, {420, 0}) = 0
15:56:32 gettimeofday({1000680992, 355303}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8083628,2) entered\n", 54) = 54
15:56:32 write(1, "Kevin: exp_channelhandler called, 10, mask = 2\n", 47) = 47
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8083628,2) done\n", 51) = 51
TIMER FIRES, BUT THERE'S DATA THIS TIME
15:56:32 write(1, "Kevin: tclIO.c ChannelTimerProc(0x8088a28) creates handler, calls notify\n", 73) = 73
15:56:32 gettimeofday({1000680992, 355588}, {420, 0}) = 0
15:56:32 gettimeofday({1000680992, 355629}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8088a28,2) entered\n", 54) = 54
15:56:32 write(1, "Kevin: exp_channelhandler called, 12, mask = 2\n", 47) = 47
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8088a28,2) done\n", 51) = 51
15:56:32 write(1, "Kevin: tclIO.c ChannelTimerProc(0x80732d8) creates handler, calls notify\n", 73) = 73
15:56:32 gettimeofday({1000680992, 355913}, {420, 0}) = 0
15:56:32 gettimeofday({1000680992, 355954}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x80732d8,2) entered\n", 54) = 54
15:56:32 write(1, "Kevin: exp_channelhandler called, 4, mask = 2\n", 46) = 46
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x80732d8,2) done\n", 51) = 51
15:56:32 gettimeofday({1000680992, 356170}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclNotify.c Tcl_ServiceEvent serviced one event\n", 55) = 55
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() serviced a queued event \n", 61) = 61
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() returns 1\n", 46) = 46
15:56:32 write(1, "Kevin blocking read: 10\n", 24) = 24
15:56:32 read(10, "06032\t\t 10\r\nSupplier#000006374\t\t 10\r\nSupplier#000006397\t\t 10\r\nSupplier#000007456\t\t 10\r\nSupplier#"..., 4096) = 4095
15:56:32 write(1, "Kevin blocking read: 12\n", 24) = 24
15:56:32 read(12, "plier#000009026\t\t 11\r\nSupplier#000009173\t\t 11\r\nSupplier#000009204\t\t 11\r\nSupplier#000009371\t\t 11\r"..., 4096) = 4095
15:56:32 write(1, "Kevin blocking read: 4\n", 23) = 23
15:56:32 read(4, "plier#000006355\t\t 11\r\nSupplier#000006524\t\t 11\r\nSupplier#000006829\t\t 11\r\nSupplier#000006994\t\t 11\r"..., 4096) = 4095
15:56:32 gettimeofday({1000680992, 861804}, {420, 0}) = 0
15:56:32 gettimeofday({1000680992, 861844}, {420, 0}) = 0
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8077ff0: exp6 armed=1\r\n", 57) = 57
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x809d970: exp20 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x807e128: exp8 armed=1\r\n", 57) = 57
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8093170: exp16 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x808dd70: exp14 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8098570: exp18 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8083570: exp10 armed=0\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x80a2d70: exp22 armed=1\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8088970: exp12 armed=0\r\n", 58) = 58
15:56:32 write(1, "Kevin: Tcl_CreateChannelHandler 0x8073220: exp4 armed=0\r\n", 57) = 57
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() entry\n", 42) = 42
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() begins ServiceEvent checks\n", 63) = 63
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() ends ServiceEvent checks\n", 61) = 61
15:56:32 gettimeofday({1000680992, 862671}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() calls Tcl_WaitForEvent(0x8049fb0)\n", 70) = 70
15:56:32 write(1, "Kevin: select 1", 15) = 15
15:56:32 select(23, [6 8 14 16 18 20 22], [], [4 6 8 10 12 14 16 18 20 22], {0, 0}) = 0 (Timeout)
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() Tcl_WaitForEvent(0x8049fb0) returned 0\n", 75) = 75
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() calls a checkProc\n", 54) = 54
15:56:32 write(1, "Kevin: tclTimer.c TimerCheckProc() entry\n", 41) = 41
15:56:32 gettimeofday({1000680992, 863179}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclTimer.c Tcl_DriverHandlerProc() Queues entry 0x8073828\n", 65) = 65
15:56:32 write(1, "Kevin: tclNotify.c Tcl_QueueEvent() event 0x8073828 \n", 53) = 53
15:56:32 write(1, "Kevin: tclNotify.c QueueEvent 0x8073828 called at 0\n", 52) = 52
15:56:32 write(1, "Kevin: tclNotify.c QueueEvent 0x8073828 at TAIL\n", 48) = 48
15:56:32 write(1, "Kevin: tclTimer.c TimerCheckProc() exit\n", 40) = 40
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() checkProc done\n", 51) = 51
15:56:32 gettimeofday({1000680992, 863544}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclIO.c ChannelTimerProc(0x8083628) creates handler, calls notify\n", 73) = 73
15:56:32 gettimeofday({1000680992, 863645}, {420, 0}) = 0
15:56:32 gettimeofday({1000680992, 863683}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8083628,2) entered\n", 54) = 54
15:56:32 write(1, "Kevin: exp_channelhandler called, 10, mask = 2\n", 47) = 47
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8083628,2) done\n", 51) = 51
TIMER FIRES, BUT THERE'S DATA THIS TIME
15:56:32 write(1, "Kevin: tclIO.c ChannelTimerProc(0x8088a28) creates handler, calls notify\n", 73) = 73
15:56:32 gettimeofday({1000680992, 863956}, {420, 0}) = 0
15:56:32 gettimeofday({1000680992, 863994}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8088a28,2) entered\n", 54) = 54
15:56:32 write(1, "Kevin: exp_channelhandler called, 12, mask = 2\n", 47) = 47
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8088a28,2) done\n", 51) = 51
15:56:32 write(1, "Kevin: tclIO.c ChannelTimerProc(0x80732d8) creates handler, calls notify\n", 73) = 73
15:56:32 gettimeofday({1000680992, 864261}, {420, 0}) = 0
15:56:32 gettimeofday({1000680992, 864300}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x80732d8,2) entered\n", 54) = 54
15:56:32 write(1, "Kevin: exp_channelhandler called, 4, mask = 2\n", 46) = 46
15:56:32 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x80732d8,2) done\n", 51) = 51
15:56:32 gettimeofday({1000680992, 864506}, {420, 0}) = 0
15:56:32 write(1, "Kevin: tclNotify.c Tcl_ServiceEvent serviced one event\n", 55) = 55
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() notices Tcl_ServiceEvent(flags)\n", 68) = 68
15:56:32 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() returns 1\n", 46) = 46
15:56:32 write(1, "Kevin blocking read: 10\n", 24) = 24
15:56:32 read(10, "Supplier#000009715\t\t 7\r\nSupplier#000009770\t\t 7\r\nSupplier#000009890\t\t 7\r\nSupplier#000009937\t\t "..., 4096) = 3028
15:56:32 write(1, "Server 4 stream 4 query 21: start 117, end 1880 Elapsed time: 1763 seconds\n", 75) = 75
15:56:32 brk(0x80f2000) = 0x80f2000
15:56:32 write(11, "rver 4 at 1879: Supplier#000005289\t\t 15\nServer 4 at 1879: Supplier#000005308\t\t 15\nServer 4 at 1879"..., 4096) = 4096
15:56:32 write(1, "Server 4 stream 4 query 21: 1071350 consistent gets\n", 57) = 57
15:56:32 write(1, "Server 4 stream 4 query 21: 20618 physical reads\n", 56) = 56
15:56:32 write(1, "Server 4 stream 4 trailer done at 1880\n", 39) = 39
15:56:32 write(10, "@Q14p 4 \'1996-12-01\'\r", 21) = 21
15:56:32 write(1, "Server 4 id exp10 stream 4 qtime 0 query 14 at 1880: @Q14p 4 \'1996-12-01\'\r\n", 75) = 75
15:56:32 write(1, "Running the main \'expect\' command.\n", 35) = 35
15:56:32 write(1, "Kevin blocking read: 4\n", 23) = 23
15:56:32 read(4, "60\t\t 8\r\nSupplier#000008985\t\t 8\r\nSupplier#000009195\t\t 8\r\nSupplier#000009490\t\t 8\r\nSupplier#000"..., 4096) = 2322
15:56:33 write(1, "Server 1 stream 1 query 21: start 0, end 1881 Elapsed time: 1881 seconds\n", 73) = 73
15:56:33 write(1, "Kevin blocking read: 12\n", 24) = 24
15:56:33 read(12, "99\t\t 8\r\nSupplier#000009886\t\t 8\r\nSupplier#000000058\t\t 7\r\nSupplier#000000093\t\t 7\r\nSupplier#000"..., 4096) = 3974
15:56:33 write(1, "Server 5 stream 5 query 21: start 0, end 1881 Elapsed time: 1881 seconds\n", 73) = 73
15:56:33 write(1, "Server 5 stream 5 query 21: 1092163 consistent gets\n", 57) = 57
15:56:33 write(1, "Server 5 stream 5 query 21: 19707 physical reads\n", 56) = 56
15:56:33 gettimeofday({1000680993, 263469}, {420, 0}) = 0
15:56:33 gettimeofday({1000680993, 263512}, {420, 0}) = 0
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8083570: exp10 armed=0\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8073220: exp4 armed=0\r\n", 57) = 57
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8088970: exp12 armed=0\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8077ff0: exp6 armed=1\r\n", 57) = 57
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x809d970: exp20 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x807e128: exp8 armed=1\r\n", 57) = 57
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8093170: exp16 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x808dd70: exp14 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8098570: exp18 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x80a2d70: exp22 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() entry\n", 42) = 42
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() begins ServiceEvent checks\n", 63) = 63
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() ends ServiceEvent checks\n", 61) = 61
15:56:33 gettimeofday({1000680993, 264337}, {420, 0}) = 0
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() calls Tcl_WaitForEvent(0x8049fb0)\n", 70) = 70
15:56:33 write(1, "Kevin: select 1", 15) = 15
15:56:33 select(23, [4 6 8 10 14 16 18 20 22], [], [4 6 8 10 12 14 16 18 20 22], {0, 0}) = 2 (in [4 10], left {0, 0})
15:56:33 write(1, "Kevin: tclNotify.c Tcl_QueueEvent() event 0x80c4a68 \n", 53) = 53
15:56:33 write(1, "Kevin: tclNotify.c QueueEvent 0x80c4a68 called at 0\n", 52) = 52
15:56:33 write(1, "Kevin: tclNotify.c QueueEvent 0x80c4a68 at TAIL\n", 48) = 48
15:56:33 write(1, "Kevin: tclNotify.c Tcl_QueueEvent() event 0x80d8418 \n", 53) = 53
15:56:33 write(1, "Kevin: tclNotify.c QueueEvent 0x80d8418 called at 0\n", 52) = 52
15:56:33 write(1, "Kevin: tclNotify.c QueueEvent 0x80d8418 at TAIL\n", 48) = 48
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() Tcl_WaitForEvent(0x8049fb0) returned 0\n", 75) = 75
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() calls a checkProc\n", 54) = 54
15:56:33 write(1, "Kevin: tclTimer.c TimerCheckProc() entry\n", 41) = 41
15:56:33 gettimeofday({1000680993, 265247}, {420, 0}) = 0
15:56:33 write(1, "Kevin: tclTimer.c Tcl_DriverHandlerProc() Queues entry 0x80ba3b0\n", 65) = 65
15:56:33 write(1, "Kevin: tclNotify.c Tcl_QueueEvent() event 0x80ba3b0 \n", 53) = 53
15:56:33 write(1, "Kevin: tclNotify.c QueueEvent 0x80ba3b0 called at 0\n", 52) = 52
15:56:33 write(1, "Kevin: tclNotify.c QueueEvent 0x80ba3b0 at TAIL\n", 48) = 48
15:56:33 write(1, "Kevin: tclTimer.c TimerCheckProc() exit\n", 40) = 40
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() checkProc done\n", 51) = 51
15:56:33 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x80732d8,2) entered\n", 54) = 54
15:56:33 write(1, "Kevin: exp_channelhandler called, 4, mask = 2\n", 46) = 46
15:56:33 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x80732d8,2) done\n", 51) = 51
15:56:33 write(1, "Kevin: tclNotify.c Tcl_ServiceEvent serviced one event\n", 55) = 55
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() notices Tcl_ServiceEvent(flags)\n", 68) = 68
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() returns 1\n", 46) = 46
15:56:33 write(1, "Kevin blocking read: 4\n", 23) = 23
15:56:33 read(4, " 0\t SELECT STATEMENT Optimizer=CHOOSE (Cost=5987 Card=304 Bytes=\r\n\t 27056)\r\n\r\n 1\t0 SORT (ORD"..., 4096) = 1444
15:56:33 write(1, "Server 1 stream 1 query 21: 1067327 consistent gets\n", 57) = 57
15:56:33 write(5, " 1880: Supplier#000009516\t\t 14\nServer 1 at 1880: Supplier#000009541\t\t 14\nServer 1 at 1880: Supplie"..., 4096) = 4096
15:56:33 write(1, "Server 1 stream 1 query 21: 20343 physical reads\n", 56) = 56
15:56:33 write(1, "Server 1 stream 1 trailer done at 1881\n", 39) = 39
15:56:33 write(4, "@Q03p 1 \'AUTOMOBILE\' \'1995-03-12\'\r", 34) = 34
15:56:33 write(1, "Server 1 id exp4 stream 1 qtime 0 query 3 at 1881: @Q03p 1 \'AUTOMOBILE\' \'1995-03-12\'\r\n", 86) = 86
15:56:33 write(1, "Running the main \'expect\' command.\n", 35) = 35
15:56:33 gettimeofday({1000680993, 324012}, {420, 0}) = 0
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8073220: exp4 armed=0\r\n", 57) = 57
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8088970: exp12 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8083570: exp10 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8077ff0: exp6 armed=1\r\n", 57) = 57
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x809d970: exp20 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x807e128: exp8 armed=1\r\n", 57) = 57
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8093170: exp16 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x808dd70: exp14 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8098570: exp18 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x80a2d70: exp22 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() entry\n", 42) = 42
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() begins ServiceEvent checks\n", 63) = 63
15:56:33 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8083628,2) entered\n", 54) = 54
15:56:33 write(1, "Kevin: exp_channelhandler called, 10, mask = 2\n", 47) = 47
15:56:33 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8083628,2) done\n", 51) = 51
15:56:33 write(1, "Kevin: tclNotify.c Tcl_ServiceEvent serviced one event\n", 55) = 55
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() serviced a queued event \n", 61) = 61
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() returns 1\n", 46) = 46
15:56:33 write(1, "Kevin blocking read: 10\n", 24) = 24
15:56:33 read(10, "@Q14p 4 \'1996-12-01\'\r\n", 4096) = 22
15:56:33 gettimeofday({1000680993, 326617}, {420, 0}) = 0
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8073220: exp4 armed=1\r\n", 57) = 57
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8088970: exp12 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8083570: exp10 armed=0\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8077ff0: exp6 armed=1\r\n", 57) = 57
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x809d970: exp20 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x807e128: exp8 armed=1\r\n", 57) = 57
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8093170: exp16 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x808dd70: exp14 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x8098570: exp18 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: Tcl_CreateChannelHandler 0x80a2d70: exp22 armed=1\r\n", 58) = 58
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() entry\n", 42) = 42
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() begins ServiceEvent checks\n", 63) = 63
15:56:33 gettimeofday({1000680993, 327376}, {420, 0}) = 0
15:56:33 write(1, "Kevin: tclIO.c ChannelTimerProc(0x8083628) clears off (no action)\n", 66) = 66
TIMER FIRES, BUT ALL DATA HAS BEEN DRAINED, SO THE READ WEDGES.
15:56:33 write(1, "Kevin: tclIO.c ChannelTimerProc(0x8088a28) creates handler, calls notify\n", 73) = 73
15:56:33 gettimeofday({1000680993, 327600}, {420, 0}) = 0
15:56:33 gettimeofday({1000680993, 327641}, {420, 0}) = 0
15:56:33 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8088a28,2) entered\n", 54) = 54
15:56:33 write(1, "Kevin: exp_channelhandler called, 12, mask = 2\n", 47) = 47
15:56:33 write(1, "Kevin: tclIO.c Tcl_NotifyChannel(0x8088a28,2) done\n", 51) = 51
15:56:33 write(1, "Kevin: tclIO.c ChannelTimerProc(0x80732d8) clears off (no action)\n", 66) = 66
15:56:33 gettimeofday({1000680993, 328140}, {420, 0}) = 0
15:56:33 write(1, "Kevin: tclNotify.c Tcl_ServiceEvent serviced one event\n", 55) = 55
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() serviced a queued event \n", 61) = 61
15:56:33 write(1, "Kevin: tclNotify.c Tcl_DoOneEvent() returns 1\n", 46) = 46
15:56:33 write(1, "Kevin blocking read: 12\n", 24) = 24
THIS READ WEDGES. I KILL OFF THE CHILD ABOUT 20 MINUTES LATER.
15:56:33 read(12, 0x808e068, 4096) = ? ERESTARTSYS (To be restarted)
16:12:12 --- SIGCHLD (Child exited) ---
16:12:12 read(12, 0x808e068, 4096) = -1 EIO (Input/output error)
16:12:12 close(12) = 0
