Trace collect stats info (#5000)

1. collect stats as column exec_plan_stats
2. record request_at, reponse_at in same table system.statement_info.
    if statement run a long time, there will be two records in table with same value statement_id
3. add ComputationWrapper::RecordExecPlan to collect exec_plan(stats info)
    it will record new format in PR Explain analyze and Support json serialization for UI #5070
4. add pkg/trace codeowner xzxiong

CODEOWNERS

@@ -72,6 +72,7 @@
 /pkg/util/internalExecutor @aptend
 /pkg/util/metric @aptend
 /pkg/util/toml @zhangxu19830126
+/pkg/util/trace @xzxiong
 
 # /proto contains pb definitions, owners will be responsible
 # for compatibility issues required for rolling upgrade.

cmd/mo-service/main.go

@@ -337,7 +337,7 @@ func initTraceMetric(ctx context.Context, cfg *Config, stopper *stopper.Stopper,
 		})
 	}
 	if !SV.DisableMetric {
-		metric.InitMetric(ctx, nil, &SV, UUID, metric.ALL_IN_ONE_MODE, metric.WithWriterFactory(writerFactory))
+		metric.InitMetric(ctx, nil, &SV, UUID, ServerType, metric.WithWriterFactory(writerFactory))
 	}
 	return nil
 }

pkg/frontend/mysql_cmd_executor.go

@@ -37,7 +37,6 @@ import (
 	"github.com/matrixorigin/matrixone/pkg/container/vector"
 	"github.com/matrixorigin/matrixone/pkg/defines"
 	"github.com/matrixorigin/matrixone/pkg/logutil"
-	"github.com/matrixorigin/matrixone/pkg/logutil/logutil2"
 	"github.com/matrixorigin/matrixone/pkg/sql/parsers"
 	"github.com/matrixorigin/matrixone/pkg/util"
 	"github.com/matrixorigin/matrixone/pkg/util/metric"
@@ -147,8 +146,15 @@ func (mce *MysqlCmdExecutor) GetRoutineManager() *RoutineManager {
 	return mce.routineMgr
 }
 
-func (mce *MysqlCmdExecutor) RecordStatement(ctx context.Context, ses *Session, proc *process.Process, cw ComputationWrapper, beginIns time.Time) context.Context {
+var RecordStatement = func(ctx context.Context, ses *Session, proc *process.Process, cw ComputationWrapper, beginIns time.Time) context.Context {
+	if !trace.GetTracerProvider().IsEnable() {
+		return ctx
+	}
 	sessInfo := proc.SessionInfo
+	tenant := ses.GetTenantInfo()
+	if tenant == nil {
+		tenant, _ = GetTenantInfo("internal")
+	}
 	var stmID uuid.UUID
 	copy(stmID[:], cw.GetUUID())
 	var txnID uuid.UUID
@@ -159,23 +165,29 @@ func (mce *MysqlCmdExecutor) RecordStatement(ctx context.Context, ses *Session,
 	copy(sesID[:], ses.GetUUID())
 	fmtCtx := tree.NewFmtCtx(dialect.MYSQL, tree.WithQuoteString(true))
 	cw.GetAst().Format(fmtCtx)
-	trace.ReportStatement(
-		ctx,
-		&trace.StatementInfo{
-			StatementID:          stmID,
-			TransactionID:        txnID,
-			SessionID:            sesID,
-			Account:              "account", //fixme: sessInfo.GetAccount()
-			User:                 sessInfo.GetUser(),
-			Host:                 sessInfo.GetHost(),
-			Database:             sessInfo.GetDatabase(),
-			Statement:            fmtCtx.String(),
-			StatementFingerprint: "", // fixme
-			StatementTag:         "", // fixme
-			RequestAt:            util.NowNS(),
-		},
-	)
-	return trace.ContextWithSpanContext(ctx, trace.SpanContextWithID(trace.TraceID(stmID)))
+	stm := &trace.StatementInfo{
+		StatementID:          stmID,
+		TransactionID:        txnID,
+		SessionID:            sesID,
+		Account:              tenant.GetTenant(),
+		User:                 tenant.GetUser(),
+		Host:                 sessInfo.GetHost(),
+		Database:             sessInfo.GetDatabase(),
+		Statement:            fmtCtx.String(),
+		StatementFingerprint: "", // fixme: (Reserved)
+		StatementTag:         "", // fixme: (Reserved)
+		RequestAt:            util.NowNS(),
+	}
+	sc := trace.SpanContextWithID(trace.TraceID(stmID))
+	return trace.ContextWithStatement(trace.ContextWithSpanContext(ctx, sc), stm)
+}
+
+func (mce *MysqlCmdExecutor) RecordStatementTxnID(ctx context.Context, ses *Session) {
+	if stm := trace.StatementFromContext(ctx); stm == nil {
+		return
+	} else if handler := ses.GetTxnHandler(); handler.IsValidTxn() {
+		stm.SetTxnIDIsZero(handler.GetTxn().Txn().ID)
+	}
 }
 
 // outputPool outputs the data
@@ -1626,6 +1638,17 @@ func (cwft *TxnComputationWrapper) Compile(requestCtx context.Context, u interfa
 	return cwft.compile, err
 }
 
+func (cwft *TxnComputationWrapper) RecordExecPlan(ctx context.Context) error {
+	if stm := trace.StatementFromContext(ctx); stm != nil {
+		if handler := cwft.ses.GetTxnHandler(); handler.IsValidTxn() {
+			stm.SetTxnIDIsZero(handler.GetTxn().Txn().ID)
+		}
+		stm.SetExecPlan(cwft.plan)
+		stm.Report(ctx)
+	}
+	return nil
+}
+
 func (cwft *TxnComputationWrapper) GetUUID() []byte {
 	return cwft.uuid[:]
 }
@@ -1797,31 +1820,31 @@ func (mce *MysqlCmdExecutor) doComQuery(requestCtx context.Context, sql string)
 	for _, cw := range cws {
 		ses.SetMysqlResultSet(&MysqlResultSet{})
 		stmt := cw.GetAst()
-		ctx := mce.RecordStatement(requestCtx, ses, proc, cw, beginInstant)
+		requestCtx = RecordStatement(requestCtx, ses, proc, cw, beginInstant)
 
 		if ses.GetTenantInfo() != nil {
 			ses.SetPrivilege(determinePrivilegeSetOfStatement(stmt))
 			havePrivilege, err2 = authenticatePrivilegeOfStatementWithObjectTypeAccountAndDatabase(requestCtx, ses, stmt)
 			if err2 != nil {
-				logStatementStatus(ctx, ses, stmt, fail, err2)
+				logStatementStatus(requestCtx, ses, stmt, fail, err2)
 				return err2
 			}
 
 			if !havePrivilege {
 				retErr = moerr.NewInternalError("do not have privilege to execute the statement")
-				logStatementStatus(ctx, ses, stmt, fail, retErr)
+				logStatementStatus(requestCtx, ses, stmt, fail, retErr)
 				return retErr
 			}
 
 			havePrivilege, err2 = authenticatePrivilegeOfStatementWithObjectTypeNone(requestCtx, ses, stmt)
 			if err2 != nil {
-				logStatementStatus(ctx, ses, stmt, fail, err2)
+				logStatementStatus(requestCtx, ses, stmt, fail, err2)
 				return err2
 			}
 
 			if !havePrivilege {
 				retErr = moerr.NewInternalError("do not have privilege to execute the statement")
-				logStatementStatus(ctx, ses, stmt, fail, retErr)
+				logStatementStatus(requestCtx, ses, stmt, fail, retErr)
 				return retErr
 			}
 		}
@@ -1845,19 +1868,19 @@ func (mce *MysqlCmdExecutor) doComQuery(requestCtx context.Context, sql string)
 				//is ddl statement
 				if IsDDL(stmt) {
 					retErr = errorOnlyCreateStatement
-					logStatementStatus(ctx, ses, stmt, fail, retErr)
+					logStatementStatus(requestCtx, ses, stmt, fail, retErr)
 					return retErr
 				} else if IsAdministrativeStatement(stmt) {
 					retErr = errorAdministrativeStatement
-					logStatementStatus(ctx, ses, stmt, fail, retErr)
+					logStatementStatus(requestCtx, ses, stmt, fail, retErr)
 					return retErr
 				} else if IsParameterModificationStatement(stmt) {
 					retErr = errorParameterModificationInTxn
-					logStatementStatus(ctx, ses, stmt, fail, retErr)
+					logStatementStatus(requestCtx, ses, stmt, fail, retErr)
 					return retErr
 				} else {
 					retErr = errorUnclassifiedStatement
-					logStatementStatus(ctx, ses, stmt, fail, retErr)
+					logStatementStatus(requestCtx, ses, stmt, fail, retErr)
 					return retErr
 				}
 			}
@@ -1870,6 +1893,7 @@ func (mce *MysqlCmdExecutor) doComQuery(requestCtx context.Context, sql string)
 			if err != nil {
 				goto handleFailed
 			}
+			mce.RecordStatementTxnID(requestCtx, ses)
 		case *tree.CommitTransaction:
 			err = ses.TxnCommit()
 			if err != nil {
@@ -2041,10 +2065,11 @@ func (mce *MysqlCmdExecutor) doComQuery(requestCtx context.Context, sql string)
 			goto handleFailed
 		}
 		stmt = cw.GetAst()
+		cw.RecordExecPlan(requestCtx)
 
 		runner = ret.(ComputationRunner)
 		if !ses.Pu.SV.DisableRecordTimeElapsedOfSqlRequest {
-			logutil2.Infof(ctx, "time of Exec.Build : %s", time.Since(cmpBegin).String())
+			logutil.Infof("time of Exec.Build : %s", time.Since(cmpBegin).String())
 		}
 
 		// cw.Compile might rewrite sql, here we fetch the latest version
@@ -2315,7 +2340,8 @@ func (mce *MysqlCmdExecutor) doComQuery(requestCtx context.Context, sql string)
 		if !fromLoadData {
 			txnErr = ses.TxnCommitSingleStatement(stmt)
 			if txnErr != nil {
-				logStatementStatus(ctx, ses, stmt, fail, txnErr)
+				trace.EndStatement(requestCtx, txnErr)
+				logStatementStatus(requestCtx, ses, stmt, fail, txnErr)
 				return txnErr
 			}
 			switch stmt.(type) {
@@ -2329,40 +2355,45 @@ func (mce *MysqlCmdExecutor) doComQuery(requestCtx context.Context, sql string)
 				*tree.Deallocate:
 				resp := NewOkResponse(rspLen, 0, 0, 0, int(COM_QUERY), "")
 				if err := mce.GetSession().protocol.SendResponse(resp); err != nil {
+					trace.EndStatement(requestCtx, err)
 					retErr = fmt.Errorf("routine send response failed. error:%v ", err)
-					logStatementStatus(ctx, ses, stmt, fail, retErr)
+					logStatementStatus(requestCtx, ses, stmt, fail, retErr)
 					return retErr
 				}
 
 			case *tree.PrepareStmt, *tree.PrepareString:
 				if mce.ses.Cmd == int(COM_STMT_PREPARE) {
 					if err := mce.ses.protocol.SendPrepareResponse(prepareStmt); err != nil {
+						trace.EndStatement(requestCtx, err)
 						retErr = fmt.Errorf("routine send response failed. error:%v ", err)
-						logStatementStatus(ctx, ses, stmt, fail, retErr)
+						logStatementStatus(requestCtx, ses, stmt, fail, retErr)
 						return retErr
 					}
 				} else {
 					resp := NewOkResponse(rspLen, 0, 0, 0, int(COM_QUERY), "")
 					if err := mce.GetSession().protocol.SendResponse(resp); err != nil {
+						trace.EndStatement(requestCtx, err)
 						retErr = fmt.Errorf("routine send response failed. error:%v ", err)
-						logStatementStatus(ctx, ses, stmt, fail, retErr)
+						logStatementStatus(requestCtx, ses, stmt, fail, retErr)
 						return retErr
 					}
 				}
 			}
 		}
-		logStatementStatus(ctx, ses, stmt, success, nil)
+		trace.EndStatement(requestCtx, nil)
+		logStatementStatus(requestCtx, ses, stmt, success, nil)
 		goto handleNext
 	handleFailed:
+		trace.EndStatement(requestCtx, err)
 		logutil.Error(err.Error())
 		if !fromLoadData {
 			txnErr = ses.TxnRollbackSingleStatement(stmt)
 			if txnErr != nil {
-				logStatementStatus(ctx, ses, stmt, fail, txnErr)
+				logStatementStatus(requestCtx, ses, stmt, fail, txnErr)
 				return txnErr
 			}
 		}
-		logStatementStatus(ctx, ses, stmt, fail, err)
+		logStatementStatus(requestCtx, ses, stmt, fail, err)
 		return err
 	handleNext:
 	} // end of for

pkg/frontend/mysql_cmd_executor_test.go

@@ -45,12 +45,24 @@ func init() {
 	trace.Init(context.Background(), trace.EnableTracer(false))
 }
 
+func mockRecordStatement(ctx context.Context) (context.Context, *gostub.Stubs) {
+	stm := &trace.StatementInfo{}
+	ctx = trace.ContextWithStatement(ctx, stm)
+	stubs := gostub.Stub(&RecordStatement, func(context.Context, *Session, *process.Process, ComputationWrapper, time.Time) context.Context {
+		return ctx
+	})
+	return ctx, stubs
+}
+
 func Test_mce(t *testing.T) {
 	ctx := context.TODO()
 	convey.Convey("boot mce succ", t, func() {
 		ctrl := gomock.NewController(t)
 		defer ctrl.Finish()
 
+		ctx, rsStubs := mockRecordStatement(ctx)
+		defer rsStubs.Reset()
+
 		eng := mock_frontend.NewMockEngine(ctrl)
 		eng.EXPECT().New(gomock.Any(), gomock.Any()).Return(nil).AnyTimes()
 		eng.EXPECT().Commit(gomock.Any(), gomock.Any()).Return(nil).AnyTimes()
@@ -78,6 +90,7 @@ func Test_mce(t *testing.T) {
 			t.Error(err)
 		}
 		use_t.EXPECT().GetAst().Return(stmts[0]).AnyTimes()
+		use_t.EXPECT().RecordExecPlan(ctx).Return(nil).AnyTimes()
 
 		runner := mock_frontend.NewMockComputationRunner(ctrl)
 		runner.EXPECT().Run(gomock.Any()).Return(nil).AnyTimes()
@@ -93,6 +106,7 @@ func Test_mce(t *testing.T) {
 		create_1.EXPECT().Compile(gomock.Any(), gomock.Any(), gomock.Any()).Return(runner, nil).AnyTimes()
 		create_1.EXPECT().Run(gomock.Any()).Return(nil).AnyTimes()
 		create_1.EXPECT().GetAffectedRows().Return(uint64(0)).AnyTimes()
+		create_1.EXPECT().RecordExecPlan(ctx).Return(nil).AnyTimes()
 
 		select_1 := mock_frontend.NewMockComputationWrapper(ctrl)
 		stmts, err = parsers.Parse(dialect.MYSQL, "select a,b,c from A")
@@ -104,6 +118,7 @@ func Test_mce(t *testing.T) {
 		select_1.EXPECT().SetDatabaseName(gomock.Any()).Return(nil).AnyTimes()
 		select_1.EXPECT().Compile(gomock.Any(), gomock.Any(), gomock.Any()).Return(runner, nil).AnyTimes()
 		select_1.EXPECT().Run(gomock.Any()).Return(nil).AnyTimes()
+		select_1.EXPECT().RecordExecPlan(ctx).Return(nil).AnyTimes()
 
 		cola := &MysqlColumn{}
 		cola.SetName("a")
@@ -184,6 +199,7 @@ func Test_mce(t *testing.T) {
 			select_2.EXPECT().Run(gomock.Any()).Return(nil).AnyTimes()
 			select_2.EXPECT().GetAffectedRows().Return(uint64(0)).AnyTimes()
 			select_2.EXPECT().GetColumns().Return(self_handle_sql_columns[i], nil).AnyTimes()
+			select_2.EXPECT().RecordExecPlan(ctx).Return(nil).AnyTimes()
 			cws = append(cws, select_2)
 		}
 
@@ -328,6 +344,9 @@ func Test_mce_selfhandle(t *testing.T) {
 		ctrl := gomock.NewController(t)
 		defer ctrl.Finish()
 
+		ctx, rsStubs := mockRecordStatement(ctx)
+		defer rsStubs.Reset()
+
 		eng := mock_frontend.NewMockEngine(ctrl)
 		eng.EXPECT().New(gomock.Any(), gomock.Any()).Return(nil).AnyTimes()
 		eng.EXPECT().Commit(gomock.Any(), gomock.Any()).Return(nil).AnyTimes()
@@ -880,6 +899,9 @@ func Test_CMD_FIELD_LIST(t *testing.T) {
 		ctrl := gomock.NewController(t)
 		defer ctrl.Finish()
 
+		ctx, rsStubs := mockRecordStatement(ctx)
+		defer rsStubs.Reset()
+
 		eng := mock_frontend.NewMockEngine(ctrl)
 		eng.EXPECT().New(gomock.Any(), gomock.Any()).Return(nil).AnyTimes()
 		eng.EXPECT().Commit(gomock.Any(), gomock.Any()).Return(nil).AnyTimes()

pkg/frontend/test/types_mock.go

@@ -132,6 +132,20 @@ func (mr *MockComputationWrapperMockRecorder) GetColumns() *gomock.Call {
 	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "GetColumns", reflect.TypeOf((*MockComputationWrapper)(nil).GetColumns))
 }
 
+// RecordExecPlan mocks base method.
+func (m *MockComputationWrapper) RecordExecPlan(ctx context.Context) error {
+	m.ctrl.T.Helper()
+	ret := m.ctrl.Call(m, "RecordExecPlan", ctx)
+	ret0, _ := ret[0].(error)
+	return ret0
+}
+
+// RecordExecPlan indicates an expected call of RecordExecPlan.
+func (mr *MockComputationWrapperMockRecorder) RecordExecPlan(ctx context.Context) *gomock.Call {
+	mr.mock.ctrl.T.Helper()
+	return mr.mock.ctrl.RecordCallWithMethodType(mr.mock, "RecordExecPlan", reflect.TypeOf((*MockComputationWrapper)(nil).RecordExecPlan), ctx)
+}
+
 // GetUUID mocks base method.
 func (m *MockComputationWrapper) GetUUID() []byte {
 	m.ctrl.T.Helper()

pkg/frontend/types.go

@@ -50,6 +50,8 @@ type ComputationWrapper interface {
 	Compile(requestCtx context.Context, u interface{}, fill func(interface{}, *batch.Batch) error) (interface{}, error)
 
 	GetUUID() []byte
+
+	RecordExecPlan(ctx context.Context) error
 }
 
 type ColumnInfo interface {

pkg/frontend/util.go

@@ -18,7 +18,8 @@ import (
 	"bytes"
 	"context"
 	"fmt"
-	"github.com/matrixorigin/matrixone/pkg/sql/parsers/dialect"
+	"github.com/matrixorigin/matrixone/pkg/common/moerr"
+	"github.com/matrixorigin/matrixone/pkg/util/trace"
 	"go/constant"
 	"os"
 	"runtime"
@@ -442,9 +443,11 @@ func (s statementStatus) String() string {
 
 // logStatementStatus prints the status of the statement into the log.
 func logStatementStatus(ctx context.Context, ses *Session, stmt tree.Statement, status statementStatus, err error) {
-	fmtCtx := tree.NewFmtCtx(dialect.MYSQL)
-	stmt.Format(fmtCtx)
-	stmtStr := fmtCtx.String()
+	stm := trace.StatementFromContext(ctx)
+	if stm == nil {
+		panic(moerr.NewInternalError("no statement info in context"))
+	}
+	stmtStr := stm.Statement
 	logStatementStringStatus(ctx, ses, stmtStr, status, err)
 }
 

pkg/logutil/dragonboat_test.go

-// Copyright 2021 Matrix Origin
+// Copyright 2022 Matrix Origin
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.

pkg/logutil/internal_test.go

-// Copyright 2021 Matrix Origin
+// Copyright 2022 Matrix Origin
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.

pkg/logutil/logutil2/api.go

-// Copyright 2021 Matrix Origin
-//
-// 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,
-// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
-// See the License for the specific language governing permissions and
-// limitations under the License.
-
-package logutil2
-
-import (
-	"context"
-	"fmt"
-	"github.com/matrixorigin/matrixone/pkg/logutil"
-	"go.uber.org/zap"
-	"go.uber.org/zap/zapcore"
-)
-
-func Debug(ctx context.Context, msg string, fields ...zap.Field) {
-	fields = append(fields, ContextField(ctx))
-	logutil.GetSkip1Logger().Debug(msg, fields...)
-}
-
-func Info(ctx context.Context, msg string, fields ...zap.Field) {
-	fields = append(fields, ContextField(ctx))
-	logutil.GetSkip1Logger().Info(msg, fields...)
-}
-
-func Warn(ctx context.Context, msg string, fields ...zap.Field) {
-	fields = append(fields, ContextField(ctx))
-	logutil.GetSkip1Logger().Warn(msg, fields...)
-}
-
-func Error(ctx context.Context, msg string, fields ...zap.Field) {
-	fields = append(fields, ContextField(ctx))
-	logutil.GetSkip1Logger().Error(msg, fields...)
-}
-
-func Panic(ctx context.Context, msg string, fields ...zap.Field) {
-	fields = append(fields, ContextField(ctx))
-	logutil.GetSkip1Logger().Panic(msg, fields...)
-}
-
-func Fatal(ctx context.Context, msg string, fields ...zap.Field) {
-	fields = append(fields, ContextField(ctx))
-	logutil.GetSkip1Logger().Fatal(msg, fields...)
-}
-
-// Debugf only use in develop mode
-func Debugf(ctx context.Context, msg string, fields ...interface{}) {
-	if len(fields) == 0 {
-		logutil.GetSkip1Logger().Debug(msg, ContextField(ctx))
-	} else {
-		logutil.GetSkip1Logger().Debug(fmt.Sprintf(msg, fields...), ContextField(ctx))
-	}
-}
-
-// Infof only use in develop mode
-func Infof(ctx context.Context, msg string, fields ...interface{}) {
-	if len(fields) == 0 {
-		logutil.GetSkip1Logger().Info(msg, ContextField(ctx))
-	} else {
-		logutil.GetSkip1Logger().Info(fmt.Sprintf(msg, fields...), ContextField(ctx))
-	}
-}
-
-// Warnf only use in develop mode
-func Warnf(ctx context.Context, msg string, fields ...interface{}) {
-	if len(fields) == 0 {
-		logutil.GetSkip1Logger().Warn(msg, ContextField(ctx))
-	} else {
-		logutil.GetSkip1Logger().Warn(fmt.Sprintf(msg, fields...), ContextField(ctx))
-	}
-}
-
-// Errorf only use in develop mode
-func Errorf(ctx context.Context, msg string, fields ...interface{}) {
-	if len(fields) == 0 {
-		logutil.GetErrorLogger().Error(msg, ContextField(ctx))
-	} else {
-		logutil.GetErrorLogger().Error(fmt.Sprintf(msg, fields...), ContextField(ctx))
-	}
-}
-
-// Panicf only use in develop mode
-func Panicf(ctx context.Context, msg string, fields ...interface{}) {
-	if len(fields) == 0 {
-		logutil.GetSkip1Logger().Panic(msg, ContextField(ctx))
-	} else {
-		logutil.GetSkip1Logger().Panic(fmt.Sprintf(msg, fields...), ContextField(ctx))
-	}
-}
-
-// Fatalf only use in develop mode
-func Fatalf(ctx context.Context, msg string, fields ...interface{}) {
-	if len(fields) == 0 {
-		logutil.GetSkip1Logger().Fatal(msg, ContextField(ctx))
-	} else {
-		logutil.GetSkip1Logger().Fatal(fmt.Sprintf(msg, fields...), ContextField(ctx))
-	}
-}
-
-// hook can catch zapcore.Entry, which can add by WithOptions(zap.Hooks(hook))
-// But what we need is zapcore.CheckedEntry
-// @deprecated
-func hook(e zapcore.Entry) error { return nil }
-
-var _ = hook(zapcore.Entry{})
-
-func ContextFieldsOption(ctx context.Context) zap.Option {
-	return zap.Fields(logutil.GetContextFieldFunc()(ctx))
-}
-func ContextField(ctx context.Context) zap.Field {
-	return logutil.GetContextFieldFunc()(ctx)
-}

pkg/logutil/report_test.go

-// Copyright 2021 Matrix Origin
+// Copyright 2022 Matrix Origin
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.

pkg/txn/storage/txn/frontend_test.go

@@ -27,14 +27,27 @@ import (
 	"github.com/matrixorigin/matrixone/pkg/testutil"
 	"github.com/matrixorigin/matrixone/pkg/txn/clock"
 	"github.com/matrixorigin/matrixone/pkg/txn/storage/txn/memtable"
+	"github.com/matrixorigin/matrixone/pkg/util/trace"
 	txnengine "github.com/matrixorigin/matrixone/pkg/vm/engine/txn"
 	"github.com/matrixorigin/matrixone/pkg/vm/mempool"
 	"github.com/matrixorigin/matrixone/pkg/vm/mheap"
 	"github.com/matrixorigin/matrixone/pkg/vm/mmu/guest"
 	"github.com/matrixorigin/matrixone/pkg/vm/mmu/host"
+	"github.com/matrixorigin/matrixone/pkg/vm/process"
 	"github.com/stretchr/testify/assert"
+
+	"github.com/prashantv/gostub"
 )
 
+func mockRecordStatement(ctx context.Context) (context.Context, *gostub.Stubs) {
+	stm := &trace.StatementInfo{}
+	ctx = trace.ContextWithStatement(ctx, stm)
+	stubs := gostub.Stub(&frontend.RecordStatement, func(context.Context, *frontend.Session, *process.Process, frontend.ComputationWrapper, time.Time) context.Context {
+		return ctx
+	})
+	return ctx, stubs
+}
+
 func TestFrontend(t *testing.T) {
 	ctx, cancel := context.WithTimeout(
 		context.Background(),
@@ -104,6 +117,9 @@ func TestFrontend(t *testing.T) {
 	}
 	ctx = context.WithValue(ctx, config.ParameterUnitKey, pu)
 
+	ctx, rsStubs := mockRecordStatement(ctx)
+	defer rsStubs.Reset()
+
 	err = frontend.InitSysTenant(ctx)
 	assert.Nil(t, err)
 

pkg/util/export/batch_processor.go

@@ -23,7 +23,6 @@ import (
 	"time"
 
 	"github.com/matrixorigin/matrixone/pkg/logutil"
-	"github.com/matrixorigin/matrixone/pkg/logutil/logutil2"
 	"github.com/matrixorigin/matrixone/pkg/util/batchpipe"
 )
 
@@ -205,7 +204,7 @@ func (c *MOCollector) Start() bool {
 	}
 	defer atomic.StoreUint32(&c.started, 1)
 
-	logutil2.Infof(DefaultContext(), "MOCollector Start")
+	logutil.Infof("MOCollector Start")
 	for i := 0; i < c.collectorCnt; i++ {
 		c.stopWait.Add(1)
 		go c.doCollect(i)

pkg/util/metric/metric.go

@@ -215,7 +215,7 @@ func createTableSqlFromMetricFamily(desc *prom.Desc, buf *bytes.Buffer, optionsF
 	buf.WriteString("create ")
 	buf.WriteString(opts.GetCreateOptions())
 	buf.WriteString(fmt.Sprintf(
-		"table if not exists %s.%s (`%s` datetime, `%s` double, `%s` varchar(36), `%s` varchar(20)",
+		"table if not exists %s.%s (`%s` datetime(6), `%s` double, `%s` varchar(36), `%s` varchar(20)",
 		MetricDBConst, extra.fqName, lblTimeConst, lblValueConst, lblNodeConst, lblRoleConst,
 	))
 	for _, lbl := range extra.labels {

pkg/util/metric/metric_test.go

@@ -125,8 +125,9 @@ func TestDescExtra(t *testing.T) {
 
 type dummyTableOptions struct{}
 
-func (o dummyTableOptions) GetCreateOptions() string { return "" }
-func (o dummyTableOptions) GetTableOptions() string  { return "" }
+func (o dummyTableOptions) FormatDdl(ddl string) string { return ddl }
+func (o dummyTableOptions) GetCreateOptions() string    { return "" }
+func (o dummyTableOptions) GetTableOptions() string     { return "" }
 
 var dummyOptionsFactory = func(db, tbl string) trace.TableOptions {
 	return &dummyTableOptions{}
@@ -137,13 +138,13 @@ func TestCreateTable(t *testing.T) {
 	name := "sql_test_counter"
 	sql := createTableSqlFromMetricFamily(prom.NewDesc(name, "", []string{"zzz", "aaa"}, nil), buf, dummyOptionsFactory)
 	assert.Equal(t, sql, fmt.Sprintf(
-		"create table if not exists %s.%s (`%s` datetime, `%s` double, `%s` varchar(36), `%s` varchar(20), `aaa` varchar(20), `zzz` varchar(20))",
+		"create table if not exists %s.%s (`%s` datetime(6), `%s` double, `%s` varchar(36), `%s` varchar(20), `aaa` varchar(20), `zzz` varchar(20))",
 		MetricDBConst, name, lblTimeConst, lblValueConst, lblNodeConst, lblRoleConst,
 	))
 
 	sql = createTableSqlFromMetricFamily(prom.NewDesc(name, "", nil, nil), buf, dummyOptionsFactory)
 	assert.Equal(t, sql, fmt.Sprintf(
-		"create table if not exists %s.%s (`%s` datetime, `%s` double, `%s` varchar(36), `%s` varchar(20))",
+		"create table if not exists %s.%s (`%s` datetime(6), `%s` double, `%s` varchar(36), `%s` varchar(20))",
 		MetricDBConst, name, lblTimeConst, lblValueConst, lblNodeConst, lblRoleConst,
 	))
 }

pkg/util/time.go

@@ -63,3 +63,8 @@ func Now() time.Time {
 	sec, nesc := nowNS/1e9, nowNS%1e9
 	return time.Unix(int64(sec), int64(nesc))
 }
+
+func Time(ns TimeNano) time.Time {
+	sec, nesc := ns/1e9, ns%1e9
+	return time.Unix(int64(sec), int64(nesc))
+}

pkg/util/trace/buffer_pipe_sql.go → pkg/util/trace/buffer_pipe.go

@@ -263,22 +263,22 @@ func genZapLogBatchSql(in []IBuffer2SqlItem, buf *bytes.Buffer) any {
 		}
 
 		buf.WriteString("(")
-		buf.WriteString(fmt.Sprintf(`"%s"`, s.SpanContext.SpanID.String()))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, s.SpanContext.TraceID.String()))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, moNode.NodeUuid))                        // node_uuid
-		buf.WriteString(fmt.Sprintf(`, "%s"`, moNode.NodeType))                        // node_type
-		buf.WriteString(fmt.Sprintf(`, "%s"`, s.Timestamp.Format(timestampFormatter))) // timestamp
-		buf.WriteString(fmt.Sprintf(`, "%s"`, s.LoggerName))                           // name
-		buf.WriteString(fmt.Sprintf(`, "%s"`, s.Level.String()))                       // log level
-		buf.WriteString(fmt.Sprintf(`, "%s"`, s.Caller))                               // caller
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.Message)))                       // message
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.Extra)))                         // extra
+		buf.WriteString(fmt.Sprintf(`%q`, s.SpanContext.SpanID.String()))
+		buf.WriteString(fmt.Sprintf(`, %q`, s.SpanContext.TraceID.String()))
+		buf.WriteString(fmt.Sprintf(`, %q`, moNode.NodeUuid))                        // node_uuid
+		buf.WriteString(fmt.Sprintf(`, %q`, moNode.NodeType))                        // node_type
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Timestamp.Format(timestampFormatter))) // timestamp
+		buf.WriteString(fmt.Sprintf(`, %q`, s.LoggerName))                           // name
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Level.String()))                       // log level
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Caller))                               // caller
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Message))                              // message
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Extra))                                // extra
 		buf.WriteString("),")
 	}
 	return string(buf.Next(buf.Len() - 1))
 }
 
-func genStatementBatchSql(in []IBuffer2SqlItem, buf *bytes.Buffer) any {
+var genStatementBatchSql = func(in []IBuffer2SqlItem, buf *bytes.Buffer) any {
 	buf.Reset()
 	if len(in) == 0 {
 		logutil.Debugf("genStatementBatchSql empty")
@@ -290,8 +290,6 @@ func genStatementBatchSql(in []IBuffer2SqlItem, buf *bytes.Buffer) any {
 	buf.WriteString("`statement_id`")
 	buf.WriteString(", `transaction_id`")
 	buf.WriteString(", `session_id`")
-	buf.WriteString(", `tenant_id`")
-	buf.WriteString(", `user_id`")
 	buf.WriteString(", `account`")
 	buf.WriteString(", `user`")
 	buf.WriteString(", `host`")
@@ -302,6 +300,10 @@ func genStatementBatchSql(in []IBuffer2SqlItem, buf *bytes.Buffer) any {
 	buf.WriteString(", `node_uuid`")
 	buf.WriteString(", `node_type`")
 	buf.WriteString(", `request_at`")
+	buf.WriteString(", `response_at`")
+	buf.WriteString(", `status`")
+	buf.WriteString(", `error`")
+	buf.WriteString(", `duration`")
 	buf.WriteString(", `exec_plan`")
 	buf.WriteString(") values ")
 
@@ -312,24 +314,34 @@ func genStatementBatchSql(in []IBuffer2SqlItem, buf *bytes.Buffer) any {
 		if !ok {
 			panic("Not StatementInfo")
 		}
+		s.mux.Lock()
 		buf.WriteString("(")
-		buf.WriteString(fmt.Sprintf(`"%s"`, uuid.UUID(s.StatementID).String()))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, uuid.UUID(s.TransactionID).String()))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, uuid.UUID(s.SessionID).String()))
-		buf.WriteString(fmt.Sprintf(`, %d`, s.TenantID))
-		buf.WriteString(fmt.Sprintf(`, %d`, s.UserID))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.Account)))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.User)))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.Host)))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.Database)))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.Statement)))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.StatementFingerprint)))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.StatementTag)))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, moNode.NodeUuid))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, moNode.NodeType))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, nanoSec2DatetimeString(s.RequestAt)))
-		buf.WriteString(fmt.Sprintf(`, "%s"`, quote(s.ExecPlan)))
+		buf.WriteString(fmt.Sprintf(`%q`, uuid.UUID(s.StatementID).String()))
+		buf.WriteString(fmt.Sprintf(`, %q`, uuid.UUID(s.TransactionID).String()))
+		buf.WriteString(fmt.Sprintf(`, %q`, uuid.UUID(s.SessionID).String()))
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Account))
+		buf.WriteString(fmt.Sprintf(`, %q`, s.User))
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Host))
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Database))
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Statement))
+		buf.WriteString(fmt.Sprintf(`, %q`, s.StatementFingerprint))
+		buf.WriteString(fmt.Sprintf(`, %q`, s.StatementTag))
+		buf.WriteString(fmt.Sprintf(`, %q`, moNode.NodeUuid))
+		buf.WriteString(fmt.Sprintf(`, %q`, moNode.NodeType))
+		buf.WriteString(fmt.Sprintf(`, %q`, nanoSec2DatetimeString(s.RequestAt)))
+		buf.WriteString(fmt.Sprintf(`, %q`, nanoSec2DatetimeString(s.ResponseAt)))
+		buf.WriteString(fmt.Sprintf(`, %d`, s.Duration))
+		buf.WriteString(fmt.Sprintf(`, %q`, s.Status.String()))
+		if s.Error == nil {
+			buf.WriteString(`, ""`)
+		} else {
+			buf.WriteString(fmt.Sprintf(`, %q`, s.Error))
+		}
+		buf.WriteString(fmt.Sprintf(`, %q`, s.ExecPlan2Json()))
 		buf.WriteString("),")
+
+		s.exported = true
+		s.mux.Unlock()
 	}
 	return string(buf.Next(buf.Len() - 1))
 }
@@ -541,7 +553,7 @@ func newBuffer2Sql(opts ...buffer2SqlOption) *buffer2Sql {
 	b := &buffer2Sql{
 		Reminder:       bp.NewConstantClock(defaultClock),
 		buf:            make([]IBuffer2SqlItem, 0, 10240),
-		sizeThreshold:  1 * MB,
+		sizeThreshold:  10 * MB,
 		filterItemFunc: noopFilterItemFunc,
 		genBatchFunc:   noopGenBatchSQL,
 	}

pkg/util/trace/buffer_pipe_sql_test.go → pkg/util/trace/buffer_pipe_test.go

@@ -315,8 +315,6 @@ func Test_buffer2Sql_GetBatch_AllType(t *testing.T) {
 						StatementID:          _1TraceID,
 						TransactionID:        _1TxnID,
 						SessionID:            _1SesID,
-						TenantID:             666,
-						UserID:               999,
 						Account:              "MO",
 						User:                 "moroot",
 						Database:             "system",
@@ -324,15 +322,15 @@ func Test_buffer2Sql_GetBatch_AllType(t *testing.T) {
 						StatementFingerprint: "show tables",
 						StatementTag:         "",
 						RequestAt:            util.TimeNano(0),
-						ExecPlan:             "",
+						ExecPlan:             nil,
 					},
 				},
 				buf: buf,
 			},
 			wantFunc: genStatementBatchSql,
 			want: `insert into system.statement_info (` +
-				"`statement_id`, `transaction_id`, `session_id`, `tenant_id`, `user_id`, `account`, `user`, `host`, `database`, `statement`, `statement_tag`, `statement_fingerprint`, `node_uuid`, `node_type`, `request_at`, `exec_plan`" +
-				`) values ("00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", 666, 999, "MO", "moroot", "", "system", "show tables", "show tables", "", "node_uuid", "Standalone", "1970-01-01 00:00:00.000000", "")`,
+				"`statement_id`, `transaction_id`, `session_id`, `account`, `user`, `host`, `database`, `statement`, `statement_tag`, `statement_fingerprint`, `node_uuid`, `node_type`, `request_at`, `response_at`, `status`, `error`, `duration`, `exec_plan`" +
+				`) values ("00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", "MO", "moroot", "", "system", "show tables", "show tables", "", "node_uuid", "Standalone", "1970-01-01 00:00:00.000000", "1970-01-01 00:00:00.000000", 0, "Running", "", "{}")`,
 		},
 		{
 			name:   "multi_statement",
@@ -343,8 +341,6 @@ func Test_buffer2Sql_GetBatch_AllType(t *testing.T) {
 						StatementID:          _1TraceID,
 						TransactionID:        _1TxnID,
 						SessionID:            _1SesID,
-						TenantID:             666,
-						UserID:               999,
 						Account:              "MO",
 						User:                 "moroot",
 						Database:             "system",
@@ -352,14 +348,12 @@ func Test_buffer2Sql_GetBatch_AllType(t *testing.T) {
 						StatementFingerprint: "show tables",
 						StatementTag:         "",
 						RequestAt:            util.TimeNano(0),
-						ExecPlan:             "",
+						ExecPlan:             nil,
 					},
 					&StatementInfo{
 						StatementID:          _2TraceID,
 						TransactionID:        _1TxnID,
 						SessionID:            _1SesID,
-						TenantID:             222,
-						UserID:               555,
 						Account:              "MO",
 						User:                 "moroot",
 						Database:             "system",
@@ -367,16 +361,18 @@ func Test_buffer2Sql_GetBatch_AllType(t *testing.T) {
 						StatementFingerprint: "show databases",
 						StatementTag:         "dcl",
 						RequestAt:            util.TimeNano(time.Microsecond),
-						ExecPlan:             "",
+						ResponseAt:           util.TimeNano(time.Microsecond + time.Second),
+						Duration:             uint64(time.Second),
+						ExecPlan:             nil,
 					},
 				},
 				buf: buf,
 			},
 			wantFunc: genStatementBatchSql,
 			want: `insert into system.statement_info (` +
-				"`statement_id`, `transaction_id`, `session_id`, `tenant_id`, `user_id`, `account`, `user`, `host`, `database`, `statement`, `statement_tag`, `statement_fingerprint`, `node_uuid`, `node_type`, `request_at`, `exec_plan`" +
-				`) values ("00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", 666, 999, "MO", "moroot", "", "system", "show tables", "show tables", "", "node_uuid", "Standalone", "1970-01-01 00:00:00.000000", "")` +
-				`,("00000000-0000-0000-0000-000000000002", "00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", 222, 555, "MO", "moroot", "", "system", "show databases", "show databases", "dcl", "node_uuid", "Standalone", "1970-01-01 00:00:00.000001", "")`,
+				"`statement_id`, `transaction_id`, `session_id`, `account`, `user`, `host`, `database`, `statement`, `statement_tag`, `statement_fingerprint`, `node_uuid`, `node_type`, `request_at`, `response_at`, `status`, `error`, `duration`, `exec_plan`" +
+				`) values ("00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", "MO", "moroot", "", "system", "show tables", "show tables", "", "node_uuid", "Standalone", "1970-01-01 00:00:00.000000", "1970-01-01 00:00:00.000000", 0, "Running", "", "{}")` +
+				`,("00000000-0000-0000-0000-000000000002", "00000000-0000-0000-0000-000000000001", "00000000-0000-0000-0000-000000000001", "MO", "moroot", "", "system", "show databases", "show databases", "dcl", "node_uuid", "Standalone", "1970-01-01 00:00:00.000001", "1970-01-01 00:00:01.000001", 1000000000, "Running", "", "{}")`,
 		},
 		{
 			name:   "single_zap",
@@ -961,8 +957,6 @@ func Test_genCsvData(t *testing.T) {
 						StatementID:          _1TraceID,
 						TransactionID:        _1TxnID,
 						SessionID:            _1SesID,
-						TenantID:             666,
-						UserID:               999,
 						Account:              "MO",
 						User:                 "moroot",
 						Database:             "system",
@@ -970,12 +964,12 @@ func Test_genCsvData(t *testing.T) {
 						StatementFingerprint: "show tables",
 						StatementTag:         "",
 						RequestAt:            util.TimeNano(0),
-						ExecPlan:             "",
+						ExecPlan:             nil,
 					},
 				},
 				buf: buf,
 			},
-			want: `00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,666,999,MO,moroot,,system,show tables,,show tables,node_uuid,Standalone,1970-01-01 00:00:00.000000,
+			want: `00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,MO,moroot,,system,show tables,,show tables,node_uuid,Standalone,1970-01-01 00:00:00.000000,1970-01-01 00:00:00.000000,0,Running,,{}
 `,
 		},
 		{
@@ -986,8 +980,6 @@ func Test_genCsvData(t *testing.T) {
 						StatementID:          _1TraceID,
 						TransactionID:        _1TxnID,
 						SessionID:            _1SesID,
-						TenantID:             666,
-						UserID:               999,
 						Account:              "MO",
 						User:                 "moroot",
 						Database:             "system",
@@ -995,14 +987,12 @@ func Test_genCsvData(t *testing.T) {
 						StatementFingerprint: "show tables",
 						StatementTag:         "",
 						RequestAt:            util.TimeNano(0),
-						ExecPlan:             "",
+						ExecPlan:             nil,
 					},
 					&StatementInfo{
 						StatementID:          _2TraceID,
 						TransactionID:        _1TxnID,
 						SessionID:            _1SesID,
-						TenantID:             321,
-						UserID:               567,
 						Account:              "MO",
 						User:                 "moroot",
 						Database:             "system",
@@ -1010,13 +1000,17 @@ func Test_genCsvData(t *testing.T) {
 						StatementFingerprint: "show databases",
 						StatementTag:         "dcl",
 						RequestAt:            util.TimeNano(time.Microsecond),
-						ExecPlan:             "",
+						ResponseAt:           util.TimeNano(time.Microsecond + time.Second),
+						Duration:             uint64(time.Microsecond + time.Second),
+						Status:               StatementStatusFailed,
+						Error:                fmt.Errorf("test error"),
+						ExecPlan:             nil,
 					},
 				},
 				buf: buf,
 			},
-			want: `00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,666,999,MO,moroot,,system,show tables,,show tables,node_uuid,Standalone,1970-01-01 00:00:00.000000,
-00000000-0000-0000-0000-000000000002,00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,321,567,MO,moroot,,system,show databases,dcl,show databases,node_uuid,Standalone,1970-01-01 00:00:00.000001,
+			want: `00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,MO,moroot,,system,show tables,,show tables,node_uuid,Standalone,1970-01-01 00:00:00.000000,1970-01-01 00:00:00.000000,0,Running,,{}
+00000000-0000-0000-0000-000000000002,00000000-0000-0000-0000-000000000001,00000000-0000-0000-0000-000000000001,MO,moroot,,system,show databases,dcl,show databases,node_uuid,Standalone,1970-01-01 00:00:00.000001,1970-01-01 00:00:01.000001,1000001000,Failed,test error,{}
 `,
 		},
 		{

pkg/util/trace/config.go

@@ -19,6 +19,7 @@ import (
 	"encoding/binary"
 	"encoding/hex"
 	"encoding/json"
+	"github.com/google/uuid"
 	"github.com/matrixorigin/matrixone/pkg/util"
 	"github.com/matrixorigin/matrixone/pkg/util/export"
 	ie "github.com/matrixorigin/matrixone/pkg/util/internalExecutor"
@@ -58,7 +59,7 @@ type tracerProviderConfig struct {
 	// registered.
 	spanProcessors []SpanProcessor
 
-	enableTracer uint32 // see EnableTracer
+	enable uint32 // see SetEnable
 
 	// idGenerator is used to generate all Span and Trace IDs when needed.
 	idGenerator IDGenerator
@@ -94,16 +95,16 @@ func (cfg *tracerProviderConfig) getNodeResource() *MONodeResource {
 func (cfg *tracerProviderConfig) IsEnable() bool {
 	cfg.mux.RLock()
 	defer cfg.mux.RUnlock()
-	return atomic.LoadUint32(&cfg.enableTracer) == 1
+	return atomic.LoadUint32(&cfg.enable) == 1
 }
 
-func (cfg *tracerProviderConfig) EnableTracer(enable bool) {
+func (cfg *tracerProviderConfig) SetEnable(enable bool) {
 	cfg.mux.Lock()
 	defer cfg.mux.Unlock()
 	if enable {
-		atomic.StoreUint32(&cfg.enableTracer, 1)
+		atomic.StoreUint32(&cfg.enable, 1)
 	} else {
-		atomic.StoreUint32(&cfg.enableTracer, 0)
+		atomic.StoreUint32(&cfg.enable, 0)
 	}
 }
 
@@ -136,7 +137,7 @@ func WithNode(uuid string, t string) tracerProviderOptionFunc {
 
 func EnableTracer(enable bool) tracerProviderOptionFunc {
 	return func(cfg *tracerProviderConfig) {
-		cfg.EnableTracer(enable)
+		cfg.SetEnable(enable)
 	}
 }
 
@@ -205,13 +206,11 @@ var nilTraceID TraceID
 
 // IsZero checks whether the trace TraceID is 0 value.
 func (t TraceID) IsZero() bool {
-	return !bytes.Equal(t[:], nilTraceID[:])
+	return bytes.Equal(t[:], nilTraceID[:])
 }
 
 func (t TraceID) String() string {
-	var dst [36]byte
-	bytes2Uuid(dst[:], t)
-	return string(dst[:])
+	return uuid.UUID(t).String()
 }
 
 type SpanID [8]byte
@@ -219,40 +218,20 @@ type SpanID [8]byte
 var nilSpanID SpanID
 
 // SetByUUID use prefix of uuid as value
-func (s *SpanID) SetByUUID(uuid string) {
-	var dst [16]byte
-	uuid2Bytes(dst[:], uuid)
-	copy(s[:], dst[0:8])
+func (s *SpanID) SetByUUID(id string) {
+	if u, err := uuid.Parse(id); err == nil {
+		copy(s[:], u[:])
+	} else {
+		copy(s[:], []byte(id)[:])
+	}
 }
 
-func (s SpanID) String() string {
-	return hex.EncodeToString(s[:])
+func (s *SpanID) IsZero() bool {
+	return bytes.Equal(s[:], nilSpanID[:])
 }
 
-func uuid2Bytes(dst []byte, uuid string) {
-	_ = dst[15]
-	l := len(uuid)
-	if l != 36 || uuid[8] != '-' || uuid[13] != '-' || uuid[18] != '-' || uuid[23] != '-' {
-		return
-	}
-	hex.Decode(dst[0:4], []byte(uuid[0:8]))
-	hex.Decode(dst[4:6], []byte(uuid[9:13]))
-	hex.Decode(dst[6:8], []byte(uuid[14:18]))
-	hex.Decode(dst[8:10], []byte(uuid[19:23]))
-	hex.Decode(dst[10:], []byte(uuid[24:]))
-}
-
-func bytes2Uuid(dst []byte, src [16]byte) {
-	_, _ = dst[35], src[15]
-	hex.Encode(dst[0:8], src[0:4])
-	hex.Encode(dst[9:13], src[4:6])
-	hex.Encode(dst[14:18], src[6:8])
-	hex.Encode(dst[19:23], src[8:10])
-	hex.Encode(dst[24:], src[10:])
-	dst[8] = '-'
-	dst[13] = '-'
-	dst[18] = '-'
-	dst[23] = '-'
+func (s SpanID) String() string {
+	return hex.EncodeToString(s[:])
 }
 
 var _ zapcore.ObjectMarshaler = (*SpanContext)(nil)
@@ -307,7 +286,7 @@ func (c *SpanContext) Reset() {
 }
 
 func (c *SpanContext) IsEmpty() bool {
-	return c.TraceID.IsZero()
+	return c.TraceID.IsZero() && c.SpanID.IsZero()
 }
 
 func (c *SpanContext) MarshalLogObject(enc zapcore.ObjectEncoder) error {
@@ -367,13 +346,24 @@ func WithNewRoot(newRoot bool) spanOptionFunc {
 	})
 }
 
+func WithTraceID(id TraceID) spanOptionFunc {
+	return spanOptionFunc(func(cfg *SpanConfig) {
+		cfg.TraceID = id
+	})
+}
+
+func WithSpanID(id SpanID) spanOptionFunc {
+	return spanOptionFunc(func(cfg *SpanConfig) {
+		cfg.SpanID = id
+	})
+}
+
 type Resource struct {
 	m map[string]any
 }
 
 func newResource() *Resource {
 	return &Resource{m: make(map[string]any)}
-
 }
 
 func (r *Resource) Put(key string, val any) {

pkg/logutil/logutil2/api_test.go → pkg/util/trace/config_test.go

-// Copyright 2021 Matrix Origin
+// Copyright 2022 Matrix Origin
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
@@ -12,145 +12,123 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-package logutil2
+package trace
 
 import (
-	"context"
-	"fmt"
+	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
-	"go.uber.org/zap"
 	"testing"
 )
 
-func TestLog(t *testing.T) {
-	type args struct {
-		ctx    context.Context
-		msg    string
-		fields []zap.Field
-	}
+func TestTraceID_IsZero(t *testing.T) {
 	tests := []struct {
 		name string
-		args args
+		t    TraceID
+		want bool
 	}{
 		{
 			name: "normal",
-			args: args{
-				ctx:    context.Background(),
-				msg:    "test",
-				fields: []zap.Field{zap.Int("int", 0), zap.String("string", "")},
-			},
+			t:    _1TraceID,
+			want: false,
+		},
+		{
+			name: "nil",
+			t:    nilTraceID,
+			want: true,
 		},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			Debug(tt.args.ctx, tt.args.msg, tt.args.fields...)
-			Info(tt.args.ctx, tt.args.msg, tt.args.fields...)
-			Warn(tt.args.ctx, tt.args.msg, tt.args.fields...)
-			Error(tt.args.ctx, tt.args.msg, tt.args.fields...)
+			assert.Equalf(t, tt.want, tt.t.IsZero(), "IsZero()")
 		})
 	}
 }
-func TestLog_panic(t *testing.T) {
+
+func TestSpanID_SetByUUID_IsZero(t *testing.T) {
 	type args struct {
-		ctx    context.Context
-		msg    string
-		fields []zap.Field
+		id string
 	}
 	tests := []struct {
-		name string
-		args args
+		name     string
+		s        SpanID
+		args     args
+		wantZero bool
 	}{
 		{
-			name: "normal",
-			args: args{
-				ctx:    context.Background(),
-				msg:    "test",
-				fields: []zap.Field{zap.Int("int", 0), zap.String("string", "")},
-			},
+			name:     "normal",
+			args:     args{id: "node_uuid"},
+			wantZero: false,
+		},
+		{
+			name:     "short",
+			args:     args{id: "1234"},
+			wantZero: false,
+		},
+		{
+			name:     "nil",
+			args:     args{id: "00000000-0000-0000-0000-000000000000"},
+			wantZero: true,
 		},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			defer func() {
-				err := recover()
-				require.Equal(t, tt.args.msg, fmt.Sprintf("%s", err))
-			}()
-			Panic(tt.args.ctx, tt.args.msg, tt.args.fields...)
+			tt.s.SetByUUID(tt.args.id)
+			t.Logf("SpanID: %s", tt.s.String())
+			require.Equal(t, tt.wantZero, tt.s.IsZero())
 		})
 	}
 }
 
-func TestLogf(t *testing.T) {
-	type args struct {
-		ctx    context.Context
-		msg    string
-		fields []any
+func TestSpanContext_IsEmpty(t *testing.T) {
+	type fields struct {
+		TraceID TraceID
+		SpanID  SpanID
 	}
 	tests := []struct {
-		name string
-		args args
+		name   string
+		fields fields
+		want   bool
 	}{
 		{
-			name: "empty",
-			args: args{
-				ctx:    context.Background(),
-				msg:    "test",
-				fields: []any{},
+			name: "normal",
+			fields: fields{
+				TraceID: _1TraceID,
+				SpanID:  _1SpanID,
 			},
+			want: false,
 		},
 		{
-			name: "normal",
-			args: args{
-				ctx:    context.Background(),
-				msg:    "hello %s",
-				fields: []any{"world"},
+			name: "nilTraceID",
+			fields: fields{
+				TraceID: nilTraceID,
+				SpanID:  _1SpanID,
 			},
+			want: false,
 		},
-	}
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			Debugf(tt.args.ctx, tt.args.msg, tt.args.fields...)
-			Infof(tt.args.ctx, tt.args.msg, tt.args.fields...)
-			Warnf(tt.args.ctx, tt.args.msg, tt.args.fields...)
-			Errorf(tt.args.ctx, tt.args.msg, tt.args.fields...)
-		})
-	}
-}
-
-func TestLogf_panic(t *testing.T) {
-	type args struct {
-		ctx    context.Context
-		msg    string
-		fields []any
-	}
-	tests := []struct {
-		name string
-		args args
-	}{
 		{
-			name: "empty",
-			args: args{
-				ctx:    context.Background(),
-				msg:    "test",
-				fields: []any{},
+			name: "nilSpanID",
+			fields: fields{
+				TraceID: _1TraceID,
+				SpanID:  nilSpanID,
 			},
+			want: false,
 		},
 		{
-			name: "normal",
-			args: args{
-				ctx:    context.Background(),
-				msg:    "hello %s",
-				fields: []any{"world"},
+			name: "nil",
+			fields: fields{
+				TraceID: nilTraceID,
+				SpanID:  nilSpanID,
 			},
+			want: true,
 		},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			defer func() {
-				err := recover()
-				require.Equal(t, fmt.Sprintf(tt.args.msg, tt.args.fields...), fmt.Sprintf("%s", err))
-			}()
-			Panicf(tt.args.ctx, tt.args.msg, tt.args.fields...)
+			c := &SpanContext{
+				TraceID: tt.fields.TraceID,
+				SpanID:  tt.fields.SpanID,
+			}
+			assert.Equalf(t, tt.want, c.IsEmpty(), "IsEmpty()")
 		})
 	}
 }