diff --git a/go/mysql/server.go b/go/mysql/server.go index e6de1925974..00ec921e254 100644 --- a/go/mysql/server.go +++ b/go/mysql/server.go @@ -288,9 +288,19 @@ func (l *Listener) Accept() { } } +type handleTimings struct { + accept time.Time + handleStart time.Duration + handlerDone time.Duration + handshakeSent time.Duration + packetRead time.Duration +} + // handle is called in a go routine for each client connection. // FIXME(alainjobart) handle per-connection logs in a way that makes sense. func (l *Listener) handle(conn net.Conn, connectionID uint32, acceptTime time.Time) { + cnxnTimings := handleTimings{accept: acceptTime} + cnxnTimings.handleStart = time.Since(acceptTime) if l.connReadTimeout != 0 || l.connWriteTimeout != 0 { conn = netutil.NewConnWithTimeouts(conn, l.connReadTimeout, l.connWriteTimeout) } @@ -313,6 +323,8 @@ func (l *Listener) handle(conn net.Conn, connectionID uint32, acceptTime time.Ti l.handler.NewConnection(c) defer l.handler.ConnectionClosed(c) + cnxnTimings.handlerDone = time.Since(acceptTime) + // Adjust the count of open connections defer connCount.Add(-1) @@ -325,6 +337,8 @@ func (l *Listener) handle(conn net.Conn, connectionID uint32, acceptTime time.Ti return } + cnxnTimings.handshakeSent = time.Since(acceptTime) + // Wait for the client response. This has to be a direct read, // so we don't buffer the TLS negotiation packets. response, err := c.readEphemeralPacketDirect() @@ -335,6 +349,13 @@ func (l *Listener) handle(conn net.Conn, connectionID uint32, acceptTime time.Ti } return } + + cnxnTimings.packetRead = time.Since(acceptTime) + + if cnxnTimings.packetRead > time.Millisecond*10 { + log.Warningf("Slow connection setup %s: %+v", c, cnxnTimings) + } + user, authMethod, authResponse, err := l.parseClientHandshakePacket(c, true, response) if err != nil { log.Errorf("Cannot parse client handshake response from %s: %v", c, err)