Add slow connection timings to vtgates

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)