diff --git a/src/pkg/io/print.go b/src/pkg/io/print.go new file mode 100644 --- /dev/null +++ b/src/pkg/io/print.go @@ -0,0 +1,55 @@ +// Copyright 2013 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package io + +import ( + "sync" + "time" + "strconv" +) + +type MemoryLog struct { + sync.Mutex + lines []string + start time.Time +} + +var ( + Log MemoryLog +) + +func NewMemoryLog() *MemoryLog { + return &MemoryLog{ + lines: make([]string, 0), + } +} + +func (l *MemoryLog) Print(line string) { + l.Lock() + defer l.Unlock() + l.lines = append(l.lines, line) +} + +func (l *MemoryLog) SetStart() { + l.Lock() + defer l.Unlock() + l.start = time.Now() + s := "SetStart at " + strconv.FormatInt(l.start.UnixNano(), 10) + "ns" + l.lines = append(l.lines, s) +} + +func (l *MemoryLog) Duration() time.Duration { + l.Lock() + defer l.Unlock() + return time.Now().Sub(l.start) +} + +func (l *MemoryLog) Dump(w Writer) { + l.Lock() + defer l.Unlock() + for _, line := range l.lines { + w.Write([]byte(line + "\n")) + } +} diff --git a/src/pkg/net/a.txt b/src/pkg/net/a.txt new file mode 100755 --- /dev/null +++ b/src/pkg/net/a.txt @@ -0,0 +1,224 @@ +netpoll: deadline (now=1375158647914756600) +netpoll: deadline (now=1375158648473371800) +netpoll: deadline (now=1375158648485091000) +netpoll: deadline (now=1375158649886512000) +netpoll: deadline (now=1375158649922646200) +netpoll: deadline (now=1375158652022336200) +SetStart at 1375158647897177800ns + 0: 1ms run 1/3 + 6836200: SetDeadline(1375158647905014000) +SetStart at 1375158647915733200ns + 0: 1ms run 2/3 + 976600: SetDeadline(1375158647917709800) + 558615200: WSARecv(fd=280): Wait: 5 err=i/o timeout + 558615200: WSARecv(fd=280): CancelIO: 1 + 558615200: WSARecv(fd=280): CancelIO: 2 + 558615200: WSARecv(fd=280): CancelIO: 3 err=Element not found. + 558615200: WSARecv(fd=280): CancelIO: 4 + 558615200: WSARecv(fd=280): WaitCanceled: 1 + 558615200: WSARecv(fd=280): WaitCanceled: 3 qty=8192 +SetStart at 1375158648475325000ns + 0: 1ms run 3/3 + 0: SetDeadline(1375158648476325000) + 10742600: WSARecv(fd=300): Wait: 5 err=i/o timeout + 10742600: WSARecv(fd=300): CancelIO: 1 + 10742600: WSARecv(fd=300): CancelIO: 2 + 10742600: WSARecv(fd=300): CancelIO: 3 err=Element not found. + 10742600: WSARecv(fd=300): CancelIO: 4 + 10742600: WSARecv(fd=300): WaitCanceled: 1 + 10742600: WSARecv(fd=300): WaitCanceled: 3 qty=8192 +SetStart at 1375158648486067600ns + 0: 5ms run 1/3 + 976600: SetDeadline(1375158648492044200) + 1402397600: WSARecv(fd=304): Wait: 5 err=i/o timeout + 1402397600: WSARecv(fd=304): CancelIO: 1 + 1402397600: WSARecv(fd=304): CancelIO: 2 + 1402397600: WSARecv(fd=304): CancelIO: 3 err=Element not found. + 1402397600: WSARecv(fd=304): CancelIO: 4 + 1402397600: WSARecv(fd=304): WaitCanceled: 1 + 1402397600: WSARecv(fd=304): WaitCanceled: 3 qty=8192 +SetStart at 1375158649888465200ns + 0: 5ms run 2/3 + 976600: SetDeadline(1375158649894441800) + 35157600: WSARecv(fd=280): Wait: 5 err=i/o timeout + 35157600: WSARecv(fd=280): CancelIO: 1 + 35157600: WSARecv(fd=280): CancelIO: 2 + 35157600: WSARecv(fd=280): CancelIO: 3 err=Element not found. + 35157600: WSARecv(fd=280): CancelIO: 4 + 35157600: WSARecv(fd=280): WaitCanceled: 1 + 35157600: WSARecv(fd=280): WaitCanceled: 3 qty=8192 +SetStart at 1375158649924599400ns + 0: 5ms run 3/3 + 0: SetDeadline(1375158649929599400) + 2105549600: WSARecv(fd=300): Wait: 5 err=i/o timeout + 2105549600: WSARecv(fd=300): CancelIO: 1 + 2105549600: WSARecv(fd=300): CancelIO: 2 + 2105549600: WSARecv(fd=300): CancelIO: 3 err=Element not found. + 2105549600: WSARecv(fd=300): CancelIO: 4 + 2105549600: WSARecv(fd=300): WaitCanceled: 1 +--- FAIL: TestVariousDeadlines1Proc (4.15 seconds) + timeout_test.go:488: 1ms run 1/3 + timeout_test.go:510: for 1ms run 1/3, good client timeout after 11.7192ms, reading 294912 bytes + timeout_test.go:522: for 1ms run 1/3: server in 11.7192ms wrote 327680, WSASend tcp 127.0.0.1:64935: The specified network name is no longer available. + timeout_test.go:488: 1ms run 2/3 + timeout_test.go:510: for 1ms run 2/3, good client timeout after 558.6152ms, reading 65880064 bytes + timeout_test.go:522: for 1ms run 2/3: server in 558.6152ms wrote 65896448, WSASend tcp 127.0.0.1:64935: The specified network name is no longer available. + timeout_test.go:488: 1ms run 3/3 + timeout_test.go:510: for 1ms run 3/3, good client timeout after 10.7426ms, reading 1081344 bytes + timeout_test.go:522: for 1ms run 3/3: server in 10.7426ms wrote 1114112, WSASend tcp 127.0.0.1:64935: The specified network name is no longer available. + timeout_test.go:488: 5ms run 1/3 + timeout_test.go:510: for 5ms run 1/3, good client timeout after 1.401421s, reading 171188224 bytes + timeout_test.go:522: for 5ms run 1/3: server in 1.4023976s wrote 171212800, WSASend tcp 127.0.0.1:64935: The specified network name is no longer available. + timeout_test.go:488: 5ms run 2/3 + timeout_test.go:510: for 5ms run 2/3, good client timeout after 34.181ms, reading 4071424 bytes + timeout_test.go:522: for 5ms run 2/3: server in 35.1576ms wrote 4096000, WSASend tcp 127.0.0.1:64935: The specified network name is no longer available. + timeout_test.go:488: 5ms run 3/3 +panic: ALEX [recovered] + panic: ALEX + +goroutine 3 [running]: +runtime.panic(0x52c7a0, 0x121a4620) + /root/go/root/src/pkg/runtime/panic.c:265 +0xa6 +testing.func·005() + /root/go/root/src/pkg/testing/testing.go:355 +0xce +----- stack segment boundary ----- +runtime.panic(0x52c7a0, 0x121a4620) + /root/go/root/src/pkg/runtime/panic.c:247 +0xe8 +net.testVariousDeadlines(0x12194180, 0x1) + /root/go/root/src/pkg/net/timeout_test.go:516 +0xf94 +net.TestVariousDeadlines1Proc(0x12194180) + /root/go/root/src/pkg/net/timeout_test.go:416 +0x32 +testing.tRunner(0x12194180, 0x6ea134) + /root/go/root/src/pkg/testing/testing.go:360 +0x88 +runtime.goexit() + /root/go/root/src/pkg/runtime/proc.c:1332 +created by testing.RunTests + /root/go/root/src/pkg/testing/testing.go:440 +0x699 + +goroutine 1 [chan receive]: +runtime.park(0x40a270, 0x1217450c, 0x6e798d) + /root/go/root/src/pkg/runtime/proc.c:1280 +0x63 +runtime.chanrecv(0x5264e0, 0x121744e0, 0x341644, 0x0, 0x0) + /root/go/root/src/pkg/runtime/chan.c:359 +0x49f +runtime.chanrecv1(0x5264e0, 0x121744e0, 0x0, 0x121744e0) + /root/go/root/src/pkg/runtime/chan.c:451 +0x2f +testing.RunTests(0x5b4f64, 0x6e9d80, 0x61, 0x61, 0x12183a01) + /root/go/root/src/pkg/testing/testing.go:441 +0x6b4 +testing.Main(0x5b4f64, 0x6e9d80, 0x61, 0x61, 0x6e5860, ...) + /root/go/root/src/pkg/testing/testing.go:372 +0x6a +main.main() + net/_test/_testmain.go:267 +0x82 +runtime.main() + /root/go/root/src/pkg/runtime/proc.c:201 +0x102 +runtime.goexit() + /root/go/root/src/pkg/runtime/proc.c:1332 + +goroutine 2 [syscall]: +runtime.asmcgocall(0x4229c0, 0x12180a94) + /root/go/root/src/pkg/runtime/asm_386.s:493 +0x22 +runtime.stdcall(0x76f31136, 0x2, 0xdc, 0xea60) + /root/go/root/src/pkg/runtime/os_windows.c:271 +0x5f +runtime.semasleep(0xea60, 0x0) + /root/go/root/src/pkg/runtime/os_windows.c:179 +0x5a +notetsleep(0x357f9c, 0xf8475800, 0xd, 0x153d5dd0, 0x13158b8f, ...) + /root/go/root/src/pkg/runtime/lock_sema.c:198 +0xb4 +runtime.notetsleepg(0x357f9c, 0xf8475800, 0xd) + /root/go/root/src/pkg/runtime/lock_sema.c:266 +0xa7 +runtime.MHeap_Scavenger() + /root/go/root/src/pkg/runtime/mheap.c:463 +0xc2 +runtime.goexit() + /root/go/root/src/pkg/runtime/proc.c:1332 +created by runtime.main + /root/go/root/src/pkg/runtime/proc.c:168 + +goroutine 4 [runnable]: +runtime.park(0x40a270, 0x30d2ec, 0x6e7bfd) + /root/go/root/src/pkg/runtime/proc.c:1280 +0x63 +netpollblock(0x30d2e8, 0x72) + /root/go/root/src/pkg/runtime/netpoll.goc:264 +0x95 +net.runtime_pollWait(0x30d2e8, 0x72, 0x0) + /root/go/root/src/pkg/runtime/netpoll.goc:116 +0x60 +net.(*pollDesc).Wait(0x12194230, 0x72, 0x30c018, 0x3e5) + /root/go/root/src/pkg/net/fd_poll_runtime.go:74 +0x34 +net.(*ioSrv).ExecIO(0x12170540, 0x30d430, 0x12193ea0, 0x56c708, 0x3, ...) + /root/go/root/src/pkg/net/fd_windows.go:188 +0x1a7 +net.(*netFD).accept(0x121941e0, 0x5b51ec, 0x0, 0x0, 0x0) + /root/go/root/src/pkg/net/fd_windows.go:595 +0x2a4 +net.(*TCPListener).AcceptTCP(0x12170560, 0x41e25d, 0x8, 0x55d440) + /root/go/root/src/pkg/net/tcpsock_posix.go:237 +0x43 +net.(*TCPListener).Accept(0x12170560, 0x121c6158, 0x121c6148, 0x0, 0x0) + /root/go/root/src/pkg/net/tcpsock_posix.go:247 +0x2a +net.func·068() + /root/go/root/src/pkg/net/timeout_test.go:439 +0x55 +runtime.goexit() + /root/go/root/src/pkg/runtime/proc.c:1332 +created by net.testVariousDeadlines + /root/go/root/src/pkg/net/timeout_test.go:452 +0x239 + +goroutine 17 [IO wait]: +runtime.park(0x40a270, 0x30d1a8, 0x6e7bfd) + /root/go/root/src/pkg/runtime/proc.c:1280 +0x63 +netpollblock(0x30d1a4, 0x72) + /root/go/root/src/pkg/runtime/netpoll.goc:264 +0x95 +net.runtime_pollWaitCanceled(0x30d1a4, 0x72) + /root/go/root/src/pkg/runtime/netpoll.goc:128 +0x41 +net.(*pollDesc).WaitCanceled(0x121cab30, 0x72) + /root/go/root/src/pkg/net/fd_poll_runtime.go:87 +0x34 +net.(*ioSrv).ExecIO(0x12170540, 0x30d498, 0x121a5b80, 0x2000, 0x2000, ...) + /root/go/root/src/pkg/net/fd_windows.go:226 +0x60d +net.(*netFD).Read(0x121caae0, 0x121a0000, 0x2000, 0x2000, 0x0, ...) + /root/go/root/src/pkg/net/fd_windows.go:449 +0x120 +net.(*conn).Read(0x121c6188, 0x121a0000, 0x2000, 0x2000, 0x2000, ...) + /root/go/root/src/pkg/net/net.go:123 +0xaa +io/ioutil.devNull.ReadFrom(0x0, 0x30d450, 0x121c6188, 0xf6d2000, 0x0, ...) + /root/go/root/src/pkg/io/ioutil/ioutil.go:140 +0xa5 +io.Copy(0x30c050, 0x0, 0x30d450, 0x121c6188, 0x0, ...) + /root/go/root/src/pkg/io/io.go:348 +0xec +net.func·069() + /root/go/root/src/pkg/net/timeout_test.go:500 +0x1ea +runtime.goexit() + /root/go/root/src/pkg/runtime/proc.c:1332 +created by net.testVariousDeadlines + /root/go/root/src/pkg/net/timeout_test.go:504 +0x721 + +goroutine 6 [timer goroutine (idle)]: +runtime.park(0x40a270, 0x6ec340, 0x6e49a6) + /root/go/root/src/pkg/runtime/proc.c:1280 +0x63 +timerproc() + /root/go/root/src/pkg/runtime/time.goc:210 +0x8b +runtime.goexit() + /root/go/root/src/pkg/runtime/proc.c:1332 +created by addtimer + /root/go/root/src/pkg/runtime/time.goc:90 + +goroutine 16 [IO wait]: +runtime.park(0x40a270, 0x30d280, 0x6e7bfd) + /root/go/root/src/pkg/runtime/proc.c:1280 +0x63 +netpollblock(0x30d27c, 0x77) + /root/go/root/src/pkg/runtime/netpoll.goc:264 +0x95 +net.runtime_pollWait(0x30d27c, 0x77, 0x0) + /root/go/root/src/pkg/runtime/netpoll.goc:116 +0x60 +net.(*pollDesc).Wait(0x121ca8f0, 0x77, 0x30c018, 0x3e5) + /root/go/root/src/pkg/net/fd_poll_runtime.go:74 +0x34 +net.(*ioSrv).ExecIO(0x12170540, 0x30d548, 0x121a5ac0, 0x8000, 0x8000, ...) + /root/go/root/src/pkg/net/fd_windows.go:188 +0x1a7 +net.(*netFD).Write(0x121ca8a0, 0x121b6000, 0x8000, 0x8000, 0x0, ...) + /root/go/root/src/pkg/net/fd_windows.go:518 +0x120 +net.(*conn).Write(0x121c6148, 0x121b6000, 0x8000, 0x8000, 0x8000, ...) + /root/go/root/src/pkg/net/net.go:131 +0xaa +net.(*writerOnly).Write(0x121c6168, 0x121b6000, 0x8000, 0x8000, 0x8000, ...) + /root/go/root/src/pkg/net/cgo_stub.go:1 +0x57 +io.Copy(0x30d518, 0x121c6168, 0x30d4d0, 0x121c9e61, 0xf6d8000, ...) + /root/go/root/src/pkg/io/io.go:354 +0x1df +net.genericReadFrom(0x30d4b8, 0x121c6148, 0x30d4d0, 0x121c9e61, 0x0, ...) + /root/go/root/src/pkg/net/net.go:395 +0xa3 +net.(*TCPConn).ReadFrom(0x121c6148, 0x30d4d0, 0x121c9e61, 0x30d500, 0x121c6148, ...) + /root/go/root/src/pkg/net/tcpsock_posix.go:76 +0x98 +io.Copy(0x30d4b8, 0x121c6148, 0x30d4d0, 0x121c9e61, 0x0, ...) + /root/go/root/src/pkg/io/io.go:348 +0xec +net.func·067() + /root/go/root/src/pkg/net/timeout_test.go:446 +0xbd +runtime.goexit() + /root/go/root/src/pkg/runtime/proc.c:1332 +created by net.func·068 + /root/go/root/src/pkg/net/timeout_test.go:450 +0xc3 diff --git a/src/pkg/net/fd_windows.go b/src/pkg/net/fd_windows.go --- a/src/pkg/net/fd_windows.go +++ b/src/pkg/net/fd_windows.go @@ -194,6 +194,7 @@ } return int(o.qty), nil } + OIPrintf(oi, "Wait: 5 err=%v", err) // IO is interrupted by "close" or "timeout" netpollErr := err switch netpollErr { @@ -203,26 +204,35 @@ panic("net: unexpected runtime.netpoll error: " + netpollErr.Error()) } // Cancel our request. + OIPrintf(oi, "CancelIO: 1") if canCancelIO { + OIPrintf(oi, "CancelIO: 2") err := syscall.CancelIoEx(syscall.Handle(o.Op().fd.sysfd), &o.o) // Assuming ERROR_NOT_FOUND is returned, if IO is completed. if err != nil && err != syscall.ERROR_NOT_FOUND { // TODO(brainman): maybe do something else, but panic. panic(err) } + OIPrintf(oi, "CancelIO: 3 err=%v", err) } else { + OIPrintf(oi, "CancelIO: 2") s.canchan <- oi <-o.errnoc + OIPrintf(oi, "CancelIO: 3") } + OIPrintf(oi, "CancelIO: 4") // Wait for cancellation to complete. + OIPrintf(oi, "WaitCanceled: 1") o.fd.pd.WaitCanceled(int(o.mode)) if o.errno != 0 { err = syscall.Errno(o.errno) + OIPrintf(oi, "WaitCanceled: 2 err=%v", err) if err == syscall.ERROR_OPERATION_ABORTED { // IO Canceled err = netpollErr } return 0, &OpError{oi.Name(), o.fd.net, o.fd.laddr, err} } + OIPrintf(oi, "WaitCanceled: 3 qty=%d", o.qty) // We issued cancellation request. But, it seems, IO operation succeeded // before cancellation request run. We need to treat IO operation as // succeeded (the bytes are actually sent/recv from network). diff --git a/src/pkg/net/print.go b/src/pkg/net/print.go new file mode 100644 --- /dev/null +++ b/src/pkg/net/print.go @@ -0,0 +1,23 @@ +// Copyright 2013 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package net + +import ( + "fmt" + "io" +) + +func Printf(format string, a ...interface{}) { + prefix := fmt.Sprintf("%14d: ", io.Log.Duration().Nanoseconds()) + io.Log.Print(prefix + fmt.Sprintf(format, a...)) +} + +func OIPrintf(oi anOpIface, format string, a ...interface{}) { + prefix := fmt.Sprintf("%14d: ", io.Log.Duration().Nanoseconds()) + o := oi.Op() + fd := o.fd + prefix += fmt.Sprintf("%s(fd=%d): ", oi.Name(), fd.sysfd) + io.Log.Print(prefix + fmt.Sprintf(format, a...)) +} diff --git a/src/pkg/net/timeout_test.go b/src/pkg/net/timeout_test.go --- a/src/pkg/net/timeout_test.go +++ b/src/pkg/net/timeout_test.go @@ -11,6 +11,7 @@ "runtime" "testing" "time" + "os" ) func isTimeout(err error) bool { @@ -423,8 +424,6 @@ switch runtime.GOOS { case "plan9": t.Skipf("skipping test on %q", runtime.GOOS) - case "windows": - t.Skipf("skipping test on %q, see issue 5971", runtime.GOOS) } defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(maxProcs)) @@ -453,6 +452,7 @@ }() for _, timeout := range []time.Duration{ + /* 1 * time.Nanosecond, 2 * time.Nanosecond, 5 * time.Nanosecond, @@ -466,6 +466,7 @@ 25 * time.Microsecond, 250 * time.Microsecond, 500 * time.Microsecond, + */ 1 * time.Millisecond, 5 * time.Millisecond, 100 * time.Millisecond, @@ -481,6 +482,8 @@ } } for run := 0; run < numRuns; run++ { + io.Log.SetStart() + Printf("%v run %d/%d", timeout, run+1, numRuns) name := fmt.Sprintf("%v run %d/%d", timeout, run+1, numRuns) t.Log(name) @@ -491,7 +494,9 @@ clientc := make(chan copyRes) go func() { t0 := time.Now() - c.SetDeadline(t0.Add(timeout)) + tend := t0.Add(timeout) + Printf("SetDeadline(%d)", tend.UnixNano()) + c.SetDeadline(tend) n, err := io.Copy(ioutil.Discard, c) d := time.Since(t0) c.Close() @@ -507,6 +512,8 @@ t.Fatalf("for %v: client Copy = %d, %v (want timeout)", name, res.n, res.err) } case <-time.After(tooLong): + io.Log.Dump(os.Stdout) + panic("ALEX") t.Fatalf("for %v: timeout (%v) waiting for client to timeout (%v) reading", name, tooLong, timeout) } diff --git a/src/pkg/runtime/netpoll.goc b/src/pkg/runtime/netpoll.goc --- a/src/pkg/runtime/netpoll.goc +++ b/src/pkg/runtime/netpoll.goc @@ -131,6 +131,8 @@ } func runtime_pollSetDeadline(pd *PollDesc, d int64, mode int) { + int64 now; + runtime·lock(pd); if(pd->closing) goto ret; @@ -145,14 +147,18 @@ pd->wt.fv = nil; } // Setup new timers. - if(d != 0 && d <= runtime·nanotime()) { - d = -1; + if(d != 0) { + now = runtime·nanotime(); + if(d <= now) { + d = -1; + } } if(mode == 'r' || mode == 'r'+'w') pd->rd = d; if(mode == 'w' || mode == 'r'+'w') pd->wd = d; if(pd->rd > 0 && pd->rd == pd->wd) { + //runtime·printf("netpoll: will deadline at %D (now=%D)\n", pd->rd, now); pd->rt.fv = &deadlineFn; pd->rt.when = pd->rd; // Copy current seq into the timer arg. @@ -329,6 +335,7 @@ static void deadline(int64 now, Eface arg) { + runtime·printf("netpoll: deadline (now=%D)\n", now); deadlineimpl(now, arg, true, true); } diff --git a/src/pkg/runtime/netpoll_windows.c b/src/pkg/runtime/netpoll_windows.c --- a/src/pkg/runtime/netpoll_windows.c +++ b/src/pkg/runtime/netpoll_windows.c @@ -79,7 +79,7 @@ wait = INFINITE; if(!block) // TODO(brainman): should use 0 here instead, but scheduler hogs CPU - wait = 1; + wait = 0; // TODO(brainman): Need a loop here to fetch all pending notifications // (or at least a batch). Scheduler will behave better if is given // a batch of newly runnable goroutines. diff --git a/src/pkg/runtime/print.c b/src/pkg/runtime/print.c --- a/src/pkg/runtime/print.c +++ b/src/pkg/runtime/print.c @@ -5,7 +5,7 @@ #include "runtime.h" #include "type.h" -//static Lock debuglock; +static Lock debuglock; static void vprintf(int8*, byte*); @@ -71,7 +71,7 @@ uintptr arg, narg; byte *v; - //runtime·lock(&debuglock); + runtime·lock(&debuglock); lp = p = s; arg = 0; @@ -176,7 +176,7 @@ if(p > lp) gwrite(lp, p-lp); - //runtime·unlock(&debuglock); + runtime·unlock(&debuglock); } #pragma textflag 7