diff --git a/examples/block-net/README.md b/examples/block-net/README.md new file mode 100644 index 0000000..329fb13 --- /dev/null +++ b/examples/block-net/README.md @@ -0,0 +1,26 @@ +# block-net + +This [program](./main.go) explores the [question](https://twitter.com/rogpeppe/status/1359202847708037124) whether network i/o (e.g. waiting on socket read/write operations) will show up in the [block profiler](../block.md) or not. + +The program does the following: + +1. Start a TCP server via `net.Listen()` and wait for a client using `l.Accept()`. +2. Sleep for 1s +3. Connect to the TCP server with a client using `net.Dial()`. +4. Let the server wait for a message from the client using `conn.Read()` +4. Sleep for 1s +5. Send a `"hello world"` message from the client to the server using `conn.Write()` +6. Server prints the message it received +7. Program exits + +Given this program and assuming the block profiler captures network i/o, we'd expect to capture two major blocking events: + +1. `l.Accept()` waiting for 1s before a client connects. +2. `conn.Read()` waiting for 1s before receiving a message from the client + +However, as you can see below, the block profiler [captures](./block.pb.gz) only `~12ms` of activity related to channel operations involved in the listen/dial process. The accept/read activity however remains completely invisible. + +![block-net](./block-net.png) + +This means that [block profiler](../block.md) is generally not able to give a good idea about goroutines that are waiting on network i/o. + diff --git a/examples/block-net/block-net.png b/examples/block-net/block-net.png new file mode 100644 index 0000000..2cc9f99 Binary files /dev/null and b/examples/block-net/block-net.png differ diff --git a/examples/block-net/block.pb.gz b/examples/block-net/block.pb.gz new file mode 100644 index 0000000..78781c1 Binary files /dev/null and b/examples/block-net/block.pb.gz differ diff --git a/examples/block-net/go.mod b/examples/block-net/go.mod new file mode 100644 index 0000000..9046aef --- /dev/null +++ b/examples/block-net/go.mod @@ -0,0 +1,5 @@ +module github.com/felixge/go-profiler-notes/examples/block-net + +go 1.15 + +require golang.org/x/sync v0.0.0-20201207232520-09787c993a3a diff --git a/examples/block-net/go.sum b/examples/block-net/go.sum new file mode 100644 index 0000000..5f7eb37 --- /dev/null +++ b/examples/block-net/go.sum @@ -0,0 +1,2 @@ +golang.org/x/sync v0.0.0-20201207232520-09787c993a3a h1:DcqTD9SDLc+1P/r1EmRBwnVsrOwW+kk2vWf9n+1sGhs= +golang.org/x/sync v0.0.0-20201207232520-09787c993a3a/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= diff --git a/examples/block-net/main.go b/examples/block-net/main.go new file mode 100644 index 0000000..760662a --- /dev/null +++ b/examples/block-net/main.go @@ -0,0 +1,86 @@ +package main + +import ( + "fmt" + "net" + "os" + "runtime" + "runtime/pprof" + "time" + + "golang.org/x/sync/errgroup" +) + +func main() { + if err := run(); err != nil { + fmt.Fprintln(os.Stderr, err) + os.Exit(1) + } +} + +func run() error { + runtime.SetBlockProfileRate(1) + + listening := make(chan struct{}) + g := &errgroup.Group{} + g.Go(func() error { + return server(listening) + }) + + <-listening + time.Sleep(time.Second) + + if err := client(); err != nil { + return err + } + if err := g.Wait(); err != nil { + return err + } + + f, err := os.Create("block.pb.gz") + if err != nil { + return err + } + defer f.Close() + if err := pprof.Lookup("block").WriteTo(f, 0); err != nil { + return err + } + return nil +} + +func server(listening chan struct{}) error { + l, err := net.Listen("tcp", "localhost:9090") + if err != nil { + return err + } + + listening <- struct{}{} + + conn, err := l.Accept() + if err != nil { + return err + } + fmt.Printf("[server] accepted: %v\n", conn) + buf := make([]byte, 1024) + n, err := conn.Read(buf) + if err != nil { + return err + } + buf = buf[:n] + fmt.Printf("[server] read: %s\n", buf) + return nil +} + +func client() error { + conn, err := net.Dial("tcp", "localhost:9090") + if err != nil { + return err + } + defer conn.Close() + + time.Sleep(time.Second) + + fmt.Printf("[client] connected: %v\n", conn) + _, err = conn.Write([]byte("hello world")) + return err +}