balance, backend: add balance logs for troubleshooting (#1034)

Author: djshow832

pkg/balance/router/group.go

@@ -284,6 +284,7 @@ func (g *Group) onCreateConn(backendInst BackendInst, conn RedirectableConn, suc
 	if succeed {
 		connWrapper := &connWrapper{
 			RedirectableConn: conn,
+			createTime:       time.Now(),
 			phase:            phaseNotRedirected,
 		}
 		g.addConn(backend, connWrapper)
@@ -407,6 +408,9 @@ func (g *Group) redirectConn(conn *connWrapper, fromBackend *backendWrapper, toB
 		zap.String("from", fromBackend.addr),
 		zap.String("to", toBackend.addr),
 	}
+	if !conn.lastRedirect.IsZero() {
+		fields = append(fields, zap.Duration("since_last_redirect", curTime.Sub(conn.lastRedirect)))
+	}
 	fields = append(fields, logFields...)
 	succeed := conn.Redirect(toBackend)
 	if succeed {

pkg/balance/router/router.go

@@ -211,5 +211,6 @@ type connWrapper struct {
 	redirectReason string
 	// Last redirect start time of this connection.
 	lastRedirect time.Time
+	createTime   time.Time
 	phase        connPhase
 }

pkg/proxy/backend/backend_conn_mgr.go

@@ -687,7 +687,7 @@ func (mgr *BackendConnManager) notifyRedirectResult(ctx context.Context, rs *red
 	} else {
 		err := eventReceiver.OnRedirectSucceed(rs.from, rs.to, mgr)
 		mgr.logger.Debug("redirect connection succeeds", zap.String("from", rs.from),
-			zap.String("to", rs.to), zap.NamedError("notify_err", err))
+			zap.String("to", rs.to), zap.Duration("lifetime", time.Since(mgr.createTime)), zap.NamedError("notify_err", err))
 	}
 }