From 1a878c9a52c13e71838717ed28bbdf997b56efc1 Mon Sep 17 00:00:00 2001 From: Connor Date: Mon, 15 Jan 2018 13:08:59 +0800 Subject: [PATCH] scheduler: add debug log (#907) (#917) * scheduler: add debug log (#907) --- pdctl/command/log_command.go | 62 +++++++++++++++++++++++++++++ pdctl/ctl.go | 1 + pkg/logutil/log.go | 5 ++- pkg/logutil/log_test.go | 14 +++---- server/api/log.go | 57 ++++++++++++++++++++++++++ server/api/router.go | 3 ++ server/schedule/filters.go | 3 ++ server/schedulers/balance_leader.go | 2 + server/schedulers/balance_region.go | 2 + server/schedulers/utils.go | 9 +++++ server/server.go | 5 +++ 11 files changed, 154 insertions(+), 9 deletions(-) create mode 100644 pdctl/command/log_command.go create mode 100644 server/api/log.go diff --git a/pdctl/command/log_command.go b/pdctl/command/log_command.go new file mode 100644 index 00000000000..a84cd58bb36 --- /dev/null +++ b/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!") +} diff --git a/pdctl/ctl.go b/pdctl/ctl.go index 3e081fe275f..df039489dc8 100644 --- a/pdctl/ctl.go +++ b/pdctl/ctl.go @@ -51,6 +51,7 @@ func init() { command.NewClusterCommand(), command.NewTableNamespaceCommand(), command.NewHealthCommand(), + command.NewLogCommand(), ) cobra.EnablePrefixMatching = true } diff --git a/pkg/logutil/log.go b/pkg/logutil/log.go index ddace9d3cb9..214cafeb34f 100644 --- a/pkg/logutil/log.go +++ b/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 == "" { diff --git a/pkg/logutil/log_test.go b/pkg/logutil/log_test.go index f78da4d3dcb..085f09ed089 100644 --- a/pkg/logutil/log_test.go +++ b/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. diff --git a/server/api/log.go b/server/api/log.go new file mode 100644 index 00000000000..9c60c6b7638 --- /dev/null +++ b/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) +} diff --git a/server/api/router.go b/server/api/router.go index 01591d093c9..567361bc408 100644 --- a/server/api/router.go +++ b/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 } diff --git a/server/schedule/filters.go b/server/schedule/filters.go index 48a0a692cec..080152c6caa 100644 --- a/server/schedule/filters.go +++ b/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 } } diff --git a/server/schedulers/balance_leader.go b/server/schedulers/balance_leader.go index ba940347531..9fc82a4aff5 100644 --- a/server/schedulers/balance_leader.go +++ b/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 diff --git a/server/schedulers/balance_region.go b/server/schedulers/balance_region.go index d8d38ec2795..f05e41f06b7 100644 --- a/server/schedulers/balance_region.go +++ b/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 diff --git a/server/schedulers/utils.go b/server/schedulers/utils.go index 12e9c6fae01..0a7f14bc63b 100644 --- a/server/schedulers/utils.go +++ b/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) } diff --git a/server/server.go b/server/server.go index ecb851acbf0..33151cc9b06 100644 --- a/server/server.go +++ b/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 +}