From 99ea5ad005091025f1c6975de5a0733587180862 Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Thu, 17 Dec 2015 14:05:37 +0800 Subject: [PATCH 1/6] kv: make it possible to turn off transaction debug log. Transaction logs too much entries in debug level, it's overwhelming and obscures other debug level messages. When we don't care about transaction log, we should be able to turn it off. --- kv/txn.go | 5 +++++ store/hbase/txn.go | 36 +++++++++++++++++++++++++++--------- store/localstore/kv.go | 4 +++- store/localstore/txn.go | 32 ++++++++++++++++++++++++-------- tidb-server/main.go | 5 +++++ 5 files changed, 64 insertions(+), 18 deletions(-) diff --git a/kv/txn.go b/kv/txn.go index aa582ae337..f9e00277ed 100644 --- a/kv/txn.go +++ b/kv/txn.go @@ -96,3 +96,8 @@ func BackOff(attempts int) int { time.Sleep(sleep) return int(sleep) } + +// LogTxn is a switch for toggle debug level log for transaction. +var ( + LogTxn = true +) diff --git a/store/hbase/txn.go b/store/hbase/txn.go index 69dac89ba3..581618ada7 100644 --- a/store/hbase/txn.go +++ b/store/hbase/txn.go @@ -65,22 +65,30 @@ func newHbaseTxn(t themis.Txn, storeName string) *hbaseTxn { // Implement transaction interface func (txn *hbaseTxn) Get(k kv.Key) ([]byte, error) { - log.Debugf("get key:%q, txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("get key:%q, txn:%d", k, txn.tid) + } return txn.UnionStore.Get(k) } func (txn *hbaseTxn) Set(k kv.Key, v []byte) error { - log.Debugf("seek %q txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("seek %q txn:%d", k, txn.tid) + } return txn.UnionStore.Set(k, v) } func (txn *hbaseTxn) Inc(k kv.Key, step int64) (int64, error) { - log.Debugf("Inc %q, step %d txn:%d", k, step, txn.tid) + if kv.LogTxn { + log.Debugf("Inc %q, step %d txn:%d", k, step, txn.tid) + } return txn.UnionStore.Inc(k, step) } func (txn *hbaseTxn) GetInt64(k kv.Key) (int64, error) { - log.Debugf("GetInt64 %q, txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("GetInt64 %q, txn:%d", k, txn.tid) + } return txn.UnionStore.GetInt64(k) } @@ -89,7 +97,9 @@ func (txn *hbaseTxn) String() string { } func (txn *hbaseTxn) Seek(k kv.Key) (kv.Iterator, error) { - log.Debugf("seek %q txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("seek %q txn:%d", k, txn.tid) + } iter, err := txn.UnionStore.Seek(k) if err != nil { return nil, errors.Trace(err) @@ -98,7 +108,9 @@ func (txn *hbaseTxn) Seek(k kv.Key) (kv.Iterator, error) { } func (txn *hbaseTxn) Delete(k kv.Key) error { - log.Debugf("delete %q txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("delete %q txn:%d", k, txn.tid) + } err := txn.UnionStore.Delete(k) if err != nil { return errors.Trace(err) @@ -140,7 +152,9 @@ func (txn *hbaseTxn) doCommit() error { } txn.version = kv.NewVersion(txn.txn.GetCommitTS()) - log.Debugf("commit successfully, txn.version:%d", txn.version.Ver) + if kv.LogTxn { + log.Debugf("commit successfully, txn.version:%d", txn.version.Ver) + } return nil } @@ -148,7 +162,9 @@ func (txn *hbaseTxn) Commit() error { if !txn.valid { return kv.ErrInvalidTxn } - log.Debugf("start to commit txn %d", txn.tid) + if kv.LogTxn { + log.Debugf("start to commit txn %d", txn.tid) + } defer func() { txn.close() }() @@ -174,7 +190,9 @@ func (txn *hbaseTxn) Rollback() error { if !txn.valid { return kv.ErrInvalidTxn } - log.Warnf("Rollback txn %d", txn.tid) + if kv.LogTxn { + log.Warnf("Rollback txn %d", txn.tid) + } return txn.close() } diff --git a/store/localstore/kv.go b/store/localstore/kv.go index 10749b5c1e..ebcbe3e46b 100644 --- a/store/localstore/kv.go +++ b/store/localstore/kv.go @@ -164,7 +164,9 @@ func (s *dbStore) Begin() (kv.Transaction, error) { version: kv.MinVersion, snapshotVals: make(map[string]struct{}), } - log.Debugf("Begin txn:%d", txn.tid) + if kv.LogTxn { + log.Debugf("Begin txn:%d", txn.tid) + } txn.UnionStore = kv.NewUnionStore(newSnapshot(s, s.db, beginVer)) return txn, nil } diff --git a/store/localstore/txn.go b/store/localstore/txn.go index c448fe21e1..d25806eeed 100644 --- a/store/localstore/txn.go +++ b/store/localstore/txn.go @@ -50,7 +50,9 @@ func (txn *dbTxn) markOrigin(k []byte) { // Implement transaction interface func (txn *dbTxn) Get(k kv.Key) ([]byte, error) { - log.Debugf("get key:%q, txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("get key:%q, txn:%d", k, txn.tid) + } val, err := txn.UnionStore.Get(k) if err != nil { return nil, errors.Trace(err) @@ -60,7 +62,9 @@ func (txn *dbTxn) Get(k kv.Key) ([]byte, error) { } func (txn *dbTxn) Set(k kv.Key, data []byte) error { - log.Debugf("set key:%q, txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("set key:%q, txn:%d", k, txn.tid) + } err := txn.UnionStore.Set(k, data) if err != nil { return errors.Trace(err) @@ -71,7 +75,9 @@ func (txn *dbTxn) Set(k kv.Key, data []byte) error { } func (txn *dbTxn) Inc(k kv.Key, step int64) (int64, error) { - log.Debugf("Inc %q, step %d txn:%d", k, step, txn.tid) + if kv.LogTxn { + log.Debugf("Inc %q, step %d txn:%d", k, step, txn.tid) + } txn.markOrigin(k) val, err := txn.UnionStore.Inc(k, step) @@ -83,7 +89,9 @@ func (txn *dbTxn) Inc(k kv.Key, step int64) (int64, error) { } func (txn *dbTxn) GetInt64(k kv.Key) (int64, error) { - log.Debugf("GetInt64 %q, txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("GetInt64 %q, txn:%d", k, txn.tid) + } val, err := txn.UnionStore.GetInt64(k) if err != nil { return 0, errors.Trace(err) @@ -97,7 +105,9 @@ func (txn *dbTxn) String() string { } func (txn *dbTxn) Seek(k kv.Key) (kv.Iterator, error) { - log.Debugf("seek key:%q, txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("seek key:%q, txn:%d", k, txn.tid) + } iter, err := txn.UnionStore.Seek(k) if err != nil { return nil, errors.Trace(err) @@ -110,7 +120,9 @@ func (txn *dbTxn) Seek(k kv.Key) (kv.Iterator, error) { } func (txn *dbTxn) Delete(k kv.Key) error { - log.Debugf("delete key:%q, txn:%d", k, txn.tid) + if kv.LogTxn { + log.Debugf("delete key:%q, txn:%d", k, txn.tid) + } err := txn.UnionStore.Delete(k) if err != nil { return errors.Trace(err) @@ -177,7 +189,9 @@ func (txn *dbTxn) Commit() error { if !txn.valid { return errors.Trace(kv.ErrInvalidTxn) } - log.Infof("commit txn %d", txn.tid) + if kv.LogTxn { + log.Infof("commit txn %d", txn.tid) + } defer func() { txn.close() }() @@ -204,7 +218,9 @@ func (txn *dbTxn) Rollback() error { if !txn.valid { return errors.Trace(kv.ErrInvalidTxn) } - log.Warnf("Rollback txn %d", txn.tid) + if kv.LogTxn { + log.Warnf("Rollback txn %d", txn.tid) + } return txn.close() } diff --git a/tidb-server/main.go b/tidb-server/main.go index 4a9809b77b..c0ce795db7 100644 --- a/tidb-server/main.go +++ b/tidb-server/main.go @@ -24,6 +24,7 @@ import ( "github.com/ngaut/log" "github.com/pingcap/tidb" + "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/metric" "github.com/pingcap/tidb/tidb-server/server" "github.com/pingcap/tidb/util/printer" @@ -33,6 +34,7 @@ var ( store = flag.String("store", "goleveldb", "registered store name, [hbase, memory, goleveldb, boltdb]") storePath = flag.String("path", "/tmp/tidb", "tidb storage path") logLevel = flag.String("L", "debug", "log level: info, debug, warn, error, fatal") + logTxn = flag.String("LTxn", "true", "log transaction: true/false") port = flag.String("P", "4000", "mp server port") lease = flag.Int("lease", 1, "schema lease seconds, very dangerous to change only if you know what you do") ) @@ -54,6 +56,9 @@ func main() { Addr: fmt.Sprintf(":%s", *port), LogLevel: *logLevel, } + if *logTxn != "true" { + kv.LogTxn = false + } log.SetLevelByString(cfg.LogLevel) store, err := tidb.NewStore(fmt.Sprintf("%s://%s", *store, *storePath)) From 379f98ce6a78c0acc70c7361b52c6c6bb9a373e9 Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Thu, 17 Dec 2015 14:13:49 +0800 Subject: [PATCH 2/6] store: log rollback even if LogTxn is false --- store/hbase/txn.go | 4 +--- store/localstore/txn.go | 6 ++---- 2 files changed, 3 insertions(+), 7 deletions(-) diff --git a/store/hbase/txn.go b/store/hbase/txn.go index 581618ada7..4eacd390c6 100644 --- a/store/hbase/txn.go +++ b/store/hbase/txn.go @@ -190,9 +190,7 @@ func (txn *hbaseTxn) Rollback() error { if !txn.valid { return kv.ErrInvalidTxn } - if kv.LogTxn { - log.Warnf("Rollback txn %d", txn.tid) - } + log.Warnf("Rollback txn %d", txn.tid) return txn.close() } diff --git a/store/localstore/txn.go b/store/localstore/txn.go index d25806eeed..af94313885 100644 --- a/store/localstore/txn.go +++ b/store/localstore/txn.go @@ -190,7 +190,7 @@ func (txn *dbTxn) Commit() error { return errors.Trace(kv.ErrInvalidTxn) } if kv.LogTxn { - log.Infof("commit txn %d", txn.tid) + log.Debugf("commit txn %d", txn.tid) } defer func() { txn.close() @@ -218,9 +218,7 @@ func (txn *dbTxn) Rollback() error { if !txn.valid { return errors.Trace(kv.ErrInvalidTxn) } - if kv.LogTxn { - log.Warnf("Rollback txn %d", txn.tid) - } + log.Warnf("Rollback txn %d", txn.tid) return txn.close() } From 6fed01d83af53cf8d3de133c109315b8d04b7513 Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Thu, 17 Dec 2015 15:08:07 +0800 Subject: [PATCH 3/6] tide-server: address comment. --- tidb-server/main.go | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/tidb-server/main.go b/tidb-server/main.go index c0ce795db7..ba0d1b7943 100644 --- a/tidb-server/main.go +++ b/tidb-server/main.go @@ -34,7 +34,7 @@ var ( store = flag.String("store", "goleveldb", "registered store name, [hbase, memory, goleveldb, boltdb]") storePath = flag.String("path", "/tmp/tidb", "tidb storage path") logLevel = flag.String("L", "debug", "log level: info, debug, warn, error, fatal") - logTxn = flag.String("LTxn", "true", "log transaction: true/false") + logTxn = flag.Bool("log_txn", true, "log transaction: true/false") port = flag.String("P", "4000", "mp server port") lease = flag.Int("lease", 1, "schema lease seconds, very dangerous to change only if you know what you do") ) @@ -56,9 +56,7 @@ func main() { Addr: fmt.Sprintf(":%s", *port), LogLevel: *logLevel, } - if *logTxn != "true" { - kv.LogTxn = false - } + kv.LogTxn = *logTxn log.SetLevelByString(cfg.LogLevel) store, err := tidb.NewStore(fmt.Sprintf("%s://%s", *store, *storePath)) From e2d6910953513bdaec1ac470eee62d1a8c8e5cd6 Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Thu, 17 Dec 2015 16:54:33 +0800 Subject: [PATCH 4/6] interpreter: address comment. --- interpreter/main.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/interpreter/main.go b/interpreter/main.go index 2c6c9d9132..0a0a6a95a1 100644 --- a/interpreter/main.go +++ b/interpreter/main.go @@ -27,12 +27,14 @@ import ( "github.com/ngaut/log" "github.com/peterh/liner" "github.com/pingcap/tidb" + "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/terror" "github.com/pingcap/tidb/util/printer" ) var ( logLevel = flag.String("L", "error", "log level") + logTxn = flag.Bool("log_txn", true, "true/false, log transaction debug level message") store = flag.String("store", "goleveldb", "the name for the registered storage, e.g. hbase, memory, goleveldb, boltdb") dbPath = flag.String("dbpath", "test", "db path") dbName = flag.String("dbname", "test", "default db name") @@ -167,6 +169,7 @@ func main() { flag.Parse() log.SetLevelByString(*logLevel) + kv.LogTxn = *logTxn // support for signal notify runtime.GOMAXPROCS(runtime.NumCPU()) From 70078490adc1949da5cef91e9f850b82091017fe Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Thu, 17 Dec 2015 17:55:17 +0800 Subject: [PATCH 5/6] meta: toggle alloc id log. --- meta/autoid/autoid.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/meta/autoid/autoid.go b/meta/autoid/autoid.go index 132be1edfc..d926decb88 100644 --- a/meta/autoid/autoid.go +++ b/meta/autoid/autoid.go @@ -68,7 +68,9 @@ func (alloc *allocator) Alloc(tableID int64) (int64, error) { } alloc.base++ - log.Infof("Alloc id %d, table ID:%d, from %p, database ID:%d", alloc.base, tableID, alloc, alloc.dbID) + if kv.LogTxn { + log.Debugf("Alloc id %d, table ID:%d, from %p, database ID:%d", alloc.base, tableID, alloc, alloc.dbID) + } return alloc.base, nil } From 322476ca68341a8f0aaa24a72de286bf68ceac2a Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Thu, 17 Dec 2015 20:04:20 +0800 Subject: [PATCH 6/6] *: add tag to log message to make it easy to be filtered out. --- ddl/column.go | 2 +- ddl/ddl.go | 2 +- ddl/ddl_test.go | 2 +- ddl/index.go | 2 +- ddl/worker.go | 20 ++++++------- domain/domain.go | 12 ++++---- interpreter/main.go | 3 -- kv/txn.go | 11 ++----- kv/union_iter.go | 2 +- meta/autoid/autoid.go | 4 +-- store/hbase/txn.go | 34 ++++++---------------- store/localstore/compactor.go | 8 +++-- store/localstore/kv.go | 10 +++---- store/localstore/local_version_provider.go | 2 +- store/localstore/txn.go | 30 +++++-------------- tidb-server/main.go | 3 -- 16 files changed, 52 insertions(+), 95 deletions(-) diff --git a/ddl/column.go b/ddl/column.go index 933cd9eff5..4808121db6 100644 --- a/ddl/column.go +++ b/ddl/column.go @@ -336,7 +336,7 @@ func (d *ddl) backfillColumn(t table.Table, columnInfo *model.ColumnInfo, reorgI func (d *ddl) backfillColumnData(t table.Table, columnInfo *model.ColumnInfo, handles []int64, reorgInfo *reorgInfo) error { for _, handle := range handles { - log.Info("backfill column...", handle) + log.Info("[ddl] backfill column...", handle) err := kv.RunInNewTxn(d.store, true, func(txn kv.Transaction) error { if err := d.isReorgRunnable(txn); err != nil { diff --git a/ddl/ddl.go b/ddl/ddl.go index a2dcacfb8f..e97733ead7 100644 --- a/ddl/ddl.go +++ b/ddl/ddl.go @@ -193,7 +193,7 @@ func (d *ddl) SetLease(lease time.Duration) { return } - log.Warnf("change schema lease %s -> %s", d.lease, lease) + log.Warnf("[ddl] change schema lease %s -> %s", d.lease, lease) if d.isClosed() { // if already closed, just set lease and return diff --git a/ddl/ddl_test.go b/ddl/ddl_test.go index f2885b4d39..85b785731a 100644 --- a/ddl/ddl_test.go +++ b/ddl/ddl_test.go @@ -336,7 +336,7 @@ func (ts *testSuite) TestAlterTableColumn(c *C) { } func statement(ctx context.Context, sql string) stmt.Statement { - log.Debug("Compile", sql) + log.Debug("[ddl] Compile", sql) lexer := parser.NewLexer(sql) parser.YYParse(lexer) compiler := &executor.Compiler{} diff --git a/ddl/index.go b/ddl/index.go index 98d3b608e3..446ee00156 100644 --- a/ddl/index.go +++ b/ddl/index.go @@ -426,7 +426,7 @@ func (d *ddl) backfillTableIndex(t table.Table, indexInfo *model.IndexInfo, hand kvX := kv.NewKVIndex(t.IndexPrefix(), indexInfo.Name.L, indexInfo.ID, indexInfo.Unique) for _, handle := range handles { - log.Debug("building index...", handle) + log.Debug("[ddl] building index...", handle) err := kv.RunInNewTxn(d.store, true, func(txn kv.Transaction) error { if err := d.isReorgRunnable(txn); err != nil { diff --git a/ddl/worker.go b/ddl/worker.go index c53101123d..d914f68a88 100644 --- a/ddl/worker.go +++ b/ddl/worker.go @@ -51,7 +51,7 @@ func (d *ddl) startJob(ctx context.Context, job *model.Job) error { // notice worker that we push a new job and wait the job done. asyncNotify(d.jobCh) - log.Warnf("start DDL job %v", job) + log.Warnf("[ddl] start DDL job %v", job) jobID := job.ID @@ -69,10 +69,10 @@ func (d *ddl) startJob(ctx context.Context, job *model.Job) error { historyJob, err = d.getHistoryJob(jobID) if err != nil { - log.Errorf("get history job err %v, check again", err) + log.Errorf("[ddl] get history job err %v, check again", err) continue } else if historyJob == nil { - log.Warnf("job %d is not in history, maybe not run", jobID) + log.Warnf("[ddl] job %d is not in history, maybe not run", jobID) continue } @@ -129,11 +129,11 @@ func (d *ddl) checkOwner(t *meta.Meta) (*model.Owner, error) { if err = t.SetDDLOwner(owner); err != nil { return nil, errors.Trace(err) } - log.Debugf("become owner %s", owner.OwnerID) + log.Debugf("[ddl] become owner %s", owner.OwnerID) } if owner.OwnerID != d.uuid { - log.Debugf("not owner, owner is %s", owner.OwnerID) + log.Debugf("[ddl] not owner, owner is %s", owner.OwnerID) return nil, errors.Trace(ErrNotOwner) } @@ -152,7 +152,7 @@ func (d *ddl) updateJob(t *meta.Meta, job *model.Job) error { } func (d *ddl) finishJob(t *meta.Meta, job *model.Job) error { - log.Warnf("finish DDL job %v", job) + log.Warnf("[ddl] finish DDL job %v", job) // done, notice and run next job. _, err := t.DeQueueDDLJob() if err != nil { @@ -203,13 +203,13 @@ func (d *ddl) handleJobQueue() error { // wait again. elapsed := time.Duration(time.Now().UnixNano() - job.LastUpdateTS) if elapsed > 0 && elapsed < waitTime { - log.Warnf("the elapsed time from last update is %s < %s, wait again", elapsed, waitTime) + log.Warnf("[ddl] the elapsed time from last update is %s < %s, wait again", elapsed, waitTime) waitTime -= elapsed return nil } } - log.Warnf("run DDL job %v", job) + log.Warnf("[ddl] run DDL job %v", job) d.hook.OnJobRunBefore(job) @@ -281,7 +281,7 @@ func (d *ddl) onWorker() { for { select { case <-ticker.C: - log.Debugf("wait %s to check DDL status again", checkTime) + log.Debugf("[ddl] wait %s to check DDL status again", checkTime) case <-d.jobCh: case <-d.quitCh: return @@ -289,7 +289,7 @@ func (d *ddl) onWorker() { err := d.handleJobQueue() if err != nil { - log.Errorf("handle job err %v", errors.ErrorStack(err)) + log.Errorf("[ddl] handle job err %v", errors.ErrorStack(err)) } } } diff --git a/domain/domain.go b/domain/domain.go index 773969b4d1..1ac14b6fac 100644 --- a/domain/domain.go +++ b/domain/domain.go @@ -55,7 +55,7 @@ func (do *Domain) loadInfoSchema(txn kv.Transaction) (err error) { if info != nil && schemaMetaVersion <= info.SchemaMetaVersion() { // info may be changed by other txn, so here its version may be bigger than schema version, // so we don't need to reload. - log.Debugf("schema version is still %d, no need reload", schemaMetaVersion) + log.Debugf("[ddl] schema version is still %d, no need reload", schemaMetaVersion) return nil } @@ -85,7 +85,7 @@ func (do *Domain) loadInfoSchema(txn kv.Transaction) (err error) { } } - log.Infof("loadInfoSchema %d", schemaMetaVersion) + log.Infof("[ddl] loadInfoSchema %d", schemaMetaVersion) err = do.infoHandle.Set(schemas, schemaMetaVersion) return errors.Trace(err) } @@ -167,7 +167,7 @@ func (do *Domain) reload() error { } if err != nil { - log.Errorf("load schema err %v, retry again", errors.ErrorStack(err)) + log.Errorf("[ddl] load schema err %v, retry again", errors.ErrorStack(err)) // TODO: use a backoff algorithm. time.Sleep(500 * time.Millisecond) continue @@ -192,7 +192,7 @@ func (do *Domain) mustReload() { // if reload error, we will terminate whole program to guarantee data safe. err := do.reload() if err != nil { - log.Fatalf("reload schema err %v", errors.ErrorStack(err)) + log.Fatalf("[ddl] reload schema err %v", errors.ErrorStack(err)) } } @@ -216,7 +216,7 @@ func (do *Domain) loadSchemaInLoop(lease time.Duration) { if terror.ErrorEqual(err, localstore.ErrDBClosed) { return } else if err != nil { - log.Fatalf("reload schema err %v", errors.ErrorStack(err)) + log.Fatalf("[ddl] reload schema err %v", errors.ErrorStack(err)) } case newLease := <-do.leaseCh: if newLease <= 0 { @@ -245,7 +245,7 @@ func (c *ddlCallback) OnChanged(err error) error { if err != nil { return err } - log.Warnf("on DDL change") + log.Warnf("[ddl] on DDL change") c.do.mustReload() return nil diff --git a/interpreter/main.go b/interpreter/main.go index 0a0a6a95a1..2c6c9d9132 100644 --- a/interpreter/main.go +++ b/interpreter/main.go @@ -27,14 +27,12 @@ import ( "github.com/ngaut/log" "github.com/peterh/liner" "github.com/pingcap/tidb" - "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/terror" "github.com/pingcap/tidb/util/printer" ) var ( logLevel = flag.String("L", "error", "log level") - logTxn = flag.Bool("log_txn", true, "true/false, log transaction debug level message") store = flag.String("store", "goleveldb", "the name for the registered storage, e.g. hbase, memory, goleveldb, boltdb") dbPath = flag.String("dbpath", "test", "db path") dbName = flag.String("dbname", "test", "default db name") @@ -169,7 +167,6 @@ func main() { flag.Parse() log.SetLevelByString(*logLevel) - kv.LogTxn = *logTxn // support for signal notify runtime.GOMAXPROCS(runtime.NumCPU()) diff --git a/kv/txn.go b/kv/txn.go index f9e00277ed..2bf483970d 100644 --- a/kv/txn.go +++ b/kv/txn.go @@ -48,13 +48,13 @@ func RunInNewTxn(store Storage, retryable bool, f func(txn Transaction) error) e for i := 0; i < maxRetryCnt; i++ { txn, err := store.Begin() if err != nil { - log.Errorf("RunInNewTxn error - %v", err) + log.Errorf("[kv] RunInNewTxn error - %v", err) return errors.Trace(err) } err = f(txn) if retryable && IsRetryableError(err) { - log.Warnf("Retry txn %v", txn) + log.Warnf("[kv] Retry txn %v", txn) txn.Rollback() continue } @@ -64,7 +64,7 @@ func RunInNewTxn(store Storage, retryable bool, f func(txn Transaction) error) e err = txn.Commit() if retryable && IsRetryableError(err) { - log.Warnf("Retry txn %v", txn) + log.Warnf("[kv] Retry txn %v", txn) txn.Rollback() BackOff(i) continue @@ -96,8 +96,3 @@ func BackOff(attempts int) int { time.Sleep(sleep) return int(sleep) } - -// LogTxn is a switch for toggle debug level log for transaction. -var ( - LogTxn = true -) diff --git a/kv/union_iter.go b/kv/union_iter.go index f6d119db52..0ef4069b5a 100644 --- a/kv/union_iter.go +++ b/kv/union_iter.go @@ -102,7 +102,7 @@ func (iter *UnionIter) updateCur() { } else { // record from dirty comes first if len(iter.dirtyIt.Value()) == 0 { - log.Warnf("delete a record not exists? k = %q", iter.dirtyIt.Key()) + log.Warnf("[kv] delete a record not exists? k = %q", iter.dirtyIt.Key()) // jump over this deletion iter.dirtyNext() continue diff --git a/meta/autoid/autoid.go b/meta/autoid/autoid.go index d926decb88..45aeb3ff86 100644 --- a/meta/autoid/autoid.go +++ b/meta/autoid/autoid.go @@ -68,9 +68,7 @@ func (alloc *allocator) Alloc(tableID int64) (int64, error) { } alloc.base++ - if kv.LogTxn { - log.Debugf("Alloc id %d, table ID:%d, from %p, database ID:%d", alloc.base, tableID, alloc, alloc.dbID) - } + log.Debugf("[kv] Alloc id %d, table ID:%d, from %p, database ID:%d", alloc.base, tableID, alloc, alloc.dbID) return alloc.base, nil } diff --git a/store/hbase/txn.go b/store/hbase/txn.go index 4eacd390c6..4910959789 100644 --- a/store/hbase/txn.go +++ b/store/hbase/txn.go @@ -65,30 +65,22 @@ func newHbaseTxn(t themis.Txn, storeName string) *hbaseTxn { // Implement transaction interface func (txn *hbaseTxn) Get(k kv.Key) ([]byte, error) { - if kv.LogTxn { - log.Debugf("get key:%q, txn:%d", k, txn.tid) - } + log.Debugf("[kv] get key:%q, txn:%d", k, txn.tid) return txn.UnionStore.Get(k) } func (txn *hbaseTxn) Set(k kv.Key, v []byte) error { - if kv.LogTxn { - log.Debugf("seek %q txn:%d", k, txn.tid) - } + log.Debugf("[kv] seek %q txn:%d", k, txn.tid) return txn.UnionStore.Set(k, v) } func (txn *hbaseTxn) Inc(k kv.Key, step int64) (int64, error) { - if kv.LogTxn { - log.Debugf("Inc %q, step %d txn:%d", k, step, txn.tid) - } + log.Debugf("[kv] Inc %q, step %d txn:%d", k, step, txn.tid) return txn.UnionStore.Inc(k, step) } func (txn *hbaseTxn) GetInt64(k kv.Key) (int64, error) { - if kv.LogTxn { - log.Debugf("GetInt64 %q, txn:%d", k, txn.tid) - } + log.Debugf("[kv] GetInt64 %q, txn:%d", k, txn.tid) return txn.UnionStore.GetInt64(k) } @@ -97,9 +89,7 @@ func (txn *hbaseTxn) String() string { } func (txn *hbaseTxn) Seek(k kv.Key) (kv.Iterator, error) { - if kv.LogTxn { - log.Debugf("seek %q txn:%d", k, txn.tid) - } + log.Debugf("[kv] seek %q txn:%d", k, txn.tid) iter, err := txn.UnionStore.Seek(k) if err != nil { return nil, errors.Trace(err) @@ -108,9 +98,7 @@ func (txn *hbaseTxn) Seek(k kv.Key) (kv.Iterator, error) { } func (txn *hbaseTxn) Delete(k kv.Key) error { - if kv.LogTxn { - log.Debugf("delete %q txn:%d", k, txn.tid) - } + log.Debugf("[kv] delete %q txn:%d", k, txn.tid) err := txn.UnionStore.Delete(k) if err != nil { return errors.Trace(err) @@ -152,9 +140,7 @@ func (txn *hbaseTxn) doCommit() error { } txn.version = kv.NewVersion(txn.txn.GetCommitTS()) - if kv.LogTxn { - log.Debugf("commit successfully, txn.version:%d", txn.version.Ver) - } + log.Debugf("[kv] commit successfully, txn.version:%d", txn.version.Ver) return nil } @@ -162,9 +148,7 @@ func (txn *hbaseTxn) Commit() error { if !txn.valid { return kv.ErrInvalidTxn } - if kv.LogTxn { - log.Debugf("start to commit txn %d", txn.tid) - } + log.Debugf("[kv] start to commit txn %d", txn.tid) defer func() { txn.close() }() @@ -190,7 +174,7 @@ func (txn *hbaseTxn) Rollback() error { if !txn.valid { return kv.ErrInvalidTxn } - log.Warnf("Rollback txn %d", txn.tid) + log.Warnf("[kv] Rollback txn %d", txn.tid) return txn.close() } diff --git a/store/localstore/compactor.go b/store/localstore/compactor.go index a60eb2086e..2a70276261 100644 --- a/store/localstore/compactor.go +++ b/store/localstore/compactor.go @@ -100,7 +100,7 @@ func (gc *localstoreCompactor) deleteWorker() { batch.Delete(key) // Batch delete. if cnt == gc.policy.BatchDeleteCnt { - log.Debugf("GC delete commit %d keys", batch.Len()) + log.Debugf("[kv] GC delete commit %d keys", batch.Len()) err := gc.db.Commit(batch) if err != nil { log.Error(err) @@ -117,7 +117,7 @@ func (gc *localstoreCompactor) checkExpiredKeysWorker() { for { select { case <-gc.stopCh: - log.Debug("GC stopped") + log.Debug("[kv] GC stopped") return case <-gc.ticker.C: gc.mu.Lock() @@ -169,7 +169,9 @@ func (gc *localstoreCompactor) Compact(k kv.Key) error { return errors.Trace(err) } filteredKeys := gc.filterExpiredKeys(keys) - log.Debugf("GC send %d keys to delete worker", len(filteredKeys)) + if len(filteredKeys) > 0 { + log.Debugf("[kv] GC send %d keys to delete worker", len(filteredKeys)) + } for _, key := range filteredKeys { gc.delCh <- key } diff --git a/store/localstore/kv.go b/store/localstore/kv.go index ebcbe3e46b..7750192170 100644 --- a/store/localstore/kv.go +++ b/store/localstore/kv.go @@ -82,7 +82,7 @@ func (d Driver) Open(schema string) (kv.Storage, error) { if store, ok := mc.cache[schema]; ok { // TODO: check the cache store has the same engine with this Driver. - log.Info("cache store", schema) + log.Info("[kv] cache store", schema) return store, nil } @@ -91,7 +91,7 @@ func (d Driver) Open(schema string) (kv.Storage, error) { return nil, errors.Trace(err) } - log.Info("New store", schema) + log.Info("[kv] New store", schema) s := &dbStore{ txns: make(map[uint64]*dbTxn), keysLocked: make(map[string]uint64), @@ -164,9 +164,7 @@ func (s *dbStore) Begin() (kv.Transaction, error) { version: kv.MinVersion, snapshotVals: make(map[string]struct{}), } - if kv.LogTxn { - log.Debugf("Begin txn:%d", txn.tid) - } + log.Debugf("[kv] Begin txn:%d", txn.tid) txn.UnionStore = kv.NewUnionStore(newSnapshot(s, s.db, beginVer)) return txn, nil } @@ -249,7 +247,7 @@ func (s *dbStore) tryConditionLockKey(tid uint64, key string) error { // If there's newer version of this key, returns error. if ver > tid { - log.Warnf("txn:%d, tryLockKey condition not match for key %s, currValue:%q", tid, key, currValue) + log.Warnf("[kv] txn:%d, tryLockKey condition not match for key %s, currValue:%q", tid, key, currValue) return errors.Trace(kv.ErrConditionNotMatch) } diff --git a/store/localstore/local_version_provider.go b/store/localstore/local_version_provider.go index a29bda4437..8450647678 100644 --- a/store/localstore/local_version_provider.go +++ b/store/localstore/local_version_provider.go @@ -37,7 +37,7 @@ func (l *LocalVersionProvider) CurrentVersion() (kv.Version, error) { ts = uint64((time.Now().UnixNano() / int64(time.Millisecond)) << timePrecisionOffset) if l.lastTimestamp > ts { - log.Error("invalid physical time stamp") + log.Error("[kv] invalid physical time stamp") continue } diff --git a/store/localstore/txn.go b/store/localstore/txn.go index af94313885..6644a8f0b0 100644 --- a/store/localstore/txn.go +++ b/store/localstore/txn.go @@ -50,9 +50,7 @@ func (txn *dbTxn) markOrigin(k []byte) { // Implement transaction interface func (txn *dbTxn) Get(k kv.Key) ([]byte, error) { - if kv.LogTxn { - log.Debugf("get key:%q, txn:%d", k, txn.tid) - } + log.Debugf("[kv] get key:%q, txn:%d", k, txn.tid) val, err := txn.UnionStore.Get(k) if err != nil { return nil, errors.Trace(err) @@ -62,9 +60,7 @@ func (txn *dbTxn) Get(k kv.Key) ([]byte, error) { } func (txn *dbTxn) Set(k kv.Key, data []byte) error { - if kv.LogTxn { - log.Debugf("set key:%q, txn:%d", k, txn.tid) - } + log.Debugf("[kv] set key:%q, txn:%d", k, txn.tid) err := txn.UnionStore.Set(k, data) if err != nil { return errors.Trace(err) @@ -75,9 +71,7 @@ func (txn *dbTxn) Set(k kv.Key, data []byte) error { } func (txn *dbTxn) Inc(k kv.Key, step int64) (int64, error) { - if kv.LogTxn { - log.Debugf("Inc %q, step %d txn:%d", k, step, txn.tid) - } + log.Debugf("[kv] Inc %q, step %d txn:%d", k, step, txn.tid) txn.markOrigin(k) val, err := txn.UnionStore.Inc(k, step) @@ -89,9 +83,7 @@ func (txn *dbTxn) Inc(k kv.Key, step int64) (int64, error) { } func (txn *dbTxn) GetInt64(k kv.Key) (int64, error) { - if kv.LogTxn { - log.Debugf("GetInt64 %q, txn:%d", k, txn.tid) - } + log.Debugf("[kv] GetInt64 %q, txn:%d", k, txn.tid) val, err := txn.UnionStore.GetInt64(k) if err != nil { return 0, errors.Trace(err) @@ -105,9 +97,7 @@ func (txn *dbTxn) String() string { } func (txn *dbTxn) Seek(k kv.Key) (kv.Iterator, error) { - if kv.LogTxn { - log.Debugf("seek key:%q, txn:%d", k, txn.tid) - } + log.Debugf("[kv] seek key:%q, txn:%d", k, txn.tid) iter, err := txn.UnionStore.Seek(k) if err != nil { return nil, errors.Trace(err) @@ -120,9 +110,7 @@ func (txn *dbTxn) Seek(k kv.Key) (kv.Iterator, error) { } func (txn *dbTxn) Delete(k kv.Key) error { - if kv.LogTxn { - log.Debugf("delete key:%q, txn:%d", k, txn.tid) - } + log.Debugf("[kv] delete key:%q, txn:%d", k, txn.tid) err := txn.UnionStore.Delete(k) if err != nil { return errors.Trace(err) @@ -189,9 +177,7 @@ func (txn *dbTxn) Commit() error { if !txn.valid { return errors.Trace(kv.ErrInvalidTxn) } - if kv.LogTxn { - log.Debugf("commit txn %d", txn.tid) - } + log.Debugf("[kv] commit txn %d", txn.tid) defer func() { txn.close() }() @@ -218,7 +204,7 @@ func (txn *dbTxn) Rollback() error { if !txn.valid { return errors.Trace(kv.ErrInvalidTxn) } - log.Warnf("Rollback txn %d", txn.tid) + log.Warnf("[kv] Rollback txn %d", txn.tid) return txn.close() } diff --git a/tidb-server/main.go b/tidb-server/main.go index ba0d1b7943..4a9809b77b 100644 --- a/tidb-server/main.go +++ b/tidb-server/main.go @@ -24,7 +24,6 @@ import ( "github.com/ngaut/log" "github.com/pingcap/tidb" - "github.com/pingcap/tidb/kv" "github.com/pingcap/tidb/metric" "github.com/pingcap/tidb/tidb-server/server" "github.com/pingcap/tidb/util/printer" @@ -34,7 +33,6 @@ var ( store = flag.String("store", "goleveldb", "registered store name, [hbase, memory, goleveldb, boltdb]") storePath = flag.String("path", "/tmp/tidb", "tidb storage path") logLevel = flag.String("L", "debug", "log level: info, debug, warn, error, fatal") - logTxn = flag.Bool("log_txn", true, "log transaction: true/false") port = flag.String("P", "4000", "mp server port") lease = flag.Int("lease", 1, "schema lease seconds, very dangerous to change only if you know what you do") ) @@ -56,7 +54,6 @@ func main() { Addr: fmt.Sprintf(":%s", *port), LogLevel: *logLevel, } - kv.LogTxn = *logTxn log.SetLevelByString(cfg.LogLevel) store, err := tidb.NewStore(fmt.Sprintf("%s://%s", *store, *storePath))