Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

*: support write slow query log into seperate files #4804

Merged
merged 6 commits into from Oct 20, 2017
Merged

*: support write slow query log into seperate files #4804

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
becb627
*: support write slow query log into seperate files
tiancaiamao Oct 17, 2017
bfadb48
Merge branch 'master' into slow-log
tiancaiamao Oct 18, 2017
88c4845
address comment
tiancaiamao Oct 18, 2017
57dd913
Merge branch 'master' into slow-log
tiancaiamao Oct 20, 2017
6887ecd
address comment
tiancaiamao Oct 20, 2017
767b63d
Merge branch 'master' into slow-log
tiancaiamao Oct 20, 2017
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
2 changes: 1 addition & 1 deletion cmd/benchdb/main.go
View file
Open in desktop
Expand Up @@ -22,11 +22,11 @@ import (
"time"

log "github.com/Sirupsen/logrus"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb"
"github.com/pingcap/tidb/kv"
"github.com/pingcap/tidb/store/tikv"
"github.com/pingcap/tidb/terror"
"github.com/pingcap/tidb/util/logutil"
"golang.org/x/net/context"
)

Expand Down
2 changes: 1 addition & 1 deletion cmd/benchfilesort/main.go
View file
Open in desktop
Expand Up @@ -26,11 +26,11 @@ import (

log "github.com/Sirupsen/logrus"
"github.com/juju/errors"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb/sessionctx/variable"
"github.com/pingcap/tidb/terror"
"github.com/pingcap/tidb/util/codec"
"github.com/pingcap/tidb/util/filesort"
"github.com/pingcap/tidb/util/logutil"
"github.com/pingcap/tidb/util/types"
)

Expand Down
9 changes: 5 additions & 4 deletions config/config.go
View file
Open in desktop
Expand Up @@ -16,7 +16,7 @@ package config
import (
"github.com/BurntSushi/toml"
"github.com/juju/errors"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb/util/logutil"
)

// Config contains configuration options.
Expand Down Expand Up @@ -50,9 +50,9 @@ type Log struct {
// File log config.
File logutil.FileLogConfig `toml:"file" json:"file"`

SlowThreshold int `toml:"slow-threshold" json:"slow-threshold"`

QueryLogMaxLen int `toml:"query-log-max-len" json:"query-log-max-len"`
SlowQueryFile string `toml:"slow-query-file" json:"slow-query-file"`
SlowThreshold int `toml:"slow-threshold" json:"slow-threshold"`
QueryLogMaxLen int `toml:"query-log-max-len" json:"query-log-max-len"`
}

// Security is the security section of the config.
Expand Down Expand Up @@ -164,5 +164,6 @@ func (l *Log) ToLogConfig() *logutil.LogConfig {
Format: l.Format,
DisableTimestamp: l.DisableTimestamp,
File: l.File,
SlowQueryFile: l.SlowQueryFile,
}
}
3 changes: 3 additions & 0 deletions config/config.toml.example
View file
Open in desktop
Expand Up @@ -37,6 +37,9 @@ format = "text"
# Disable automatic timestamps in output
disable-timestamp = false

# Stores slow query log into seperate files.
#slow-query-file = ""
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Remove #?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should not set it by default, merge the output of slow query to standard log will be helpful for debugging.


# Queries with execution time greater than this value will be logged. (Milliseconds)
slow-threshold = 300

Expand Down
2 changes: 1 addition & 1 deletion ddl/ddl_test.go
View file
Open in desktop
Expand Up @@ -21,7 +21,6 @@ import (

"github.com/coreos/etcd/clientv3"
. "github.com/pingcap/check"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb/ast"
"github.com/pingcap/tidb/context"
"github.com/pingcap/tidb/infoschema"
Expand All @@ -30,6 +29,7 @@ import (
"github.com/pingcap/tidb/model"
"github.com/pingcap/tidb/store/localstore"
"github.com/pingcap/tidb/store/localstore/goleveldb"
"github.com/pingcap/tidb/util/logutil"
"github.com/pingcap/tidb/util/mock"
"github.com/pingcap/tidb/util/types"
goctx "golang.org/x/net/context"
Expand Down
6 changes: 4 additions & 2 deletions executor/adapter.go
View file
Open in desktop
Expand Up @@ -30,6 +30,7 @@ import (
"github.com/pingcap/tidb/plan"
"github.com/pingcap/tidb/sessionctx/variable"
"github.com/pingcap/tidb/terror"
"github.com/pingcap/tidb/util/logutil"
)

type processinfoSetter interface {
Expand Down Expand Up @@ -277,11 +278,12 @@ func (a *ExecStmt) logSlowQuery() {
sql = fmt.Sprintf("%.*q(len:%d)", cfg.Log.QueryLogMaxLen, sql, len(a.Text))
}
connID := a.ctx.GetSessionVars().ConnectionID
logEntry := log.WithFields(log.Fields{
logEntry := log.NewEntry(logutil.SlowQueryLogger)
logEntry.Data = log.Fields{
"connectionId": connID,
"costTime": costTime,
"sql": sql,
})
}
if costTime < time.Duration(cfg.Log.SlowThreshold)*time.Millisecond {
logEntry.WithField("type", "query").Debugf("query")
} else {
Expand Down
2 changes: 1 addition & 1 deletion executor/executor_test.go
View file
Open in desktop
Expand Up @@ -24,7 +24,6 @@ import (
"github.com/juju/errors"
. "github.com/pingcap/check"
pb "github.com/pingcap/kvproto/pkg/kvrpcpb"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb"
"github.com/pingcap/tidb/context"
"github.com/pingcap/tidb/domain"
Expand All @@ -41,6 +40,7 @@ import (
"github.com/pingcap/tidb/store/tikv/tikvrpc"
"github.com/pingcap/tidb/terror"
"github.com/pingcap/tidb/util/admin"
"github.com/pingcap/tidb/util/logutil"
"github.com/pingcap/tidb/util/testkit"
"github.com/pingcap/tidb/util/testleak"
"github.com/pingcap/tidb/util/testutil"
Expand Down
2 changes: 1 addition & 1 deletion server/server_test.go
View file
Open in desktop
Expand Up @@ -28,9 +28,9 @@ import (
log "github.com/Sirupsen/logrus"
"github.com/go-sql-driver/mysql"
. "github.com/pingcap/check"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb/executor"
tmysql "github.com/pingcap/tidb/mysql"
"github.com/pingcap/tidb/util/logutil"
"github.com/pingcap/tidb/util/printer"
)

Expand Down
2 changes: 1 addition & 1 deletion sessionctx/binloginfo/binloginfo_test.go
View file
Open in desktop
Expand Up @@ -22,14 +22,14 @@ import (
"time"

. "github.com/pingcap/check"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb"
"github.com/pingcap/tidb/context"
"github.com/pingcap/tidb/ddl"
"github.com/pingcap/tidb/kv"
"github.com/pingcap/tidb/sessionctx"
"github.com/pingcap/tidb/store/tikv"
"github.com/pingcap/tidb/util/codec"
"github.com/pingcap/tidb/util/logutil"
"github.com/pingcap/tidb/util/testkit"
"github.com/pingcap/tidb/util/types"
"github.com/pingcap/tipb/go-binlog"
Expand Down
2 changes: 1 addition & 1 deletion store/store_test.go
View file
Open in desktop
Expand Up @@ -23,12 +23,12 @@ import (
"testing"

. "github.com/pingcap/check"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb"
"github.com/pingcap/tidb/kv"
"github.com/pingcap/tidb/store/localstore"
"github.com/pingcap/tidb/store/localstore/boltdb"
"github.com/pingcap/tidb/store/localstore/goleveldb"
"github.com/pingcap/tidb/util/logutil"
"github.com/pingcap/tidb/util/testleak"
)

Expand Down
2 changes: 1 addition & 1 deletion tidb-server/main.go
View file
Open in desktop
Expand Up @@ -26,7 +26,6 @@ import (

log "github.com/Sirupsen/logrus"
"github.com/juju/errors"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb"
"github.com/pingcap/tidb/config"
"github.com/pingcap/tidb/ddl"
Expand All @@ -40,6 +39,7 @@ import (
"github.com/pingcap/tidb/store/localstore/boltdb"
"github.com/pingcap/tidb/store/tikv"
"github.com/pingcap/tidb/terror"
"github.com/pingcap/tidb/util/logutil"
"github.com/pingcap/tidb/util/printer"
"github.com/pingcap/tidb/util/systimemon"
"github.com/pingcap/tidb/x-server"
Expand Down
2 changes: 1 addition & 1 deletion tidb_test.go
View file
Open in desktop
Expand Up @@ -25,11 +25,11 @@ import (

"github.com/juju/errors"
. "github.com/pingcap/check"
"github.com/pingcap/pd/pkg/logutil"
"github.com/pingcap/tidb/ast"
"github.com/pingcap/tidb/domain"
"github.com/pingcap/tidb/kv"
"github.com/pingcap/tidb/util/auth"
"github.com/pingcap/tidb/util/logutil"
"github.com/pingcap/tidb/util/testleak"
"github.com/pingcap/tidb/util/types"
)
Expand Down
72 changes: 29 additions & 43 deletions .../github.com/pingcap/pd/pkg/logutil/log.go → util/logutil/log.go
View file
Open in desktop
Expand Up @@ -22,7 +22,6 @@ import (
"strings"

log "github.com/Sirupsen/logrus"
"github.com/coreos/pkg/capnslog"
"github.com/juju/errors"
lumberjack "gopkg.in/natefinch/lumberjack.v2"
)
Expand Down Expand Up @@ -58,38 +57,10 @@ type LogConfig struct {
DisableTimestamp bool `toml:"disable-timestamp" json:"disable-timestamp"`
// File log config.
File FileLogConfig `toml:"file" json:"file"`
// SlowQueryFile filename, default to File log config on empty.
SlowQueryFile string
}

// redirectFormatter will redirect etcd logs to logrus logs.
type redirectFormatter struct{}

// Format implements capnslog.Formatter hook.
func (rf *redirectFormatter) Format(pkg string, level capnslog.LogLevel, depth int, entries ...interface{}) {
if pkg != "" {
pkg = fmt.Sprint(pkg, ": ")
}

logStr := fmt.Sprint(pkg, entries)

switch level {
case capnslog.CRITICAL:
log.Fatalf(logStr)
case capnslog.ERROR:
log.Errorf(logStr)
case capnslog.WARNING:
log.Warningf(logStr)
case capnslog.NOTICE:
log.Infof(logStr)
case capnslog.INFO:
log.Infof(logStr)
case capnslog.DEBUG, capnslog.TRACE:
log.Debugf(logStr)
}
}

// Flush only for implementing Formatter.
func (rf *redirectFormatter) Flush() {}

// isSKippedPackageName tests wether path name is on log library calling stack.
func isSkippedPackageName(name string) bool {
return strings.Contains(name, "github.com/Sirupsen/logrus") ||
Expand Down Expand Up @@ -190,8 +161,8 @@ func stringToLogFormatter(format string, disableTimestamp bool) log.Formatter {
}
}

// InitFileLog initializes file based logging options.
func InitFileLog(cfg *FileLogConfig) error {
// initFileLog initializes file based logging options.
func initFileLog(cfg *FileLogConfig, logger *log.Logger) error {
if st, err := os.Stat(cfg.Filename); err == nil {
if st.IsDir() {
return errors.New("can't use directory as log file name")
Expand All @@ -210,10 +181,17 @@ func InitFileLog(cfg *FileLogConfig) error {
LocalTime: true,
}

log.SetOutput(output)
if logger == nil {
log.SetOutput(output)
} else {
logger.Out = output
}
return nil
}

// SlowQueryLogger is used to log slow query, InitLogger will modify it according to config file.
var SlowQueryLogger = log.StandardLogger()

// InitLogger initalizes PD's logger.
func InitLogger(cfg *LogConfig) error {
log.SetLevel(stringToLogLevel(cfg.Level))
Expand All @@ -222,18 +200,26 @@ func InitLogger(cfg *LogConfig) error {
if cfg.Format == "" {
cfg.Format = defaultLogFormat
}
log.SetFormatter(stringToLogFormatter(cfg.Format, cfg.DisableTimestamp))
formatter := stringToLogFormatter(cfg.Format, cfg.DisableTimestamp)
log.SetFormatter(formatter)

// etcd log
capnslog.SetFormatter(&redirectFormatter{})

if len(cfg.File.Filename) == 0 {
return nil
if len(cfg.File.Filename) != 0 {
if err := initFileLog(&cfg.File, nil); err != nil {
return errors.Trace(err)
}
}

err := InitFileLog(&cfg.File)
if err != nil {
return errors.Trace(err)
if len(cfg.SlowQueryFile) != 0 {
SlowQueryLogger = log.New()
tmp := cfg.File
tmp.Filename = cfg.SlowQueryFile
if err := initFileLog(&tmp, SlowQueryLogger); err != nil {
return errors.Trace(err)
}
hooks := make(log.LevelHooks)
hooks.Add(&contextHook{})
SlowQueryLogger.Hooks = hooks
SlowQueryLogger.Formatter = formatter
}

return nil
Expand Down