scheduler: add debug log (#907) (#917)

* scheduler: add debug log (#907)

pdctl/command/log_command.go

@@ -0,0 +1,62 @@
+// Copyright 2018 PingCAP, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package command
+
+import (
+	"bytes"
+	"encoding/json"
+	"fmt"
+	"net/http"
+
+	"github.com/spf13/cobra"
+)
+
+var (
+	logPrefix = "pd/api/v1/log"
+)
+
+// NewLogCommand New a log subcommand of the rootCmd
+func NewLogCommand() *cobra.Command {
+	conf := &cobra.Command{
+		Use:   "log [fatal|error|warn|info|debug]",
+		Short: "set log level",
+		Run:   logCommandFunc,
+	}
+	return conf
+}
+
+func logCommandFunc(cmd *cobra.Command, args []string) {
+	var err error
+	if len(args) != 1 {
+		fmt.Println(cmd.UsageString())
+		return
+	}
+
+	data, err := json.Marshal(args[0])
+	if err != nil {
+		fmt.Printf("Failed to set log level: %s\n", err)
+		return
+	}
+	req, err := getRequest(cmd, logPrefix, http.MethodPost, "application/json", bytes.NewBuffer(data))
+	if err != nil {
+		fmt.Printf("Failed to set log level: %s\n", err)
+		return
+	}
+	_, err = dail(req)
+	if err != nil {
+		fmt.Printf("Failed to set log level: %s\n", err)
+		return
+	}
+	fmt.Println("Success!")
+}

pdctl/ctl.go

@@ -51,6 +51,7 @@ func init() {
 		command.NewClusterCommand(),
 		command.NewTableNamespaceCommand(),
 		command.NewHealthCommand(),
+		command.NewLogCommand(),
 	)
 	cobra.EnablePrefixMatching = true
 }

pkg/logutil/log.go

@@ -124,7 +124,8 @@ func (hook *contextHook) Levels() []log.Level {
 	return log.AllLevels
 }
 
-func stringToLogLevel(level string) log.Level {
+// StringToLogLevel translates log level string to log level.
+func StringToLogLevel(level string) log.Level {
 	switch strings.ToLower(level) {
 	case "fatal":
 		return log.FatalLevel
@@ -221,7 +222,7 @@ var once sync.Once
 func InitLogger(cfg *LogConfig) error {
 	var err error
 	once.Do(func() {
-		log.SetLevel(stringToLogLevel(cfg.Level))
+		log.SetLevel(StringToLogLevel(cfg.Level))
 		log.AddHook(&contextHook{})
 
 		if cfg.Format == "" {

pkg/logutil/log_test.go

@@ -42,13 +42,13 @@ func (s *testLogSuite) SetUpSuite(c *C) {
 }
 
 func (s *testLogSuite) TestStringToLogLevel(c *C) {
-	c.Assert(stringToLogLevel("fatal"), Equals, log.FatalLevel)
-	c.Assert(stringToLogLevel("ERROR"), Equals, log.ErrorLevel)
-	c.Assert(stringToLogLevel("warn"), Equals, log.WarnLevel)
-	c.Assert(stringToLogLevel("warning"), Equals, log.WarnLevel)
-	c.Assert(stringToLogLevel("debug"), Equals, log.DebugLevel)
-	c.Assert(stringToLogLevel("info"), Equals, log.InfoLevel)
-	c.Assert(stringToLogLevel("whatever"), Equals, log.InfoLevel)
+	c.Assert(StringToLogLevel("fatal"), Equals, log.FatalLevel)
+	c.Assert(StringToLogLevel("ERROR"), Equals, log.ErrorLevel)
+	c.Assert(StringToLogLevel("warn"), Equals, log.WarnLevel)
+	c.Assert(StringToLogLevel("warning"), Equals, log.WarnLevel)
+	c.Assert(StringToLogLevel("debug"), Equals, log.DebugLevel)
+	c.Assert(StringToLogLevel("info"), Equals, log.InfoLevel)
+	c.Assert(StringToLogLevel("whatever"), Equals, log.InfoLevel)
 }
 
 // TestLogging assure log format and log redirection works.

server/api/log.go

@@ -0,0 +1,57 @@
+// Copyright 2018 PingCAP, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package api
+
+import (
+	"encoding/json"
+	"io/ioutil"
+	"net/http"
+
+	log "github.com/Sirupsen/logrus"
+	"github.com/pingcap/pd/pkg/logutil"
+	"github.com/pingcap/pd/server"
+	"github.com/unrolled/render"
+)
+
+type logHandler struct {
+	svr *server.Server
+	rd  *render.Render
+}
+
+func newlogHandler(svr *server.Server, rd *render.Render) *logHandler {
+	return &logHandler{
+		svr: svr,
+		rd:  rd,
+	}
+}
+
+func (h *logHandler) Handle(w http.ResponseWriter, r *http.Request) {
+	var level string
+	data, err := ioutil.ReadAll(r.Body)
+	r.Body.Close()
+	if err != nil {
+		h.rd.JSON(w, http.StatusInternalServerError, err.Error())
+		return
+	}
+	err = json.Unmarshal(data, &level)
+	if err != nil {
+		h.rd.JSON(w, http.StatusInternalServerError, err.Error())
+		return
+	}
+
+	h.svr.SetLogLevel(level)
+	log.SetLevel(logutil.StringToLogLevel(level))
+
+	h.rd.JSON(w, http.StatusOK, nil)
+}

server/api/router.go

@@ -95,6 +95,9 @@ func createRouter(prefix string, svr *server.Server) *mux.Router {
 	classifierHandler := newClassifierHandler(svr, rd, classifierPrefix)
 	router.PathPrefix("/api/v1/classifier/").Handler(classifierHandler)
 
+	logHanler := newlogHandler(svr, rd)
+	router.HandleFunc("/api/v1/log", logHanler.Handle).Methods("POST")
+
 	router.HandleFunc("/ping", func(w http.ResponseWriter, r *http.Request) {}).Methods("GET")
 	return router
 }

server/schedule/filters.go

@@ -14,6 +14,7 @@
 package schedule
 
 import (
+	log "github.com/Sirupsen/logrus"
 	"github.com/pingcap/pd/server/cache"
 	"github.com/pingcap/pd/server/core"
 	"github.com/pingcap/pd/server/namespace"
@@ -31,6 +32,7 @@ type Filter interface {
 func FilterSource(store *core.StoreInfo, filters []Filter) bool {
 	for _, filter := range filters {
 		if filter.FilterSource(store) {
+			log.Debugf("[filter %T] filters store %v from source", filter, store)
 			return true
 		}
 	}
@@ -41,6 +43,7 @@ func FilterSource(store *core.StoreInfo, filters []Filter) bool {
 func FilterTarget(store *core.StoreInfo, filters []Filter) bool {
 	for _, filter := range filters {
 		if filter.FilterTarget(store) {
+			log.Debugf("[filter %T] filters store %v from target", filter, store)
 			return true
 		}
 	}

server/schedulers/balance_leader.go

@@ -16,6 +16,7 @@ package schedulers
 import (
 	"time"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/pingcap/pd/server/core"
 	"github.com/pingcap/pd/server/schedule"
 )
@@ -86,6 +87,7 @@ func (l *balanceLeaderScheduler) Schedule(cluster schedule.Cluster) *schedule.Op
 
 	source := cluster.GetStore(region.Leader.GetStoreId())
 	target := cluster.GetStore(newLeader.GetStoreId())
+	log.Debugf("[region %d] source store id is %v, target store id is %v", region.GetId(), source.GetId(), target.GetId())
 	if !shouldBalance(source, target, l.GetResourceKind()) {
 		schedulerCounter.WithLabelValues(l.GetName(), "skip").Inc()
 		return nil

server/schedulers/balance_region.go

@@ -16,6 +16,7 @@ package schedulers
 import (
 	"time"
 
+	log "github.com/Sirupsen/logrus"
 	"github.com/pingcap/kvproto/pkg/metapb"
 	"github.com/pingcap/pd/server/cache"
 	"github.com/pingcap/pd/server/core"
@@ -125,6 +126,7 @@ func (s *balanceRegionScheduler) transferPeer(cluster schedule.Cluster, region *
 	}
 
 	target := cluster.GetStore(newPeer.GetStoreId())
+	log.Debugf("[region %d] source store id is %v, target store id is %v", region.GetId(), source.GetId(), target.GetId())
 	if !shouldBalance(source, target, s.GetResourceKind()) {
 		schedulerCounter.WithLabelValues(s.GetName(), "skip").Inc()
 		return nil

server/schedulers/utils.go

@@ -39,6 +39,7 @@ func scheduleTransferLeader(cluster schedule.Cluster, schedulerName string, s sc
 
 	mostLeaderStore := s.SelectSource(stores, filters...)
 	leastLeaderStore := s.SelectTarget(stores, filters...)
+	log.Debugf("[%s] mostLeaderStore is %v, leastLeaderStore is %v", schedulerName, mostLeaderStore, leastLeaderStore)
 
 	var mostLeaderDistance, leastLeaderDistance float64
 	if mostLeaderStore != nil {
@@ -47,6 +48,7 @@ func scheduleTransferLeader(cluster schedule.Cluster, schedulerName string, s sc
 	if leastLeaderStore != nil {
 		leastLeaderDistance = math.Abs(leastLeaderStore.LeaderScore() - averageLeader)
 	}
+	log.Debugf("[%s] mostLeaderDistance is %v, leastLeaderDistance is %v", schedulerName, mostLeaderDistance, leastLeaderDistance)
 	if mostLeaderDistance == 0 && leastLeaderDistance == 0 {
 		schedulerCounter.WithLabelValues(schedulerName, "already_balanced").Inc()
 		return nil, nil
@@ -63,6 +65,11 @@ func scheduleTransferLeader(cluster schedule.Cluster, schedulerName string, s sc
 			region, peer = scheduleRemoveLeader(cluster, schedulerName, mostLeaderStore.GetId(), s)
 		}
 	}
+	if region == nil {
+		log.Debugf("[%v] select no region", schedulerName)
+	} else {
+		log.Debugf("[region %v][%v] select %v to be new leader", region.GetId(), schedulerName, peer)
+	}
 	return region, peer
 }
 
@@ -176,10 +183,12 @@ func shouldBalance(source, target *core.StoreInfo, kind core.ResourceKind) bool
 	sourceScore := source.ResourceScore(kind)
 	targetScore := target.ResourceScore(kind)
 	if targetScore >= sourceScore {
+		log.Debugf("should balance return false cause targetScore %v >= sourceScore %v", targetScore, sourceScore)
 		return false
 	}
 	diffRatio := 1 - targetScore/sourceScore
 	diffCount := diffRatio * float64(sourceCount)
+	log.Debugf("count diff is %v and balance diff is %v", diffCount, minBalanceDiff(sourceCount))
 	return diffCount >= minBalanceDiff(sourceCount)
 }
 

server/server.go

@@ -345,3 +345,8 @@ func (s *Server) txn() clientv3.Txn {
 func (s *Server) leaderTxn(cs ...clientv3.Cmp) clientv3.Txn {
 	return s.txn().If(append(cs, s.leaderCmp())...)
 }
+
+// SetLogLevel sets log level.
+func (s *Server) SetLogLevel(level string) {
+	s.cfg.Log.Level = level
+}