diff --git a/cmd/mo-service/debug.go b/cmd/mo-service/debug.go index bc98397fc53a7..b1b40f49a748c 100644 --- a/cmd/mo-service/debug.go +++ b/cmd/mo-service/debug.go @@ -404,14 +404,16 @@ func saveProfilesLoop(sigs chan os.Signal) { quit := false tk := time.NewTicker(*profileInterval) - logutil.GetGlobalLogger().Info("save profiles loop started", zap.Duration("profile-interval", *profileInterval), zap.Duration("cpuProfileInterval", cpuProfileInterval)) + logutil.Info( + "save.profiles.loop.started", + zap.Duration("interval", *profileInterval), + zap.Duration("duration", cpuProfileInterval), + ) for { select { case <-tk.C: - logutil.GetGlobalLogger().Info("save profiles start") saveProfiles() saveCpuProfile(cpuProfileInterval) - logutil.GetGlobalLogger().Info("save profiles end") case <-sigs: quit = true } @@ -435,20 +437,29 @@ func saveProfiles() { func saveProfile(typ string) string { name, _ := uuid.NewV7() profilePath := catalog.BuildProfilePath(globalServiceType, globalNodeId, typ, name.String()) + ".gz" - logutil.GetGlobalLogger().Info("save profiles ", zap.String("path", profilePath)) cnservice.SaveProfile(profilePath, typ, globalEtlFS) return profilePath } func saveCpuProfile(cpuProfileInterval time.Duration) { + // Skip CPU profile if already in use (e.g., started via -cpu-profile flag) + if *cpuProfilePathFlag != "" { + logutil.GetGlobalLogger().Debug("skip cpu profile generation, cpu profiling already enabled via -cpu-profile flag") + return + } + genCpuProfile := func(writer io.Writer) error { err := pprof.StartCPUProfile(writer) if err != nil { + // If CPU profiling is already in use, skip silently + if strings.Contains(err.Error(), "cpu profiling already in use") { + return nil + } return err } time.Sleep(cpuProfileInterval) pprof.StopCPUProfile() - return err + return nil } saveProfileWithType("cpu", genCpuProfile) } diff --git a/pkg/bootstrap/versions/upgrade_strategy.go b/pkg/bootstrap/versions/upgrade_strategy.go index b317a822485fd..0136f5e315f57 100644 --- a/pkg/bootstrap/versions/upgrade_strategy.go +++ b/pkg/bootstrap/versions/upgrade_strategy.go @@ -250,7 +250,7 @@ func CheckTableColumn(txn executor.TxnExecutor, AND att_database = '%s' and att_relname = '%s' and attname = '%s';`, schema, tableName, columnName) } - res, err := txn.Exec(sql, executor.StatementOption{}.WithAccountID(accountId)) + res, err := txn.Exec(sql, executor.StatementOption{}.WithAccountID(accountId).WithDisableLog()) if err != nil { return colInfo, err } @@ -292,7 +292,7 @@ var CheckViewDefinition = func(txn executor.TxnExecutor, accountId uint32, schem sql = fmt.Sprintf("SELECT tbl.rel_createsql AS `VIEW_DEFINITION` FROM mo_catalog.mo_tables tbl LEFT JOIN mo_catalog.mo_user usr ON tbl.creator = usr.user_id WHERE tbl.relkind = 'v' AND account_id = 0 AND tbl.reldatabase = '%s' AND tbl.relname = '%s'", schema, viewName) } - res, err := txn.Exec(sql, executor.StatementOption{}.WithAccountID(accountId)) + res, err := txn.Exec(sql, executor.StatementOption{}.WithAccountID(accountId).WithDisableLog()) if err != nil { return false, "", err } @@ -330,7 +330,7 @@ var CheckTableDefinition = func(txn executor.TxnExecutor, accountId uint32, sche AND account_id = 0 AND reldatabase = '%s' AND relname = '%s'`, schema, tableName) } - res, err := txn.Exec(sql, executor.StatementOption{}.WithAccountID(accountId)) + res, err := txn.Exec(sql, executor.StatementOption{}.WithAccountID(accountId).WithDisableLog()) if err != nil { return false, err } diff --git a/pkg/cdc/table_scanner.go b/pkg/cdc/table_scanner.go index b53deb1e44765..f7f9495bb990d 100644 --- a/pkg/cdc/table_scanner.go +++ b/pkg/cdc/table_scanner.go @@ -31,6 +31,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/catalog" "github.com/matrixorigin/matrixone/pkg/common/moerr" "github.com/matrixorigin/matrixone/pkg/common/runtime" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/container/types" "github.com/matrixorigin/matrixone/pkg/container/vector" "github.com/matrixorigin/matrixone/pkg/defines" @@ -646,7 +647,7 @@ func (s *TableDetector) cleanupOrphanWatermarks(ctx context.Context) { fields := []zap.Field{ zap.Uint64("deleted-rows", res.AffectedRows), zap.Duration("duration", duration), - zap.String("sql", sql), + zap.String("sql", commonutil.Abbreviate(sql, 500)), } if duration > s.cleanupWarn { logutil.Warn( diff --git a/pkg/cdc/util.go b/pkg/cdc/util.go index 3c0fc652ec99f..5dfca6bd815ff 100644 --- a/pkg/cdc/util.go +++ b/pkg/cdc/util.go @@ -135,7 +135,7 @@ func extractRowFromVector(ctx context.Context, vec *vector.Vector, i int, row [] switch vec.GetType().Oid { //get col case types.T_json: - row[i] = types.DecodeJson(copyBytes(vec.GetBytesAt(rowIndex))) + row[i] = types.DecodeJson(vec.CloneBytesAt(rowIndex)) case types.T_bool: row[i] = vector.GetFixedAtWithTypeCheck[bool](vec, rowIndex) case types.T_bit: @@ -161,7 +161,7 @@ func extractRowFromVector(ctx context.Context, vec *vector.Vector, i int, row [] case types.T_float64: row[i] = vector.GetFixedAtWithTypeCheck[float64](vec, rowIndex) case types.T_char, types.T_varchar, types.T_blob, types.T_text, types.T_binary, types.T_varbinary, types.T_datalink: - row[i] = copyBytes(vec.GetBytesAt(rowIndex)) + row[i] = vec.CloneBytesAt(rowIndex) case types.T_array_float32: // NOTE: Don't merge it with T_varchar. You will get raw binary in the SQL output //+------------------------------+ @@ -211,16 +211,6 @@ func extractRowFromVector(ctx context.Context, vec *vector.Vector, i int, row [] return nil } -func copyBytes(src []byte) []byte { - if len(src) > 0 { - dst := make([]byte, len(src)) - copy(dst, src) - return dst - } else { - return []byte{} - } -} - func convertColIntoSql( ctx context.Context, data any, diff --git a/pkg/cdc/util_test.go b/pkg/cdc/util_test.go index 00782dcc28714..6e72d3957a43d 100644 --- a/pkg/cdc/util_test.go +++ b/pkg/cdc/util_test.go @@ -28,6 +28,7 @@ import ( "github.com/stretchr/testify/require" "github.com/matrixorigin/matrixone/pkg/common/moerr" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/container/batch" "github.com/matrixorigin/matrixone/pkg/container/bytejson" "github.com/matrixorigin/matrixone/pkg/container/types" @@ -438,7 +439,7 @@ func Test_copyBytes(t *testing.T) { } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - assert.Equalf(t, tt.want, copyBytes(tt.args.src), "copyBytes(%v)", tt.args.src) + assert.Equalf(t, tt.want, commonutil.CloneBytes(tt.args.src), "copyBytes(%v)", tt.args.src) }) } } diff --git a/pkg/cnservice/server.go b/pkg/cnservice/server.go index e906696745f02..c61dfc69c3129 100644 --- a/pkg/cnservice/server.go +++ b/pkg/cnservice/server.go @@ -999,15 +999,26 @@ func SaveProfile(profilePath string, profileType string, etlFS fileservice.FileS } err := profile.ProfileRuntime(profileType, gzWriter, debug) if err != nil { - logutil.Errorf("get profile of %s failed. err:%v", profilePath, err) + logutil.Error( + "profile.save.runtime.failed", + zap.String("path", profilePath), + zap.Error(err), + ) return } err = gzWriter.Close() if err != nil { - logutil.Errorf("close gzip write of %s failed. err:%v", profilePath, err) + logutil.Error( + "profile.writer.close.failed", + zap.String("path", profilePath), + zap.Error(err), + ) return } - logutil.Info("get profile done. save profiles ", zap.String("path", profilePath)) + logutil.Info( + "profile.save.get.ok", + zap.String("path", profilePath), + ) writeVec := fileservice.IOVector{ FilePath: profilePath, Entries: []fileservice.IOEntry{ @@ -1023,7 +1034,11 @@ func SaveProfile(profilePath string, profileType string, etlFS fileservice.FileS err = etlFS.Write(ctx, writeVec) if err != nil { err = moerr.AttachCause(ctx, err) - logutil.Errorf("save profile %s failed. err:%v", profilePath, err) + logutil.Error( + "profile.save.failed", + zap.String("path", profilePath), + zap.Error(err), + ) return } } diff --git a/pkg/cnservice/server_query.go b/pkg/cnservice/server_query.go index 3f268446b6574..d4aeb3f568e7e 100644 --- a/pkg/cnservice/server_query.go +++ b/pkg/cnservice/server_query.go @@ -22,6 +22,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/common/moerr" "github.com/matrixorigin/matrixone/pkg/common/morpc" "github.com/matrixorigin/matrixone/pkg/common/system" + commonUtil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/container/types" "github.com/matrixorigin/matrixone/pkg/defines" "github.com/matrixorigin/matrixone/pkg/fileservice" @@ -345,15 +346,9 @@ func copyWaitTxn(src pblock.WaitTxn) *pblock.WaitTxn { return dst } -func copyBytes(src []byte) []byte { - dst := make([]byte, len(src)) - copy(dst, src) - return dst -} - func copyTxnMeta(src txn.TxnMeta) *txn.TxnMeta { dst := &txn.TxnMeta{ - ID: copyBytes(src.GetID()), + ID: commonUtil.CloneBytes(src.GetID()), Status: src.GetStatus(), SnapshotTS: src.GetSnapshotTS(), PreparedTS: src.GetPreparedTS(), diff --git a/pkg/common/moerr/error.go b/pkg/common/moerr/error.go index bb7666aa6ad04..300a86bb27774 100644 --- a/pkg/common/moerr/error.go +++ b/pkg/common/moerr/error.go @@ -816,7 +816,8 @@ func NewBadS3Config(ctx context.Context, msg string) *Error { } func NewInternalErrorf(ctx context.Context, format string, args ...any) *Error { - return NewInternalError(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrInternal, msg) } func NewInternalError(ctx context.Context, msg string) *Error { @@ -836,7 +837,8 @@ func NewNYI(ctx context.Context, msg string) *Error { } func NewNotSupportedf(ctx context.Context, format string, args ...any) *Error { - return NewNotSupported(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrNotSupported, msg) } func NewNotSupported(ctx context.Context, msg string) *Error { @@ -856,7 +858,8 @@ func NewDivByZero(ctx context.Context) *Error { } func NewOutOfRangef(ctx context.Context, typ string, format string, args ...any) *Error { - return NewOutOfRange(ctx, typ, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrOutOfRange, typ, msg) } func NewOutOfRange(ctx context.Context, typ string, msg string) *Error { @@ -864,15 +867,13 @@ func NewOutOfRange(ctx context.Context, typ string, msg string) *Error { } func NewDataTruncatedf(ctx context.Context, typ string, format string, args ...any) *Error { - return NewDataTruncated(ctx, typ, fmt.Sprintf(format, args...)) -} - -func NewDataTruncated(ctx context.Context, typ string, msg string) *Error { + msg := fmt.Sprintf(format, args...) return newError(ctx, ErrDataTruncated, typ, msg) } func NewInvalidArg(ctx context.Context, arg string, val any) *Error { - return newError(ctx, ErrInvalidArg, arg, fmt.Sprintf("%v", val)) + msg := fmt.Sprintf("%v", val) + return newError(ctx, ErrInvalidArg, arg, msg) } func NewTruncatedValueForField(ctx context.Context, t, v, c string, idx int) *Error { @@ -880,7 +881,8 @@ func NewTruncatedValueForField(ctx context.Context, t, v, c string, idx int) *Er } func NewBadConfigf(ctx context.Context, format string, args ...any) *Error { - return NewBadConfig(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrBadConfig, msg) } func NewBadConfig(ctx context.Context, msg string) *Error { @@ -888,7 +890,8 @@ func NewBadConfig(ctx context.Context, msg string) *Error { } func NewInvalidInputf(ctx context.Context, format string, args ...any) *Error { - return NewInvalidInput(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrInvalidInput, msg) } func NewInvalidInput(ctx context.Context, msg string) *Error { @@ -896,7 +899,8 @@ func NewInvalidInput(ctx context.Context, msg string) *Error { } func NewSyntaxErrorf(ctx context.Context, format string, args ...any) *Error { - return NewSyntaxError(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrSyntaxError, msg) } func NewSyntaxError(ctx context.Context, msg string) *Error { @@ -904,23 +908,26 @@ func NewSyntaxError(ctx context.Context, msg string) *Error { } func NewParseErrorf(ctx context.Context, format string, args ...any) *Error { - return NewParseError(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrParseError, msg) } func NewParseError(ctx context.Context, msg string) *Error { return newError(ctx, ErrParseError, msg) } func NewConstraintViolationf(ctx context.Context, format string, args ...any) *Error { - return NewConstraintViolation(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrConstraintViolation, msg) } func NewConstraintViolation(ctx context.Context, msg string) *Error { return newError(ctx, ErrConstraintViolation, msg) } -func NewUnsupportedDML(ctx context.Context, msg string, args ...any) *Error { - xmsg := fmt.Sprintf(msg, args...) - return newError(ctx, ErrUnsupportedDML, xmsg) +func NewUnsupportedDML(ctx context.Context, format string, args ...any) *Error { + msg := fmt.Sprintf(format, args...) + noReportCtx := errutil.ContextWithNoReport(ctx, true) + return newError(noReportCtx, ErrUnsupportedDML, msg) } func NewEmptyVector(ctx context.Context) *Error { @@ -972,7 +979,8 @@ func NewInvalidPath(ctx context.Context, f string) *Error { } func NewInvalidStatef(ctx context.Context, format string, args ...any) *Error { - return NewInvalidState(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrInvalidState, msg) } func NewInvalidState(ctx context.Context, msg string) *Error { @@ -1072,7 +1080,8 @@ func NewTxnClosed(ctx context.Context, txnID []byte) *Error { } func NewTxnWriteConflictf(ctx context.Context, format string, args ...any) *Error { - return NewTxnWriteConflict(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrTxnWriteConflict, msg) } func NewTxnWriteConflict(ctx context.Context, msg string) *Error { @@ -1088,7 +1097,8 @@ func NewUnresolvedConflict(ctx context.Context) *Error { } func NewTxnErrorf(ctx context.Context, format string, args ...any) *Error { - return NewTxnError(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrTxnError, msg) } func NewTxnError(ctx context.Context, msg string) *Error { @@ -1096,7 +1106,8 @@ func NewTxnError(ctx context.Context, msg string) *Error { } func NewTAEErrorf(ctx context.Context, format string, args ...any) *Error { - return NewTAEError(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrTAEError, msg) } func NewTAEError(ctx context.Context, msg string) *Error { @@ -1112,7 +1123,8 @@ func NewShardNotReported(ctx context.Context, uuid string, id uint64) *Error { } func NewDragonboatTimeoutf(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatTimeout(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatTimeout, msg) } func NewDragonboatTimeout(ctx context.Context, msg string) *Error { @@ -1120,7 +1132,8 @@ func NewDragonboatTimeout(ctx context.Context, msg string) *Error { } func NewDragonboatTimeoutTooSmallf(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatTimeoutTooSmall(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatTimeoutTooSmall, msg) } func NewDragonboatTimeoutTooSmall(ctx context.Context, msg string) *Error { @@ -1128,7 +1141,8 @@ func NewDragonboatTimeoutTooSmall(ctx context.Context, msg string) *Error { } func NewDragonboatInvalidDeadlinef(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatInvalidDeadline(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatInvalidDeadline, msg) } func NewDragonboatInvalidDeadline(ctx context.Context, msg string) *Error { @@ -1136,7 +1150,8 @@ func NewDragonboatInvalidDeadline(ctx context.Context, msg string) *Error { } func NewDragonboatRejectedf(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatRejected(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatRejected, msg) } func NewDragonboatRejected(ctx context.Context, msg string, args ...any) *Error { @@ -1144,7 +1159,8 @@ func NewDragonboatRejected(ctx context.Context, msg string, args ...any) *Error } func NewDragonboatInvalidPayloadSizef(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatInvalidPayloadSize(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatInvalidPayloadSize, msg) } func NewDragonboatInvalidPayloadSize(ctx context.Context, msg string) *Error { @@ -1152,7 +1168,8 @@ func NewDragonboatInvalidPayloadSize(ctx context.Context, msg string) *Error { } func NewDragonboatShardNotReadyf(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatShardNotReady(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatShardNotReady, msg) } func NewDragonboatShardNotReady(ctx context.Context, msg string) *Error { @@ -1160,21 +1177,24 @@ func NewDragonboatShardNotReady(ctx context.Context, msg string) *Error { } func NewDragonboatSystemClosedf(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatSystemClosed(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatSystemClosed, msg) } func NewDragonboatSystemClosed(ctx context.Context, msg string) *Error { return newError(ctx, ErrDragonboatSystemClosed, msg) } func NewDragonboatInvalidRangef(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatInvalidRange(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatInvalidRange, msg) } func NewDragonboatInvalidRange(ctx context.Context, msg string) *Error { return newError(ctx, ErrDragonboatInvalidRange, msg) } func NewDragonboatShardNotFoundf(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatShardNotFound(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatShardNotFound, msg) } func NewDragonboatShardNotFound(ctx context.Context, msg string) *Error { @@ -1182,7 +1202,8 @@ func NewDragonboatShardNotFound(ctx context.Context, msg string) *Error { } func NewDragonboatOtherSystemErrorf(ctx context.Context, format string, args ...any) *Error { - return NewDragonboatOtherSystemError(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrDragonboatOtherSystemError, msg) } func NewDragonboatOtherSystemError(ctx context.Context, msg string) *Error { @@ -1218,7 +1239,8 @@ func NewTAEWrite(ctx context.Context) *Error { } func NewTAECommitf(ctx context.Context, format string, args ...any) *Error { - return NewTAECommit(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrTAECommit, msg) } func NewTAECommit(ctx context.Context, msg string) *Error { @@ -1226,7 +1248,8 @@ func NewTAECommit(ctx context.Context, msg string) *Error { } func NewTAERollbackf(ctx context.Context, format string, args ...any) *Error { - return NewTAERollback(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrTAERollback, msg) } func NewTAERollback(ctx context.Context, msg string) *Error { @@ -1234,7 +1257,8 @@ func NewTAERollback(ctx context.Context, msg string) *Error { } func NewTAEPreparef(ctx context.Context, format string, args ...any) *Error { - return NewTAEPrepare(ctx, fmt.Sprintf(format, args...)) + msg := fmt.Sprintf(format, args...) + return newError(ctx, ErrTAEPrepare, msg) } func NewTAEPrepare(ctx context.Context, msg string) *Error { diff --git a/pkg/common/moerr/error_no_ctx.go b/pkg/common/moerr/error_no_ctx.go index 11936a6104345..e85615ace870f 100644 --- a/pkg/common/moerr/error_no_ctx.go +++ b/pkg/common/moerr/error_no_ctx.go @@ -17,6 +17,8 @@ package moerr import ( "encoding/hex" "fmt" + + "github.com/matrixorigin/matrixone/pkg/util/errutil" ) func NewInfoNoCtx(msg string) *Error { @@ -314,8 +316,12 @@ func NewTAENeedRetryNoCtx() *Error { return newError(Context(), ErrTAENeedRetry) } -func NewTxnStaleNoCtx(msg string) *Error { - return newError(Context(), ErrTxnStale, msg) +func NewTxnStaleNoCtxf( + format string, args ...any, +) *Error { + msg := fmt.Sprintf(format, args...) + ctx := errutil.ContextWithNoReport(Context(), true) + return newError(ctx, ErrTxnStale, msg) } func NewRetryForCNRollingRestart() *Error { diff --git a/pkg/common/moerr/error_test.go b/pkg/common/moerr/error_test.go index 01561b80e56a8..99a2d08f4f64d 100644 --- a/pkg/common/moerr/error_test.go +++ b/pkg/common/moerr/error_test.go @@ -192,3 +192,63 @@ func TestNewErrTooBigPrecision(t *testing.T) { require.True(t, ok) require.Equal(t, ErrTooBigPrecision, code) } + +func Test_ForCoverage(t *testing.T) { + ctx := context.Background() + err := NewDataTruncatedf(ctx, "test", "test") + require.True(t, IsMoErrCode(err, ErrDataTruncated)) + + err = NewConstraintViolationf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrConstraintViolation)) + + err = NewTxnWriteConflictf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrTxnWriteConflict)) + + err = NewTxnErrorf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrTxnError)) + + err = NewTAEErrorf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrTAEError)) + + err = NewDragonboatTimeoutf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatTimeout)) + + err = NewDragonboatTimeoutTooSmallf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatTimeoutTooSmall)) + + err = NewDragonboatInvalidDeadlinef(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatInvalidDeadline)) + + err = NewDragonboatRejectedf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatRejected)) + + err = NewDragonboatInvalidPayloadSizef(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatInvalidPayloadSize)) + + err = NewDragonboatShardNotReadyf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatShardNotReady)) + + err = NewDragonboatSystemClosedf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatSystemClosed)) + + err = NewDragonboatInvalidRangef(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatInvalidRange)) + + err = NewDragonboatShardNotFoundf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatShardNotFound)) + + err = NewDragonboatOtherSystemErrorf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrDragonboatOtherSystemError)) + + err = NewTAECommitf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrTAECommit)) + + err = NewTAERollbackf(ctx, "test") + require.True(t, IsMoErrCode(err, ErrTAERollback)) + + err = NewTAEPreparef(ctx, "test") + require.True(t, IsMoErrCode(err, ErrTAEPrepare)) + + err = NewTxnStaleNoCtxf("test") + require.True(t, IsMoErrCode(err, ErrTxnStale)) +} diff --git a/pkg/common/util/bytes.go b/pkg/common/util/bytes.go new file mode 100644 index 0000000000000..34a8b24827e6f --- /dev/null +++ b/pkg/common/util/bytes.go @@ -0,0 +1,41 @@ +// 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 util + +// CloneBytesIf conditionally copies a byte slice. +// If clone is true, it returns a new copy of the slice. +// If clone is false, it returns the original slice without copying. +// If the source slice is empty, it returns an empty slice. +func CloneBytesIf(src []byte, clone bool) []byte { + if clone { + if len(src) > 0 { + dst := make([]byte, len(src)) + copy(dst, src) + return dst + } + return []byte{} + } + return src +} + +// new copy of the slice +func CloneBytes(src []byte) []byte { + if len(src) > 0 { + ret := make([]byte, len(src)) + copy(ret, src) + return ret + } + return make([]byte, 0) +} diff --git a/pkg/common/util/bytes_test.go b/pkg/common/util/bytes_test.go new file mode 100644 index 0000000000000..01e963a180f77 --- /dev/null +++ b/pkg/common/util/bytes_test.go @@ -0,0 +1,88 @@ +// 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 util + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +func TestCopyBytes(t *testing.T) { + tests := []struct { + name string + src []byte + needCopy bool + want []byte + wantSame bool // whether the returned slice is the same as src (when needCopy=false) + }{ + { + name: "empty slice, needCopy=true", + src: []byte{}, + needCopy: true, + want: []byte{}, + wantSame: false, + }, + { + name: "empty slice, needCopy=false", + src: []byte{}, + needCopy: false, + want: []byte{}, + wantSame: true, + }, + { + name: "non-empty slice, needCopy=true", + src: []byte{'a', 'b', 'c'}, + needCopy: true, + want: []byte{'a', 'b', 'c'}, + wantSame: false, + }, + { + name: "non-empty slice, needCopy=false", + src: []byte{'a', 'b', 'c'}, + needCopy: false, + want: []byte{'a', 'b', 'c'}, + wantSame: true, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := CloneBytesIf(tt.src, tt.needCopy) + assert.Equal(t, tt.want, got, "CopyBytes(%v, %v)", tt.src, tt.needCopy) + + // Check if the returned slice is the same as src when needCopy=false + if tt.needCopy { + // When needCopy=true, the slice should be a copy + if len(tt.src) > 0 { + assert.NotSame(t, &tt.src[0], &got[0], "CopyBytes should return a new slice when needCopy=true") + } + } else { + // When needCopy=false, the slice should be the same + if len(tt.src) > 0 { + assert.Same(t, &tt.src[0], &got[0], "CopyBytes should return the same slice when needCopy=false") + } + } + + // Verify that modifying the original doesn't affect the copy when needCopy=true + if tt.needCopy && len(tt.src) > 0 { + original := make([]byte, len(tt.src)) + copy(original, tt.src) + tt.src[0] = 'x' + assert.Equal(t, original, got, "CopyBytes should return an independent copy when needCopy=true") + } + }) + } +} diff --git a/pkg/common/util/string.go b/pkg/common/util/string.go new file mode 100644 index 0000000000000..45039e208efcc --- /dev/null +++ b/pkg/common/util/string.go @@ -0,0 +1,38 @@ +// 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 util + +// Abbreviate truncates a string from the beginning to the specified length. +// Parameters: +// - str: the input string +// - length: the maximum length to truncate to +// -1: return the complete string +// 0: return empty string +// >0: return the first 'length' characters, appending "..." if truncated +func Abbreviate(str string, length int) string { + if length == 0 || length < -1 { + return "" + } + + if length == -1 { + return str + } + + l := min(len(str), length) + if l != len(str) { + return str[:l] + "..." + } + return str[:l] +} diff --git a/pkg/common/util/string_test.go b/pkg/common/util/string_test.go new file mode 100644 index 0000000000000..51773ab2e28d9 --- /dev/null +++ b/pkg/common/util/string_test.go @@ -0,0 +1,53 @@ +// 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 util + +import ( + "testing" + + "github.com/smartystreets/goconvey/convey" +) + +func TestSubStringFromBegin(t *testing.T) { + convey.Convey("SubStringFromBegin", t, func() { + // Test normal truncation + convey.So(Abbreviate("abcdef", 3), convey.ShouldEqual, "abc...") + + // Test string shorter than length + convey.So(Abbreviate("abc", 5), convey.ShouldEqual, "abc") + + // Test exact length match + convey.So(Abbreviate("abc", 3), convey.ShouldEqual, "abc") + + // Test empty string + convey.So(Abbreviate("", 5), convey.ShouldEqual, "") + + // Test length 0 + convey.So(Abbreviate("abcdef", 0), convey.ShouldEqual, "") + + // Test length -1 (return complete string) + convey.So(Abbreviate("abcdef", -1), convey.ShouldEqual, "abcdef") + + // Test length < -1 + convey.So(Abbreviate("abcdef", -2), convey.ShouldEqual, "") + + // Test long string + longStr := "a" + string(make([]byte, 2000)) + result := Abbreviate(longStr, 1024) + convey.So(len(result), convey.ShouldEqual, 1027) // 1024 + "..." + convey.So(result[:1024], convey.ShouldEqual, longStr[:1024]) + convey.So(result[1024:], convey.ShouldEqual, "...") + }) +} diff --git a/pkg/frontend/data_branch.go b/pkg/frontend/data_branch.go index a77a400c95040..99eb2519c4efb 100644 --- a/pkg/frontend/data_branch.go +++ b/pkg/frontend/data_branch.go @@ -4389,9 +4389,9 @@ func compareSingleValInVector( // Use raw values to avoid format conversions in extractRowFromVector. switch vec1.GetType().Oid { case types.T_json: - val1 := types.DecodeJson(copyBytes(vec1.GetBytesAt(rowIdx1), false)) - val2 := types.DecodeJson(copyBytes(vec2.GetBytesAt(rowIdx2), false)) - return types.CompareValue(val1, val2), nil + val1 := types.DecodeJson(vec1.GetBytesAt(rowIdx1)) + val2 := types.DecodeJson(vec2.GetBytesAt(rowIdx2)) + return bytejson.CompareByteJson(val1, val2), nil case types.T_bool: val1 := vector.GetFixedAtNoTypeCheck[bool](vec1, rowIdx1) val2 := vector.GetFixedAtNoTypeCheck[bool](vec2, rowIdx2) @@ -4441,9 +4441,10 @@ func compareSingleValInVector( val2 := vector.GetFixedAtNoTypeCheck[float64](vec2, rowIdx2) return types.CompareValue(val1, val2), nil case types.T_char, types.T_varchar, types.T_blob, types.T_text, types.T_binary, types.T_varbinary, types.T_datalink: - val1 := copyBytes(vec1.GetBytesAt(rowIdx1), false) - val2 := copyBytes(vec2.GetBytesAt(rowIdx2), false) - return types.CompareValue(val1, val2), nil + return bytes.Compare( + vec1.GetBytesAt(rowIdx1), + vec2.GetBytesAt(rowIdx2), + ), nil case types.T_array_float32: val1 := vector.GetArrayAt[float32](vec1, rowIdx1) val2 := vector.GetArrayAt[float32](vec2, rowIdx2) diff --git a/pkg/frontend/mysql_buffer.go b/pkg/frontend/mysql_buffer.go index 97c770272feaa..ffdee8741f065 100644 --- a/pkg/frontend/mysql_buffer.go +++ b/pkg/frontend/mysql_buffer.go @@ -582,7 +582,7 @@ func (c *Conn) Append(elems ...byte) (err error) { for cutIndex < len(elems) { // if bufferLength > 16MB, split packet remainPacketSpace := int(MaxPayloadSize) - c.packetLength - writeLength := Min(remainPacketSpace, len(elems[cutIndex:])) + writeLength := min(remainPacketSpace, len(elems[cutIndex:])) err = AppendPart(c, elems[cutIndex:cutIndex+writeLength]) if err != nil { return err diff --git a/pkg/frontend/mysql_cmd_executor.go b/pkg/frontend/mysql_cmd_executor.go index 4a37c847c3a27..2195f0ebbdb8f 100644 --- a/pkg/frontend/mysql_cmd_executor.go +++ b/pkg/frontend/mysql_cmd_executor.go @@ -42,7 +42,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/common/moerr" "github.com/matrixorigin/matrixone/pkg/common/pubsub" "github.com/matrixorigin/matrixone/pkg/common/runtime" - "github.com/matrixorigin/matrixone/pkg/common/util" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/container/batch" "github.com/matrixorigin/matrixone/pkg/container/types" "github.com/matrixorigin/matrixone/pkg/container/vector" @@ -155,7 +155,7 @@ var RecordStatement = func(ctx context.Context, ses *Session, proc *process.Proc bb.WriteString(envStmt) bb.WriteString(" // ") bb.WriteString(execSql) - text = SubStringFromBegin(bb.String(), int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)) + text = commonutil.Abbreviate(bb.String(), int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)) } else { // ignore envStmt == "" // case: exec `set @t = 2;` will trigger an internal query with the same session. @@ -163,11 +163,11 @@ var RecordStatement = func(ctx context.Context, ses *Session, proc *process.Proc // + fmtCtx := tree.NewFmtCtx(dialect.MYSQL, tree.WithQuoteString(true)) // + cw.GetAst().Format(fmtCtx) // + envStmt = fmtCtx.String() - text = SubStringFromBegin(envStmt, int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)) + text = commonutil.Abbreviate(envStmt, int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)) } } else { stmID, _ = uuid.NewV7() - text = SubStringFromBegin(envStmt, int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)) + text = commonutil.Abbreviate(envStmt, int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)) } ses.SetStmtId(stmID) ses.SetStmtType(getStatementType(statement).GetStatementType()) @@ -3311,9 +3311,9 @@ func ExecRequest(ses *Session, execCtx *ExecCtx, req *Request) (resp *Response, case COM_QUIT: return resp, moerr.GetMysqlClientQuit() case COM_QUERY: - var query = util.UnsafeBytesToString(req.GetData().([]byte)) + var query = commonutil.UnsafeBytesToString(req.GetData().([]byte)) ses.addSqlCount(1) - ses.Debug(execCtx.reqCtx, "query trace", logutil.QueryField(SubStringFromBegin(query, int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)))) + ses.Debug(execCtx.reqCtx, "query trace", logutil.QueryField(commonutil.Abbreviate(query, int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)))) input := &UserInput{sql: query} err = doComQuery(ses, execCtx, input) if err != nil { @@ -3325,7 +3325,7 @@ func ExecRequest(ses *Session, execCtx *ExecCtx, req *Request) (resp *Response, } return resp, nil case COM_INIT_DB: - var dbname = util.UnsafeBytesToString(req.GetData().([]byte)) + var dbname = commonutil.UnsafeBytesToString(req.GetData().([]byte)) ses.addSqlCount(1) query := "use `" + dbname + "`" err = doComQuery(ses, execCtx, &UserInput{sql: query}) @@ -3335,7 +3335,7 @@ func ExecRequest(ses *Session, execCtx *ExecCtx, req *Request) (resp *Response, return resp, nil case COM_FIELD_LIST: - var payload = util.UnsafeBytesToString(req.GetData().([]byte)) + var payload = commonutil.UnsafeBytesToString(req.GetData().([]byte)) ses.addSqlCount(1) query := makeCmdFieldListSql(payload) err = doComQuery(ses, execCtx, &UserInput{sql: query}) @@ -3351,7 +3351,7 @@ func ExecRequest(ses *Session, execCtx *ExecCtx, req *Request) (resp *Response, case COM_STMT_PREPARE: ses.SetCmd(COM_STMT_PREPARE) - sql = util.UnsafeBytesToString(req.GetData().([]byte)) + sql = commonutil.UnsafeBytesToString(req.GetData().([]byte)) ses.addSqlCount(1) // rewrite to "Prepare stmt_name from 'xxx'" @@ -3603,11 +3603,11 @@ func convertMysqlTextTypeToBlobType(col *MysqlColumn) { // build plan json when marhal plan error func buildErrorJsonPlan(buffer *bytes.Buffer, uuid uuid.UUID, errcode uint16, msg string) []byte { var bytes [36]byte - util.EncodeUUIDHex(bytes[:], uuid[:]) + commonutil.EncodeUUIDHex(bytes[:], uuid[:]) explainData := models.ExplainData{ Code: errcode, Message: msg, - Uuid: util.UnsafeBytesToString(bytes[:]), + Uuid: commonutil.UnsafeBytesToString(bytes[:]), } encoder := json.NewEncoder(buffer) encoder.SetEscapeHTML(false) diff --git a/pkg/frontend/mysql_protocol_test.go b/pkg/frontend/mysql_protocol_test.go index 32269ff1191e3..465b20b6ae652 100644 --- a/pkg/frontend/mysql_protocol_test.go +++ b/pkg/frontend/mysql_protocol_test.go @@ -2220,7 +2220,7 @@ func Test_beginPacket(t *testing.T) { var data []byte = nil var sequenceId byte = 0 for i := 0; i < n; i += curLen { - curLen = Min(int(MaxPayloadSize), n-i) + curLen = min(int(MaxPayloadSize), n-i) binary.LittleEndian.PutUint32(header[:], uint32(curLen)) header[3] = sequenceId sequenceId++ diff --git a/pkg/frontend/output.go b/pkg/frontend/output.go index e2acfe509efd7..49a7bf9a6e4e6 100644 --- a/pkg/frontend/output.go +++ b/pkg/frontend/output.go @@ -22,6 +22,7 @@ import ( "go.uber.org/zap" "github.com/matrixorigin/matrixone/pkg/common/moerr" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/container/batch" "github.com/matrixorigin/matrixone/pkg/container/types" "github.com/matrixorigin/matrixone/pkg/container/vector" @@ -62,7 +63,7 @@ func extractRowFromVector(ctx context.Context, ses FeSession, vec *vector.Vector switch vec.GetType().Oid { //get col case types.T_json: - row[i] = types.DecodeJson(copyBytes(vec.GetBytesAt(rowIndex), !safeRefSlice)) + row[i] = types.DecodeJson(commonutil.CloneBytesIf(vec.GetBytesAt(rowIndex), !safeRefSlice)) case types.T_bool: row[i] = vector.GetFixedAtNoTypeCheck[bool](vec, rowIndex) case types.T_bit: @@ -88,7 +89,7 @@ func extractRowFromVector(ctx context.Context, ses FeSession, vec *vector.Vector case types.T_float64: row[i] = vector.GetFixedAtNoTypeCheck[float64](vec, rowIndex) case types.T_char, types.T_varchar, types.T_blob, types.T_text, types.T_binary, types.T_varbinary, types.T_datalink: - row[i] = copyBytes(vec.GetBytesAt(rowIndex), !safeRefSlice) + row[i] = commonutil.CloneBytesIf(vec.GetBytesAt(rowIndex), !safeRefSlice) case types.T_array_float32: // NOTE: Don't merge it with T_varchar. You will get raw binary in the SQL output //+------------------------------+ @@ -180,7 +181,7 @@ func extractRowFromVector2(ctx context.Context, ses FeSession, vec *vector.Vecto switch vec.GetType().Oid { //get col case types.T_json: - row[i] = types.DecodeJson(copyBytes(vec.GetBytesAt2(colSlices.arrVarlena[sliceIdx], rowIndex), !safeRefSlice)) + row[i] = types.DecodeJson(commonutil.CloneBytesIf(vec.GetBytesAt2(colSlices.arrVarlena[sliceIdx], rowIndex), !safeRefSlice)) case types.T_bool: row[i] = colSlices.arrBool[sliceIdx][rowIndex] case types.T_bit: @@ -206,7 +207,7 @@ func extractRowFromVector2(ctx context.Context, ses FeSession, vec *vector.Vecto case types.T_float64: row[i] = colSlices.arrFloat64[sliceIdx][rowIndex] case types.T_char, types.T_varchar, types.T_blob, types.T_text, types.T_binary, types.T_varbinary, types.T_datalink: - row[i] = copyBytes(vec.GetBytesAt2(colSlices.arrVarlena[sliceIdx], rowIndex), !safeRefSlice) + row[i] = commonutil.CloneBytesIf(vec.GetBytesAt2(colSlices.arrVarlena[sliceIdx], rowIndex), !safeRefSlice) case types.T_array_float32: // NOTE: Don't merge it with T_varchar. You will get raw binary in the SQL output //+------------------------------+ @@ -530,7 +531,7 @@ func (slices *ColumnSlices) GetStringBased(r uint64, i uint64) (string, error) { vec := slices.GetVector(i) switch vec.GetType().Oid { //get col case types.T_json: - return types.DecodeJson(copyBytes(vec.GetBytesAt2(slices.arrVarlena[sliceIdx], int(r)), !slices.safeRefSlice)).String(), nil + return types.DecodeJson(commonutil.CloneBytesIf(vec.GetBytesAt2(slices.arrVarlena[sliceIdx], int(r)), !slices.safeRefSlice)).String(), nil case types.T_array_float32: // NOTE: Don't merge it with T_varchar. You will get raw binary in the SQL output //+------------------------------+ @@ -566,7 +567,7 @@ func (slices *ColumnSlices) GetBytesBased(r uint64, i uint64) ([]byte, error) { vec := slices.dataSet.Vecs[i] switch vec.GetType().Oid { //get col case types.T_char, types.T_varchar, types.T_blob, types.T_text, types.T_binary, types.T_varbinary, types.T_datalink: - return copyBytes(vec.GetBytesAt2(slices.arrVarlena[sliceIdx], int(r)), !slices.safeRefSlice), nil + return commonutil.CloneBytesIf(vec.GetBytesAt2(slices.arrVarlena[sliceIdx], int(r)), !slices.safeRefSlice), nil default: return nil, moerr.NewInternalError(slices.ctx, "invalid bytes based slice") } diff --git a/pkg/frontend/show_account.go b/pkg/frontend/show_account.go index 2b55cfdb4ff21..43808fb8271cf 100644 --- a/pkg/frontend/show_account.go +++ b/pkg/frontend/show_account.go @@ -416,8 +416,6 @@ func getAccountsStorageUsage( } ret[k][0] = v } - logutil.Info("show accounts", - zap.Int("get size from mts (acc cnt)", len(sizes))) } }() diff --git a/pkg/frontend/util.go b/pkg/frontend/util.go index d6b9c62e309c0..abb38060f24b5 100644 --- a/pkg/frontend/util.go +++ b/pkg/frontend/util.go @@ -38,7 +38,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/common/moerr" "github.com/matrixorigin/matrixone/pkg/common/mpool" moruntime "github.com/matrixorigin/matrixone/pkg/common/runtime" - "github.com/matrixorigin/matrixone/pkg/common/util" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" mo_config "github.com/matrixorigin/matrixone/pkg/config" "github.com/matrixorigin/matrixone/pkg/container/batch" "github.com/matrixorigin/matrixone/pkg/container/nulls" @@ -84,14 +84,6 @@ func (cf *CloseFlag) IsOpened() bool { return atomic.LoadUint32(&cf.closed) == 0 } -func Min(a int, b int) int { - if a < b { - return a - } else { - return b - } -} - func Max(a int, b int) int { if a < b { return b @@ -113,71 +105,6 @@ func GetRoutineId() uint64 { return uint64(id) } -type Timeout struct { - //last record of the time - lastTime atomic.Value //time.Time - - //period - timeGap time.Duration - - //auto update - autoUpdate bool -} - -func NewTimeout(tg time.Duration, autoUpdateWhenChecked bool) *Timeout { - ret := &Timeout{ - timeGap: tg, - autoUpdate: autoUpdateWhenChecked, - } - ret.lastTime.Store(time.Now()) - return ret -} - -func (t *Timeout) UpdateTime(tn time.Time) { - t.lastTime.Store(tn) -} - -/* -----------+---------+------------------+-------- - - lastTime Now lastTime + timeGap - -return true : is timeout. the lastTime has been updated. -return false : is not timeout. the lastTime has not been updated. -*/ -func (t *Timeout) isTimeout() bool { - if time.Since(t.lastTime.Load().(time.Time)) <= t.timeGap { - return false - } - - if t.autoUpdate { - t.lastTime.Store(time.Now()) - } - return true -} - -/* -length: --1, complete string. -0, empty string ->0 , length of characters at the header of the string. -*/ -func SubStringFromBegin(str string, length int) string { - if length == 0 || length < -1 { - return "" - } - - if length == -1 { - return str - } - - l := Min(len(str), length) - if l != len(str) { - return str[:l] + "..." - } - return str[:l] -} - /* path exists in the system return: @@ -484,14 +411,27 @@ func (s statementStatus) String() string { } // logStatementStatus prints the status of the statement into the log. -func logStatementStatus(ctx context.Context, ses FeSession, stmt tree.Statement, status statementStatus, err error) { +func logStatementStatus( + ctx context.Context, + ses FeSession, + _ tree.Statement, + status statementStatus, + err error, +) { logStatementStringStatus(ctx, ses, "", status, err) } // logStatementStringStatus -// if stmtStr == "", get the query statement from FeSession or motrace.StatementInfo (which migrate from logStatementStatus). +// if stmtStr == "", get the query statement from FeSession or motrace.StatementInfo +// (which migrate from logStatementStatus). // This op is aim to avoid string copy in 'status == success' case. -func logStatementStringStatus(ctx context.Context, ses FeSession, stmtStr string, status statementStatus, err error) { +func logStatementStringStatus( + ctx context.Context, + ses FeSession, + stmtStr string, + status statementStatus, + err error, +) { var outBytes, outPacket int64 var getFormatedSqlStr = func() string { var str = stmtStr @@ -503,7 +443,7 @@ func logStatementStringStatus(ctx context.Context, ses FeSession, stmtStr string str = stm.CopyStatementInfo() } } - str = SubStringFromBegin(str, int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)) + str = commonutil.Abbreviate(str, int(getPu(ses.GetService()).SV.LengthOfQueryPrinted)) return str } switch resper := ses.GetResponser().(type) { @@ -616,19 +556,6 @@ func makeServerVersion(pu *mo_config.ParameterUnit, version string) string { return pu.SV.ServerVersionPrefix + version } -func copyBytes(src []byte, needCopy bool) []byte { - if needCopy { - if len(src) > 0 { - dst := make([]byte, len(src)) - copy(dst, src) - return dst - } else { - return []byte{} - } - } - return src -} - // getUserProfile returns the account, user, role of the account func getUserProfile(account *TenantInfo) (string, string, string) { var ( @@ -1468,7 +1395,7 @@ func Copy[T any](src []T) []T { func hashString(s string) string { hash := sha256.New() - hash.Write(util.UnsafeStringToBytes(s)) + hash.Write(commonutil.UnsafeStringToBytes(s)) hashBytes := hash.Sum(nil) return hex.EncodeToString(hashBytes) } diff --git a/pkg/frontend/util_test.go b/pkg/frontend/util_test.go index 0b24eb12dcbc2..38f25642f3370 100644 --- a/pkg/frontend/util_test.go +++ b/pkg/frontend/util_test.go @@ -35,6 +35,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/catalog" "github.com/matrixorigin/matrixone/pkg/common/moerr" "github.com/matrixorigin/matrixone/pkg/common/mpool" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/config" "github.com/matrixorigin/matrixone/pkg/container/types" "github.com/matrixorigin/matrixone/pkg/container/vector" @@ -82,12 +83,7 @@ func Test_PathExists(t *testing.T) { } } -func Test_MinMax(t *testing.T) { - cvey.Convey("min", t, func() { - cvey.So(Min(10, 9), cvey.ShouldEqual, 9) - cvey.So(Min(9, 10), cvey.ShouldEqual, 9) - }) - +func Test_Max(t *testing.T) { cvey.Convey("max", t, func() { cvey.So(Max(10, 9), cvey.ShouldEqual, 10) cvey.So(Max(9, 10), cvey.ShouldEqual, 10) @@ -101,17 +97,9 @@ func Test_routineid(t *testing.T) { }) } -func Test_timeout(t *testing.T) { - cvey.Convey("timeout", t, func() { - to := NewTimeout(5*time.Second, true) - to.UpdateTime(time.Now()) - cvey.So(to.isTimeout(), cvey.ShouldBeFalse) - }) -} - func Test_substringFromBegin(t *testing.T) { cvey.Convey("ssfb", t, func() { - cvey.So(SubStringFromBegin("abcdef", 3), cvey.ShouldEqual, "abc...") + cvey.So(commonutil.Abbreviate("abcdef", 3), cvey.ShouldEqual, "abc...") }) } diff --git a/pkg/queryservice/multi_cn_bug_test.go b/pkg/queryservice/multi_cn_bug_test.go index 503529e6324e5..a181b7bfe52c3 100644 --- a/pkg/queryservice/multi_cn_bug_test.go +++ b/pkg/queryservice/multi_cn_bug_test.go @@ -543,9 +543,6 @@ func TestRequestMultipleCn_TimeoutOverrideLogging(t *testing.T) { cn := metadata.CNService{ServiceID: "test_timeout_override"} runTestWithQueryService(t, cn, nil, func(cli client.QueryClient, addr string) { - // Event-based synchronization: signal when connection error occurs - connectionErrorOccurred := make(chan struct{}) - // Use WithTimeout with a very long deadline to avoid timing issues on slow systems. // The actual cancellation is controlled precisely via events, not by timeout. // morpc's Future requires a deadline, but we cancel immediately after connection error, @@ -561,6 +558,10 @@ func TestRequestMultipleCn_TimeoutOverrideLogging(t *testing.T) { node1 := addr node2 := fmt.Sprintf("unix:///tmp/nonexistent-%d.sock", time.Now().Nanosecond()) + // Event-based synchronization: signal when connection error is processed by main loop + // Use a buffered channel to avoid blocking if signal is sent before we wait + connectionErrorProcessed := make(chan struct{}, 1) + var successCount int genRequest := func() *pb.Request { req := cli.NewRequest(pb.CmdMethod_GetCacheInfo) @@ -575,14 +576,16 @@ func TestRequestMultipleCn_TimeoutOverrideLogging(t *testing.T) { } } - // Monitor connection errors: signal when node2 fails (sets retErr) + // Monitor connection errors: signal when node2's error is processed by main loop + // This happens in query_service.go:226, after the error response is received handleInvalidResponse := func(nodeAddr string) { if nodeAddr == node2 { - // Connection error occurred, retErr is now set - // Signal that retErr is set (non-blocking) + // Connection error has been processed, retErr is now set + // Signal that retErr is set (non-blocking due to buffered channel) select { - case connectionErrorOccurred <- struct{}{}: + case connectionErrorProcessed <- struct{}{}: default: + // Channel already has signal, ignore } } } @@ -595,18 +598,25 @@ func TestRequestMultipleCn_TimeoutOverrideLogging(t *testing.T) { close(done) }() - // Step 1: Wait for connection error to occur (node2 fails, retErr is set) - // This is event-based with 10s protection + // Step 1: Wait for connection error to be processed (node2 fails, retErr is set) + // This is event-based synchronization - we wait for handleInvalidResponse to be called + // which happens after the error response is processed by the main loop at line 226. + // This ensures retErr is set before we cancel the context. select { - case <-connectionErrorOccurred: - // Connection error occurred + case <-connectionErrorProcessed: + // Connection error processed, retErr is now set + case <-done: + // RequestMultipleCn completed before connection error was processed + // This can happen if node1 responds very quickly and node2 error happens later + // In this case, the test still verifies the error handling, but timeout override + // path may not be executed. We accept this as it's still a valid scenario. case <-time.After(10 * time.Second): - t.Fatal("Connection error not detected within 10s") + t.Fatal("Connection error not processed within 10s - test protection timeout") } // Step 2: Cancel context immediately to trigger <-ctx.Done() // At this point: - // - retErr is set (connection error from node2) + // - retErr is set (connection error from node2 has been processed) // - node1's response may or may not have arrived yet // - If node1's response hasn't arrived: main loop is waiting, <-ctx.Done() triggers with retErr != nil // - If node1's response has arrived: it may be processed, but <-ctx.Done() can still trigger @@ -746,15 +756,17 @@ func TestRequestMultipleCn_ResponseErrorWithDeadlineExceeded(t *testing.T) { assert.Error(t, errResult, "Should return error when context deadline exceeded") // Accept multiple error types that can occur in different environments: // - "context deadline exceeded": normal timeout path + // - "context canceled": when cancel() is called explicitly // - "failed to get result": connection error during timeout // - "EOF": connection closed by server during timeout - // All of these indicate the timeout was handled correctly + // All of these indicate the timeout/cancellation was handled correctly errStr := errResult.Error() assert.True(t, strings.Contains(errStr, "context deadline exceeded") || + strings.Contains(errStr, "context canceled") || strings.Contains(errStr, "failed to get result") || strings.Contains(errStr, "EOF"), - "Error should indicate timeout or connection error, got: %s", errStr) + "Error should indicate timeout/cancellation or connection error, got: %s", errStr) assert.Equal(t, 0, successCount, "No nodes should succeed due to timeout") }, ) diff --git a/pkg/queryservice/query_service.go b/pkg/queryservice/query_service.go index 0d80e194f04d2..7c21d401b173e 100644 --- a/pkg/queryservice/query_service.go +++ b/pkg/queryservice/query_service.go @@ -196,17 +196,23 @@ func RequestMultipleCn(ctx context.Context, case res := <-responseChan: responsesReceived++ if res.err != nil { - // Check if the error itself is a context timeout error - // or if the context has already timed out (handles race condition) - // If context has timed out, prioritize timeout error over connection error - if ctx.Err() == context.DeadlineExceeded || errors.Is(res.err, context.DeadlineExceeded) { - // Context has timed out, prioritize timeout error + // Check if the error itself is a context timeout/cancellation error + // or if the context has already timed out/canceled (handles race condition) + // If context has timed out or been canceled, prioritize context error over connection error + ctxErr := ctx.Err() + if ctxErr == context.DeadlineExceeded || ctxErr == context.Canceled || + errors.Is(res.err, context.DeadlineExceeded) || errors.Is(res.err, context.Canceled) { + // Context has timed out or been canceled, prioritize context error if retErr == nil { - retErr = moerr.NewInternalError(ctx, "RequestMultipleCn : context deadline exceeded") + if ctxErr == context.Canceled || errors.Is(res.err, context.Canceled) { + retErr = moerr.NewInternalError(ctx, "RequestMultipleCn : context canceled") + } else { + retErr = moerr.NewInternalError(ctx, "RequestMultipleCn : context deadline exceeded") + } } } else { - // Context has not timed out, record connection error - // Note: if context times out later, timeout error will override connection error + // Context has not timed out or been canceled, record connection error + // Note: if context times out or is canceled later, context error will override connection error if retErr == nil { retErr = errors.Wrapf(res.err, "failed to get result from %s", res.nodeAddr) } @@ -297,16 +303,21 @@ func RequestMultipleCn(ctx context.Context, } } case <-ctx.Done(): - // Context timeout: prioritize timeout error, override previous connection error - // Timeout is a higher-level error and should take precedence over connection errors + // Context timeout/cancellation: prioritize context error, override previous connection error + // Context termination is a higher-level error and should take precedence over connection errors if retErr != nil { // Log the overridden error for debugging purposes logger.GetLogger("RequestMultipleCn").Infof( - "[timeout override] %s context timeout overrides previous error: %v", + "[context override] %s context termination overrides previous error: %v", qc.ServiceID(), retErr, ) } - retErr = moerr.NewInternalError(ctx, "RequestMultipleCn : context deadline exceeded") + // Set appropriate error message based on context error type + if ctx.Err() == context.Canceled { + retErr = moerr.NewInternalError(ctx, "RequestMultipleCn : context canceled") + } else { + retErr = moerr.NewInternalError(ctx, "RequestMultipleCn : context deadline exceeded") + } // Don't add "context timeout" to failedNodes - keep it as real node addresses only // Timeout info is already in retErr // Continue receiving remaining responses to avoid goroutine leaks diff --git a/pkg/sql/compile/compile.go b/pkg/sql/compile/compile.go index 6c5d63c4b0002..e21a51492c823 100644 --- a/pkg/sql/compile/compile.go +++ b/pkg/sql/compile/compile.go @@ -31,6 +31,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/common/mpool" moruntime "github.com/matrixorigin/matrixone/pkg/common/runtime" "github.com/matrixorigin/matrixone/pkg/common/system" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/config" "github.com/matrixorigin/matrixone/pkg/container/batch" "github.com/matrixorigin/matrixone/pkg/container/types" @@ -531,7 +532,7 @@ func (c *Compile) runOnce() (err error) { if e := recover(); e != nil { err := moerr.ConvertPanicError(c.proc.Ctx, e) c.proc.Error(c.proc.Ctx, "panic in run", - zap.String("sql", c.sql), + zap.String("sql", commonutil.Abbreviate(c.sql, 500)), zap.String("error", err.Error())) errC <- err } @@ -4887,7 +4888,7 @@ func detectFkSelfRefer(c *Compile, detectSqls []string) error { // runDetectSql runs the fk detecting sql func runDetectSql(c *Compile, sql string) error { - res, err := c.runSqlWithResult(sql, NoAccountId) + res, err := c.runSqlWithResultAndOptions(sql, NoAccountId, executor.StatementOption{}.WithDisableLog()) if err != nil { c.proc.Errorf(c.proc.Ctx, "The sql that caused the fk self refer check failed is %s, and generated background sql is %s", c.sql, sql) return err @@ -4908,7 +4909,7 @@ func runDetectSql(c *Compile, sql string) error { // runDetectFkReferToDBSql runs the fk detecting sql func runDetectFkReferToDBSql(c *Compile, sql string) error { - res, err := c.runSqlWithResult(sql, NoAccountId) + res, err := c.runSqlWithResultAndOptions(sql, NoAccountId, executor.StatementOption{}.WithDisableLog()) if err != nil { c.proc.Errorf(c.proc.Ctx, "The sql that caused the fk self refer check failed is %s, and generated background sql is %s", c.sql, sql) return err diff --git a/pkg/sql/compile/compile2.go b/pkg/sql/compile/compile2.go index 90bde16bca0e5..d69f22fb30786 100644 --- a/pkg/sql/compile/compile2.go +++ b/pkg/sql/compile/compile2.go @@ -22,6 +22,7 @@ import ( "time" "github.com/matrixorigin/matrixone/pkg/common/moerr" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/container/batch" "github.com/matrixorigin/matrixone/pkg/defines" "github.com/matrixorigin/matrixone/pkg/pb/plan" @@ -64,7 +65,7 @@ func (c *Compile) Compile( if e := recover(); e != nil { err = moerr.ConvertPanicError(execTopContext, e) c.proc.Error(execTopContext, "panic in compile", - zap.String("sql", c.sql), + zap.String("sql", commonutil.Abbreviate(c.sql, 500)), zap.String("error", err.Error())) } task.End() @@ -297,8 +298,15 @@ func (c *Compile) Run(_ uint64) (queryResult *util2.RunResult, err error) { return nil, err } queryResult.AffectRows = runC.getAffectedRows() - if c.uid != "mo_logger" && strings.Contains(strings.ToLower(c.sql), "insert") && (strings.Contains(c.sql, "{MO_TS =") || strings.Contains(c.sql, "{SNAPSHOT =")) { - getLogger(c.proc.GetService()).Info("insert into with snapshot", zap.String("sql", c.sql), zap.Uint64("affectRows", queryResult.AffectRows)) + if c.uid != "mo_logger" && + strings.Contains(strings.ToLower(c.sql), "insert") && + (strings.Contains(c.sql, "{MO_TS =") || + strings.Contains(c.sql, "{SNAPSHOT =")) { + getLogger(c.proc.GetService()).Info( + "insert into with snapshot", + zap.String("sql", commonutil.Abbreviate(c.sql, 500)), + zap.Uint64("affectRows", queryResult.AffectRows), + ) } if txnOperator != nil { err = txnOperator.GetWorkspace().Adjust(writeOffset) diff --git a/pkg/sql/compile/ddl.go b/pkg/sql/compile/ddl.go index 3bf5af2d6338d..fb3de6d46cc37 100644 --- a/pkg/sql/compile/ddl.go +++ b/pkg/sql/compile/ddl.go @@ -36,6 +36,7 @@ import ( "github.com/google/uuid" "github.com/matrixorigin/matrixone/pkg/catalog" "github.com/matrixorigin/matrixone/pkg/common/moerr" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/container/batch" "github.com/matrixorigin/matrixone/pkg/container/types" "github.com/matrixorigin/matrixone/pkg/container/vector" @@ -190,8 +191,9 @@ func (s *Scope) DropDatabase(c *Compile) error { for _, t := range deleteTables { dropSql := fmt.Sprintf(dropTableBeforeDropDatabase, dbName, t) - err = c.runSql(dropSql) - if err != nil { + if err = c.runSqlWithOptions( + dropSql, executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } } @@ -210,21 +212,23 @@ func (s *Scope) DropDatabase(c *Compile) error { // 1.delete all index object record under the database from mo_catalog.mo_indexes deleteSql := fmt.Sprintf(deleteMoIndexesWithDatabaseIdFormat, s.Plan.GetDdl().GetDropDatabase().GetDatabaseId()) - err = c.runSql(deleteSql) - if err != nil { + if err = c.runSqlWithOptions( + deleteSql, executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } // 3. delete fks - err = c.runSql(s.Plan.GetDdl().GetDropDatabase().GetUpdateFkSql()) - if err != nil { + if err = c.runSqlWithOptions( + s.Plan.GetDdl().GetDropDatabase().GetUpdateFkSql(), executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } // 4.update mo_pitr table if !needSkipDbs[dbName] { now := c.proc.GetTxnOperator().SnapshotTS().ToStdTime().UTC().UnixNano() - updatePitrSql := fmt.Sprintf("update `%s`.`%s` set `%s` = %d, `%s` = %d where `%s` = %d and `%s` = '%s' and `%s` = %d and `%s` = %s", + updatePitrSql := fmt.Sprintf("UPDATE `%s`.`%s` SET `%s` = %d, `%s` = %d WHERE `%s` = %d AND `%s` = '%s' AND `%s` = %d AND `%s` = %s", catalog.MO_CATALOG, catalog.MO_PITR, catalog.MO_PITR_STATUS, 0, catalog.MO_PITR_CHANGED_TIME, now, @@ -461,11 +465,13 @@ func (s *Scope) AlterTableInplace(c *Compile) error { if !moerr.IsMoErrCode(err, moerr.ErrParseError) && !moerr.IsMoErrCode(err, moerr.ErrTxnNeedRetry) && !moerr.IsMoErrCode(err, moerr.ErrTxnNeedRetryWithDefChanged) { - c.proc.Error(c.proc.Ctx, "lock index table for alter table", - zap.String("databaseName", c.db), - zap.String("origin tableName", qry.GetTableDef().Name), - zap.String("index name", indexdef.IndexName), - zap.String("index tableName", indexdef.IndexTableName), + c.proc.Error( + c.proc.Ctx, + "alter.table.lock.index.table", + zap.String("db", c.db), + zap.String("main-table", qry.GetTableDef().Name), + zap.String("index-name", indexdef.IndexName), + zap.String("index-table-name", indexdef.IndexTableName), zap.Error(err)) return err } @@ -582,14 +588,16 @@ func (s *Scope) AlterTableInplace(c *Compile) error { //1. drop index table if indexdef.TableExist { - if err := c.runSql("drop table `" + indexdef.IndexTableName + "`"); err != nil { + if err := c.runSqlWithOptions( + "DROP TABLE `"+indexdef.IndexTableName+"`", executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } } - //2. delete index object from mo_catalog.mo_indexes deleteSql := fmt.Sprintf(deleteMoIndexesWithTableIdAndIndexNameFormat, oTableDef.TblId, indexdef.IndexName) - err = c.runSql(deleteSql) - if err != nil { + if err = c.runSqlWithOptions( + deleteSql, executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } } else { @@ -691,8 +699,9 @@ func (s *Scope) AlterTableInplace(c *Compile) error { if err != nil { return err } - err = c.runSql(insertSql) - if err != nil { + if err = c.runSqlWithOptions( + insertSql, executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } } @@ -712,8 +721,9 @@ func (s *Scope) AlterTableInplace(c *Compile) error { } else { updateSql = fmt.Sprintf(updateMoIndexesVisibleFormat, 0, oTableDef.TblId, indexdef.IndexName) } - err = c.runSql(updateSql) - if err != nil { + if err = c.runSqlWithOptions( + updateSql, executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } @@ -757,8 +767,9 @@ func (s *Scope) AlterTableInplace(c *Compile) error { // 3.b Update mo_catalog.mo_indexes updateSql := fmt.Sprintf(updateMoIndexesAlgoParams, newAlgoParams, oTableDef.TblId, alterIndex.IndexName) - err = c.runSql(updateSql) - if err != nil { + if err = c.runSqlWithOptions( + updateSql, executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } case catalog.MoIndexHnswAlgo.ToString(): @@ -1096,8 +1107,9 @@ func (s *Scope) CreateTable(c *Compile) error { //update mo_foreign_keys for _, sql := range qry.UpdateFkSqls { - err = c.runSql(sql) - if err != nil { + if err = c.runSqlWithOptions( + sql, executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } } @@ -1431,7 +1443,7 @@ func (s *Scope) CreateTable(c *Compile) error { var initSQL string switch def.TableType { case catalog.SystemSI_IVFFLAT_TblType_Metadata: - initSQL = fmt.Sprintf("insert into `%s`.`%s` (`%s`, `%s`) VALUES('version', '0');", + initSQL = fmt.Sprintf("INSERT INTO `%s`.`%s` (`%s`, `%s`) VALUES('version', '0');", qry.Database, def.Name, catalog.SystemSI_IVFFLAT_TblCol_Metadata_key, @@ -1439,7 +1451,7 @@ func (s *Scope) CreateTable(c *Compile) error { ) case catalog.SystemSI_IVFFLAT_TblType_Centroids: - initSQL = fmt.Sprintf("insert into `%s`.`%s` (`%s`, `%s`, `%s`) VALUES(0,1,NULL);", + initSQL = fmt.Sprintf("INSERT INTO `%s`.`%s` (`%s`, `%s`, `%s`) VALUES(0,1,NULL);", qry.Database, def.Name, catalog.SystemSI_IVFFLAT_TblCol_Centroids_version, @@ -1447,7 +1459,9 @@ func (s *Scope) CreateTable(c *Compile) error { catalog.SystemSI_IVFFLAT_TblCol_Centroids_centroid, ) } - err = c.runSql(initSQL) + err = c.runSqlWithOptions( + initSQL, executor.StatementOption{}.WithDisableLog(), + ) if err != nil { c.proc.Error(c.proc.Ctx, "create index table for execute initSQL", zap.String("databaseName", c.db), @@ -1489,7 +1503,9 @@ func (s *Scope) CreateTable(c *Compile) error { ) return err } - err = c.runSql(insertSQL) + err = c.runSqlWithOptions( + insertSQL, executor.StatementOption{}.WithDisableLog(), + ) if err != nil { c.proc.Error(c.proc.Ctx, "createTable", zap.String("insertSQL", insertSQL), @@ -1585,7 +1601,9 @@ func (c *Compile) runSqlWithSystemTenant(sql string) error { defer func() { c.proc.Ctx = oldCtx }() - return c.runSql(sql) + return c.runSqlWithOptions( + sql, executor.StatementOption{}.WithDisableLog(), + ) } func (s *Scope) CreateView(c *Compile) error { @@ -1644,8 +1662,9 @@ func (s *Scope) CreateView(c *Compile) error { } if qry.GetReplace() { - err = c.runSql(fmt.Sprintf("drop view if exists %s", viewName)) - if err != nil { + if err = c.runSqlWithOptions( + fmt.Sprintf("DROP VIEW IF EXISTS %s", viewName), executor.StatementOption{}.WithDisableLog(), + ); err != nil { getLogger(s.Proc.GetService()).Error("drop existing view failed", zap.String("databaseName", c.db), zap.String("viewName", qry.GetTableDef().GetName()), @@ -1986,7 +2005,9 @@ func (s *Scope) doCreateIndex( if err != nil { return err } - err = c.runSql(sql) + err = c.runSqlWithOptions( + sql, executor.StatementOption{}.WithDisableLog(), + ) if err != nil { return err } @@ -2207,9 +2228,10 @@ func (s *Scope) DropIndex(c *Compile) error { return err } - //4. delete index object from mo_catalog.mo_indexes deleteSql := fmt.Sprintf(deleteMoIndexesWithTableIdAndIndexNameFormat, r.GetTableID(c.proc.Ctx), qry.IndexName) - err = c.runSql(deleteSql) + err = c.runSqlWithOptions( + deleteSql, executor.StatementOption{}.WithDisableLog(), + ) if err != nil { return err } @@ -2468,9 +2490,10 @@ func (s *Scope) TruncateTable(c *Compile) error { createOpts = createOpts.WithKeepAutoIncrement(oldID) } - r, err := c.runSqlWithResult( - fmt.Sprintf("show create table `%s`.`%s`", db, table), + r, err := c.runSqlWithResultAndOptions( + fmt.Sprintf("SHOW CREATE TABLE `%s`.`%s`", db, table), int32(accountID), + executor.StatementOption{}.WithDisableLog(), ) if err != nil { return err @@ -2671,7 +2694,9 @@ func (s *Scope) DropTable(c *Compile) error { if len(qry.UpdateFkSqls) > 0 { for _, sql := range qry.UpdateFkSqls { - if err = c.runSql(sql); err != nil { + if err = c.runSqlWithOptions( + sql, executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } } @@ -2741,8 +2766,9 @@ func (s *Scope) DropTable(c *Compile) error { if !qry.IsView && qry.Database != catalog.MO_CATALOG && qry.Table != catalog.MO_INDEXES { if qry.GetTableDef().Pkey != nil || len(qry.GetTableDef().Indexes) > 0 { deleteSql := fmt.Sprintf(deleteMoIndexesWithTableIdFormat, qry.GetTableDef().TblId) - err = c.runSql(deleteSql) - if err != nil { + if err = c.runSqlWithOptions( + deleteSql, executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } } @@ -2881,7 +2907,7 @@ func (s *Scope) DropTable(c *Compile) error { for _, ss := range sqls { if err = c.runSqlWithSystemTenant(ss); err != nil { logutil.Error("run extra sql failed when drop table", - zap.String("sql", ss), + zap.String("sql", commonutil.Abbreviate(ss, 500)), zap.Error(err), ) return err @@ -3021,8 +3047,9 @@ func (s *Scope) AlterSequence(c *Compile) error { curval = c.proc.GetSessionInfo().SeqCurValues[rel.GetTableID(c.proc.Ctx)] // dorp the pre sequence - err = c.runSql(fmt.Sprintf("drop sequence %s", tblName)) - if err != nil { + if err = c.runSqlWithOptions( + fmt.Sprintf("DROP SEQUENCE %s", tblName), executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } } else { @@ -3921,7 +3948,7 @@ func (s *Scope) CreatePitr(c *Compile) error { // check pitr if exists（pitr_name + create_account） checkExistSql := getSqlForCheckPitrExists(pitrName, accountId) - existRes, err := c.runSqlWithResult(checkExistSql, int32(sysAccountId)) + existRes, err := c.runSqlWithResultAndOptions(checkExistSql, int32(sysAccountId), executor.StatementOption{}.WithDisableLog()) if err != nil { return err } @@ -3936,7 +3963,7 @@ func (s *Scope) CreatePitr(c *Compile) error { // Check if pitr dup checkSql := getSqlForCheckPitrDup(createPitr) - res, err := c.runSqlWithResult(checkSql, int32(sysAccountId)) + res, err := c.runSqlWithResultAndOptions(checkSql, int32(sysAccountId), executor.StatementOption{}.WithDisableLog()) if err != nil { return err } @@ -3985,7 +4012,7 @@ func (s *Scope) CreatePitr(c *Compile) error { ) // Execute create pitr sql - err = c.runSqlWithAccountId(sql, int32(sysAccountId)) + err = c.runSqlWithAccountIdAndOptions(sql, int32(sysAccountId), executor.StatementOption{}.WithDisableLog()) if err != nil { return err } @@ -3995,8 +4022,8 @@ func (s *Scope) CreatePitr(c *Compile) error { const sysAccountId = 0 // Query for sys_mo_catalog_pitr - sysPitrSql := "select pitr_length, pitr_unit from mo_catalog.mo_pitr where pitr_name = '" + sysMoCatalogPitr + "'" - sysRes, err := c.runSqlWithResult(sysPitrSql, sysAccountId) + sysPitrSql := "SELECT pitr_length, pitr_unit FROM mo_catalog.mo_pitr WHERE pitr_name = '" + sysMoCatalogPitr + "'" + sysRes, err := c.runSqlWithResultAndOptions(sysPitrSql, sysAccountId, executor.StatementOption{}.WithDisableLog()) if err != nil { return err } @@ -4013,8 +4040,8 @@ func (s *Scope) CreatePitr(c *Compile) error { } if needUpdateSysPitr { - updateSql := fmt.Sprintf("update mo_catalog.mo_pitr set pitr_length = %d, pitr_unit = '%s' where pitr_name = '%s'", createPitr.GetPitrValue(), createPitr.GetPitrUnit(), sysMoCatalogPitr) - err = c.runSqlWithAccountId(updateSql, sysAccountId) + updateSql := fmt.Sprintf("UPDATE mo_catalog.mo_pitr SET pitr_length = %d, pitr_unit = '%s' WHERE pitr_name = '%s'", createPitr.GetPitrValue(), createPitr.GetPitrUnit(), sysMoCatalogPitr) + err = c.runSqlWithAccountIdAndOptions(updateSql, sysAccountId, executor.StatementOption{}.WithDisableLog()) if err != nil { return err } @@ -4065,7 +4092,7 @@ func (s *Scope) CreatePitr(c *Compile) error { createPitr.GetPitrUnit(), now, ) - err = c.runSqlWithAccountId(insertSql, sysAccountId) + err = c.runSqlWithAccountIdAndOptions(insertSql, sysAccountId, executor.StatementOption{}.WithDisableLog()) if err != nil { return err } @@ -4114,8 +4141,8 @@ func (s *Scope) DropPitr(c *Compile) error { } // 1. Check if PITR exists - checkSql := fmt.Sprintf("select pitr_id from mo_catalog.mo_pitr where pitr_name = '%s' and create_account = %d", pitrName, accountId) - res, err := c.runSqlWithResult(checkSql, int32(sysAccountId)) + checkSql := fmt.Sprintf("SELECT pitr_id FROM mo_catalog.mo_pitr WHERE pitr_name = '%s' AND create_account = %d", pitrName, accountId) + res, err := c.runSqlWithResultAndOptions(checkSql, int32(sysAccountId), executor.StatementOption{}.WithDisableLog()) if err != nil { return err } @@ -4128,23 +4155,23 @@ func (s *Scope) DropPitr(c *Compile) error { } // 2. Delete PITR record - deleteSql := fmt.Sprintf("delete from mo_catalog.mo_pitr where pitr_name = '%s' and create_account = %d", pitrName, accountId) - err = c.runSqlWithAccountId(deleteSql, int32(sysAccountId)) + deleteSql := fmt.Sprintf("DELETE FROM mo_catalog.mo_pitr WHERE pitr_name = '%s' AND create_account = %d", pitrName, accountId) + err = c.runSqlWithAccountIdAndOptions(deleteSql, int32(sysAccountId), executor.StatementOption{}.WithDisableLog()) if err != nil { return err } // 3. Check if there are other PITR records besides sys_mo_catalog_pitr - checkOtherSql := fmt.Sprintf("select pitr_id from mo_catalog.mo_pitr where pitr_name != '%s'", sysMoCatalogPitr) - otherRes, err := c.runSqlWithResult(checkOtherSql, sysAccountId) + checkOtherSql := fmt.Sprintf("SELECT pitr_id FROM mo_catalog.mo_pitr WHERE pitr_name != '%s'", sysMoCatalogPitr) + otherRes, err := c.runSqlWithResultAndOptions(checkOtherSql, sysAccountId, executor.StatementOption{}.WithDisableLog()) if err != nil { return err } defer otherRes.Close() if len(otherRes.Batches) == 0 || otherRes.Batches[0].RowCount() == 0 { // 4. No other PITR records, delete sys_mo_catalog_pitr - deleteSysSql := fmt.Sprintf("delete from mo_catalog.mo_pitr where pitr_name = '%s' and create_account = %d", sysMoCatalogPitr, sysAccountId) - err = c.runSqlWithAccountId(deleteSysSql, sysAccountId) + deleteSysSql := fmt.Sprintf("DELETE FROM mo_catalog.mo_pitr WHERE pitr_name = '%s' AND create_account = %d", sysMoCatalogPitr, sysAccountId) + err = c.runSqlWithAccountIdAndOptions(deleteSysSql, sysAccountId, executor.StatementOption{}.WithDisableLog()) if err != nil { return err } @@ -4170,26 +4197,26 @@ func pitrDupError(c *Compile, createPitr *plan.CreatePitr) error { func getSqlForCheckPitrDup( createPitr *plan.CreatePitr, ) string { - sql := "select pitr_id from mo_catalog.mo_pitr where create_account = %d" + sql := "SELECT pitr_id FROM mo_catalog.mo_pitr WHERE create_account = %d" switch tree.PitrLevel(createPitr.GetLevel()) { case tree.PITRLEVELCLUSTER: return getSqlForCheckDupPitrFormat(createPitr.CurrentAccountId, math.MaxUint64) case tree.PITRLEVELACCOUNT: if createPitr.OriginAccountName { - return fmt.Sprintf(sql, createPitr.CurrentAccountId) + fmt.Sprintf(" and account_name = '%s' and level = 'account' and pitr_status = 1;", createPitr.AccountName) + return fmt.Sprintf(sql, createPitr.CurrentAccountId) + fmt.Sprintf(" AND account_name = '%s' AND level = 'account' AND pitr_status = 1;", createPitr.AccountName) } else { - return fmt.Sprintf(sql, createPitr.CurrentAccountId) + fmt.Sprintf(" and account_name = '%s' and level = 'account' and pitr_status = 1;", createPitr.CurrentAccount) + return fmt.Sprintf(sql, createPitr.CurrentAccountId) + fmt.Sprintf(" AND account_name = '%s' AND level = 'account' AND pitr_status = 1;", createPitr.CurrentAccount) } case tree.PITRLEVELDATABASE: - return fmt.Sprintf(sql, createPitr.CurrentAccountId) + fmt.Sprintf(" and database_name = '%s' and level = 'database' and pitr_status = 1;", createPitr.DatabaseName) + return fmt.Sprintf(sql, createPitr.CurrentAccountId) + fmt.Sprintf(" AND database_name = '%s' AND level = 'database' AND pitr_status = 1;", createPitr.DatabaseName) case tree.PITRLEVELTABLE: - return fmt.Sprintf(sql, createPitr.CurrentAccountId) + fmt.Sprintf(" and database_name = '%s' and table_name = '%s' and level = 'table' and pitr_status = 1;", createPitr.DatabaseName, createPitr.TableName) + return fmt.Sprintf(sql, createPitr.CurrentAccountId) + fmt.Sprintf(" AND database_name = '%s' AND table_name = '%s' AND level = 'table' AND pitr_status = 1;", createPitr.DatabaseName, createPitr.TableName) } return sql } func getSqlForCheckDupPitrFormat(accountId uint32, objId uint64) string { - return fmt.Sprintf(`select pitr_id from mo_catalog.mo_pitr where create_account = %d and obj_id = %d;`, accountId, objId) + return fmt.Sprintf(`SELECT pitr_id FROM mo_catalog.mo_pitr WHERE create_account = %d AND obj_id = %d;`, accountId, objId) } func getPitrObjectId(createPitr *plan.CreatePitr) uint64 { @@ -4257,7 +4284,7 @@ func CheckSysMoCatalogPitrResult(ctx context.Context, vecs []*vector.Vector, new } func getSqlForCheckPitrExists(pitrName string, accountId uint32) string { - return fmt.Sprintf("select pitr_id from mo_catalog.mo_pitr where pitr_name = '%s' and create_account = %d order by pitr_id", pitrName, accountId) + return fmt.Sprintf("SELECT pitr_id FROM mo_catalog.mo_pitr WHERE pitr_name = '%s' AND create_account = %d ORDER BY pitr_id", pitrName, accountId) } func (s *Scope) CreateCDC(c *Compile) error { @@ -4273,7 +4300,7 @@ func (s *Scope) CreateCDC(c *Compile) error { // 1.5 IF NOT EXISTS pre-check to avoid inconsistent rows between mo_cdc_task and daemon task if planCDC.GetIfNotExists() { preCheckSQL := cdc.CDCSQLBuilder.GetTaskIdSQL(uint64(opts.UserInfo.AccountId), opts.TaskName) - if res, err := c.runSqlWithResult(preCheckSQL, int32(catalog.System_Account)); err == nil { + if res, err := c.runSqlWithResultAndOptions(preCheckSQL, int32(catalog.System_Account), executor.StatementOption{}.WithDisableLog()); err == nil { exists := false if len(res.Batches) > 0 && res.Batches[0].Vecs[0].Length() > 0 { exists = true @@ -5014,9 +5041,9 @@ func (c *Compile) checkPitrGranularity( return err } - sqlCluster := fmt.Sprintf(`select pitr_length,pitr_unit from %s.%s where level='cluster' and account_id = %d`, + sqlCluster := fmt.Sprintf(`SELECT pitr_length,pitr_unit FROM %s.%s WHERE level='cluster' AND account_id = %d`, catalog.MO_CATALOG, catalog.MO_PITR, accountId) - if res, err := c.runSqlWithResult(sqlCluster, int32(catalog.System_Account)); err == nil { + if res, err := c.runSqlWithResultAndOptions(sqlCluster, int32(catalog.System_Account), executor.StatementOption{}.WithDisableLog()); err == nil { if len(res.Batches) > 0 && res.Batches[0].Vecs[0].Length() > 0 { val := int64(vector.MustFixedColNoTypeCheck[uint8](res.Batches[0].Vecs[0])[0]) unit := strings.ToLower(res.Batches[0].Vecs[1].GetStringAt(0)) @@ -5035,7 +5062,7 @@ func (c *Compile) checkPitrGranularity( isAccountPattern := pt.Source.Database == cdc.CDCPitrGranularity_All && pt.Source.Table == cdc.CDCPitrGranularity_All // helper to run query and evaluate requirement checkQuery := func(q string) (bool, error) { - res, err := c.runSqlWithResult(q, int32(catalog.System_Account)) + res, err := c.runSqlWithResultAndOptions(q, int32(catalog.System_Account), executor.StatementOption{}.WithDisableLog()) if err != nil { return false, err } diff --git a/pkg/sql/compile/fuzzyCheck.go b/pkg/sql/compile/fuzzyCheck.go index 23e4cf51115ea..0fbc1d0826601 100644 --- a/pkg/sql/compile/fuzzyCheck.go +++ b/pkg/sql/compile/fuzzyCheck.go @@ -31,6 +31,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/container/types" "github.com/matrixorigin/matrixone/pkg/container/vector" "github.com/matrixorigin/matrixone/pkg/pb/plan" + "github.com/matrixorigin/matrixone/pkg/util/executor" ) /* @@ -317,7 +318,7 @@ func (f *fuzzyCheck) backgroundSQLCheck(c *Compile) error { duplicateCheckSql = fmt.Sprintf(fuzzyNonCompoundCheck, f.attr, f.db, f.tbl, f.attr, f.condition, f.attr) } - res, err := c.runSqlWithResult(duplicateCheckSql, NoAccountId) + res, err := c.runSqlWithResultAndOptions(duplicateCheckSql, NoAccountId, executor.StatementOption{}.WithDisableLog()) if err != nil { c.debugLogFor19288(err, duplicateCheckSql) c.proc.Errorf(c.proc.Ctx, "The sql that caused the fuzzy check background SQL failed is %s, and generated background sql is %s", c.sql, duplicateCheckSql) diff --git a/pkg/sql/compile/pub_sub.go b/pkg/sql/compile/pub_sub.go index 6677ce826bac0..cd0ac4afec025 100644 --- a/pkg/sql/compile/pub_sub.go +++ b/pkg/sql/compile/pub_sub.go @@ -45,8 +45,16 @@ func createSubscription(ctx context.Context, c *Compile, dbName string, subOptio } // check existence - sql := fmt.Sprintf("select count(1) from mo_catalog.mo_subs where pub_account_name = '%s' and pub_name = '%s' and sub_account_id = %d and sub_name is not null", subOption.From, subOption.Publication, accountId) - rs, err := c.runSqlWithResult(sql, sysAccountId) + sql := fmt.Sprintf(` + SELECT count(1) + FROM mo_catalog.mo_subs + WHERE pub_account_name = '%s' AND pub_name = '%s' AND sub_account_id = %d AND sub_name is not null + `, subOption.From, subOption.Publication, accountId) + rs, err := c.runSqlWithResultAndOptions( + sql, + sysAccountId, + executor.StatementOption{}.WithDisableLog(), + ) if err != nil { return err } @@ -61,8 +69,16 @@ func createSubscription(ctx context.Context, c *Compile, dbName string, subOptio return moerr.NewInternalErrorf(ctx, "publication %s can only be subscribed once", subOption.Publication) } - sql = fmt.Sprintf("update mo_catalog.mo_subs set sub_name='%s', sub_time=now() where pub_account_name = '%s' and pub_name = '%s' and sub_account_id = %d", dbName, subOption.From, subOption.Publication, accountId) - return c.runSqlWithAccountId(sql, sysAccountId) + sql = fmt.Sprintf(` + UPDATE mo_catalog.mo_subs + SET sub_name='%s', sub_time=now() + WHERE pub_account_name = '%s' AND pub_name = '%s' AND sub_account_id = %d + `, dbName, subOption.From, subOption.Publication, accountId) + return c.runSqlWithAccountIdAndOptions( + sql, + sysAccountId, + executor.StatementOption{}.WithDisableLog(), + ) } func dropSubscription(ctx context.Context, c *Compile, dbName string) error { @@ -72,14 +88,25 @@ func dropSubscription(ctx context.Context, c *Compile, dbName string) error { } // update SubStatusNormal records - sql := fmt.Sprintf("update mo_catalog.mo_subs set sub_name=null, sub_time=null where sub_account_id = %d and sub_name = '%s' and status = %d", accountId, dbName, pubsub.SubStatusNormal) - if err = c.runSqlWithAccountId(sql, sysAccountId); err != nil { + sql := fmt.Sprintf(` + UPDATE mo_catalog.mo_subs + SET sub_name=null, sub_time=null + WHERE sub_account_id = %d AND sub_name = '%s' AND status = %d + `, accountId, dbName, pubsub.SubStatusNormal) + if err = c.runSqlWithAccountIdAndOptions( + sql, + sysAccountId, + executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } // delete SubStatusDeleted && SubStatusNotAuthorized records - sql = fmt.Sprintf("delete from mo_catalog.mo_subs where sub_account_id = %d and sub_name = '%s' and status != %d", accountId, dbName, pubsub.SubStatusNormal) - return c.runSqlWithAccountId(sql, sysAccountId) + sql = fmt.Sprintf(` + DELETE FROM mo_catalog.mo_subs + WHERE sub_account_id = %d AND sub_name = '%s' AND status != %d + `, accountId, dbName, pubsub.SubStatusNormal) + return c.runSqlWithAccountIdAndOptions(sql, sysAccountId, executor.StatementOption{}.WithDisableLog()) } func updatePubTableList(ctx context.Context, c *Compile, dbName, dropTblName string) error { @@ -94,8 +121,16 @@ func updatePubTableList(ctx context.Context, c *Compile, dbName, dropTblName str } accountName, err := func() (string, error) { - sql := fmt.Sprintf("select account_name from mo_catalog.mo_account where account_id = %d", accountId) - rs, err := c.runSqlWithResult(sql, sysAccountId) + sql := fmt.Sprintf(` + SELECT account_name + FROM mo_catalog.mo_account + WHERE account_id = %d + `, accountId) + rs, err := c.runSqlWithResultAndOptions( + sql, + sysAccountId, + executor.StatementOption{}.WithDisableLog(), + ) if err != nil { return "", err } @@ -116,8 +151,16 @@ func updatePubTableList(ctx context.Context, c *Compile, dbName, dropTblName str } // get pub - sql := fmt.Sprintf("select pub_name, table_list from mo_catalog.mo_pubs where account_id = %d and database_name = '%s'", accountId, dbName) - rs, err := c.runSqlWithResult(sql, sysAccountId) + sql := fmt.Sprintf(` + SELECT pub_name, table_list + FROM mo_catalog.mo_pubs + WHERE account_id = %d AND database_name = '%s' + `, accountId, dbName) + rs, err := c.runSqlWithResultAndOptions( + sql, + sysAccountId, + executor.StatementOption{}.WithDisableLog(), + ) if err != nil { return err } @@ -138,14 +181,30 @@ func updatePubTableList(ctx context.Context, c *Compile, dbName, dropTblName str newTableListStr := pubsub.RemoveTable(tableListStr, dropTblName) // update pub - sql = fmt.Sprintf("update mo_catalog.mo_pubs set table_list='%s' where account_id = %d and pub_name = '%s'", newTableListStr, accountId, pubName) - if err = c.runSqlWithAccountId(sql, sysAccountId); err != nil { + sql = fmt.Sprintf(` + UPDATE mo_catalog.mo_pubs + SET table_list='%s' + WHERE account_id = %d AND pub_name = '%s' + `, newTableListStr, accountId, pubName) + if err = c.runSqlWithAccountIdAndOptions( + sql, + sysAccountId, + executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } // update sub - sql = fmt.Sprintf("update mo_catalog.mo_subs set pub_tables='%s' where pub_account_name = '%s' and pub_name = '%s'", newTableListStr, accountName, pubName) - if err = c.runSqlWithAccountId(sql, sysAccountId); err != nil { + sql = fmt.Sprintf(` + UPDATE mo_catalog.mo_subs + SET pub_tables='%s' + WHERE pub_account_name = '%s' AND pub_name = '%s' + `, newTableListStr, accountName, pubName) + if err = c.runSqlWithAccountIdAndOptions( + sql, + sysAccountId, + executor.StatementOption{}.WithDisableLog(), + ); err != nil { return err } } diff --git a/pkg/sql/compile/scope.go b/pkg/sql/compile/scope.go index 3fd849dd0a114..3a8c308109ee3 100644 --- a/pkg/sql/compile/scope.go +++ b/pkg/sql/compile/scope.go @@ -27,6 +27,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/common/moerr" "github.com/matrixorigin/matrixone/pkg/common/reuse" "github.com/matrixorigin/matrixone/pkg/common/runtime" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/defines" "github.com/matrixorigin/matrixone/pkg/logutil" "github.com/matrixorigin/matrixone/pkg/objectio" @@ -146,7 +147,7 @@ func (s *Scope) Run(c *Compile) (err error) { if e := recover(); e != nil { err = moerr.ConvertPanicError(s.Proc.Ctx, e) c.proc.Error(c.proc.Ctx, "panic in scope run", - zap.String("sql", c.sql), + zap.String("sql", commonutil.Abbreviate(c.sql, 500)), zap.String("error", err.Error())) } if p != nil { @@ -446,7 +447,7 @@ func (s *Scope) ParallelRun(c *Compile) (err error) { if e := recover(); e != nil { err = moerr.ConvertPanicError(s.Proc.Ctx, e) c.proc.Error(c.proc.Ctx, "panic in scope run", - zap.String("sql", c.sql), + zap.String("sql", commonutil.Abbreviate(c.sql, 500)), zap.String("error", err.Error())) } @@ -906,7 +907,7 @@ func (s *Scope) replace(c *Compile) error { delAffectedRows := uint64(0) if deleteCond != "" { - result, err := c.runSqlWithResult(fmt.Sprintf("delete from `%s`.`%s` where %s", dbName, tblName, deleteCond), NoAccountId) + result, err := c.runSqlWithResult(fmt.Sprintf("DELETE FROM `%s`.`%s` WHERE %s", dbName, tblName, deleteCond), NoAccountId) if err != nil { return err } diff --git a/pkg/sql/compile/sql_executor.go b/pkg/sql/compile/sql_executor.go index 4f16f886d3534..f843102d83066 100644 --- a/pkg/sql/compile/sql_executor.go +++ b/pkg/sql/compile/sql_executor.go @@ -24,6 +24,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/common/moerr" "github.com/matrixorigin/matrixone/pkg/common/mpool" "github.com/matrixorigin/matrixone/pkg/common/runtime" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/container/batch" "github.com/matrixorigin/matrixone/pkg/defines" "github.com/matrixorigin/matrixone/pkg/fileservice" @@ -162,7 +163,7 @@ func (s *sqlExecutor) ExecTxn( if err != nil { logutil.Error("internal sql executor error", zap.Error(err), - zap.String("sql", opts.SQL()), + zap.String("sql", commonutil.Abbreviate(opts.SQL(), 500)), zap.String("txn", exec.Txn().Txn().DebugString()), ) return exec.rollback(err) @@ -523,12 +524,8 @@ func (exec *txnExecutor) Exec( } if !statementOption.DisableLog() { - printSql := sql - if len(printSql) > 1000 { - printSql = printSql[:1000] + "..." - } logutil.Info("sql_executor exec", - zap.String("sql", printSql), + zap.String("sql", commonutil.Abbreviate(sql, 500)), zap.String("txn-id", hex.EncodeToString(exec.opts.Txn().Txn().ID)), zap.Duration("duration", time.Since(receiveAt)), zap.Int("BatchSize", len(batches)), diff --git a/pkg/sql/plan/build_show.go b/pkg/sql/plan/build_show.go index 3867d6fed8fa3..731e149dcec12 100644 --- a/pkg/sql/plan/build_show.go +++ b/pkg/sql/plan/build_show.go @@ -74,7 +74,7 @@ func buildShowCreateDatabase(stmt *tree.ShowCreateDatabase, return returnByRewriteSQL(ctx, sql, plan.DataDefinition_SHOW_CREATEDATABASE) } - sqlStr := "select \"%s\" as `Database`, \"%s\" as `Create Database`" + sqlStr := "SELECT \"%s\" AS `Database`, \"%s\" AS `Create Database`" createSql := fmt.Sprintf("CREATE DATABASE `%s`", name) sqlStr = fmt.Sprintf(sqlStr, name, createSql) @@ -148,7 +148,7 @@ func buildShowCreateTable(stmt *tree.ShowCreateTable, ctx CompilerContext) (*Pla } buf.WriteRune(ch) } - sql := "select \"%s\" as `Table`, \"%s\" as `Create Table`" + sql := "SELECT \"%s\" AS `Table`, \"%s\" AS `Create Table`" sql = fmt.Sprintf(sql, tblName, buf.String()) return returnByRewriteSQL(ctx, sql, plan.DataDefinition_SHOW_CREATETABLE) @@ -231,7 +231,7 @@ func buildShowDatabases(stmt *tree.ShowDatabases, ctx CompilerContext) (*Plan, e // Any account should show database MO_CATALOG_DB_NAME accountClause := fmt.Sprintf("account_id = %v or (account_id = 0 and datname = '%s')", accountId, MO_CATALOG_DB_NAME) - sql = fmt.Sprintf("SELECT datname `Database` FROM %s.mo_database %s where (%s) ORDER BY %s", MO_CATALOG_DB_NAME, snapshotSpec, accountClause, catalog.SystemDBAttr_Name) + sql = fmt.Sprintf("SELECT datname `Database` FROM %s.mo_database %s WHERE (%s) ORDER BY %s", MO_CATALOG_DB_NAME, snapshotSpec, accountClause, catalog.SystemDBAttr_Name) if stmt.Where != nil { return returnByWhereAndBaseSQL(ctx, sql, stmt.Where, ddlType) @@ -256,7 +256,7 @@ func buildShowSequences(stmt *tree.ShowSequences, ctx CompilerContext) (*Plan, e ddlType := plan.DataDefinition_SHOW_SEQUENCES - sql := fmt.Sprintf("select %s.mo_tables.relname as `Names`, mo_show_visible_bin(%s.mo_columns.atttyp, 2) as 'Data Type' from %s.mo_tables left join %s.mo_columns on %s.mo_tables.rel_id = %s.mo_columns.att_relname_id where %s.mo_tables.relkind = '%s' and %s.mo_tables.reldatabase = '%s' and %s.mo_columns.attname = '%s'", MO_CATALOG_DB_NAME, + sql := fmt.Sprintf("SELECT %s.mo_tables.relname AS `Names`, mo_show_visible_bin(%s.mo_columns.atttyp, 2) AS 'Data Type' FROM %s.mo_tables LEFT JOIN %s.mo_columns ON %s.mo_tables.rel_id = %s.mo_columns.att_relname_id WHERE %s.mo_tables.relkind = '%s' AND %s.mo_tables.reldatabase = '%s' AND %s.mo_columns.attname = '%s'", MO_CATALOG_DB_NAME, MO_CATALOG_DB_NAME, MO_CATALOG_DB_NAME, MO_CATALOG_DB_NAME, MO_CATALOG_DB_NAME, MO_CATALOG_DB_NAME, MO_CATALOG_DB_NAME, catalog.SystemSequenceRel, MO_CATALOG_DB_NAME, dbName, MO_CATALOG_DB_NAME, Sequence_cols_name[0]) if stmt.Where != nil { @@ -1071,7 +1071,7 @@ func buildShowCreatePublications(stmt *tree.ShowCreatePublications, ctx Compiler if err != nil { return nil, err } - sql := fmt.Sprintf("select pub_name as Publication, 'CREATE PUBLICATION ' || pub_name || ' DATABASE ' || database_name || case table_list when '*' then '' else ' TABLE ' || table_list end || ' ACCOUNT ' || account_list as 'Create Publication' from mo_catalog.mo_pubs where account_id = %d and pub_name='%s';", accountId, stmt.Name) + sql := fmt.Sprintf("SELECT pub_name AS Publication, 'CREATE PUBLICATION ' || pub_name || ' DATABASE ' || database_name || CASE table_list WHEN '*' THEN '' ELSE ' TABLE ' || table_list END || ' ACCOUNT ' || account_list AS 'Create Publication' FROM mo_catalog.mo_pubs WHERE account_id = %d AND pub_name='%s';", accountId, stmt.Name) ctx.SetContext(defines.AttachAccountId(ctx.GetContext(), catalog.System_Account)) return returnByRewriteSQL(ctx, sql, ddlType) } @@ -1079,10 +1079,10 @@ func buildShowCreatePublications(stmt *tree.ShowCreatePublications, ctx Compiler func returnByRewriteSQL(ctx CompilerContext, sql string, ddlType plan.DataDefinition_DdlType) (*Plan, error) { newStmt, err := getRewriteSQLStmt(ctx, sql) - defer newStmt.Free() if err != nil { return nil, err } + defer newStmt.Free() return getReturnDdlBySelectStmt(ctx, newStmt, ddlType) } diff --git a/pkg/sql/plan/function/func_mo.go b/pkg/sql/plan/function/func_mo.go index c26e5627fdb19..3f914e5a281fd 100644 --- a/pkg/sql/plan/function/func_mo.go +++ b/pkg/sql/plan/function/func_mo.go @@ -29,6 +29,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/catalog" "github.com/matrixorigin/matrixone/pkg/common/moerr" "github.com/matrixorigin/matrixone/pkg/common/pubsub" + commonutil "github.com/matrixorigin/matrixone/pkg/common/util" "github.com/matrixorigin/matrixone/pkg/container/bytejson" "github.com/matrixorigin/matrixone/pkg/container/types" "github.com/matrixorigin/matrixone/pkg/container/vector" @@ -229,7 +230,7 @@ func isSubscribedTable( zap.String("db name", dbName), zap.String("tbl name", tblName), zap.String("subscription", sub.String()), - zap.String("sql", sql), + zap.String("sql", commonutil.Abbreviate(sql, 500)), ) } }() diff --git a/pkg/sql/plan/tools/matcher.go b/pkg/sql/plan/tools/matcher.go index 3808215d8ff49..943464cbb81d6 100644 --- a/pkg/sql/plan/tools/matcher.go +++ b/pkg/sql/plan/tools/matcher.go @@ -390,7 +390,7 @@ func (matcher *JoinMatcher) String() string { } func parseSql(sql string) tree.Expr { - exSql := "select " + sql + exSql := "SELECT " + sql one, err := parsers.ParseOne(context.Background(), dialect.MYSQL, exSql, 1) if err != nil { panic(err) diff --git a/pkg/util/export/batch_processor.go b/pkg/util/export/batch_processor.go index 5de37599daa56..ded37139f3ce6 100644 --- a/pkg/util/export/batch_processor.go +++ b/pkg/util/export/batch_processor.go @@ -229,7 +229,7 @@ func (b *bufferHolder) loopAggr() { return } counter := v2.GetTraceMOLoggerAggrCounter(b.name) - logutil.Info("handle-aggr-start") + logutil.Info("logger.aggr.start") mainL: for { select { @@ -245,9 +245,8 @@ mainL: recordCnt += len(results) if time.Since(lastPrintTime) > printInterval { logutil.Info( - "handle-aggr", - zap.Int("records", recordCnt), - zap.Time("end", end), + "logger.aggr.handle.count", + zap.Int("count", recordCnt), ) recordCnt = 0 lastPrintTime = time.Now() @@ -256,14 +255,14 @@ mainL: case <-b.bgCtx.Done(): // trigger by b.bgCancel - logger.Info("handle-aggr-bgctx-done") + logger.Info("logger.aggr.bgctx.done") break mainL case <-b.ctx.Done(): - logutil.Info("handle-aggr-ctx-done") + logutil.Info("logger.aggr.ctx.done") break mainL } } - logutil.Info("handle-aggr-exit") + logutil.Info("logger.aggr.exit") } var _ generateReq = (*bufferGenerateReq)(nil) diff --git a/pkg/util/metric/config.go b/pkg/util/metric/config.go index aaa90db6a10fc..b39ab529cf611 100644 --- a/pkg/util/metric/config.go +++ b/pkg/util/metric/config.go @@ -28,7 +28,7 @@ var ( // full buffer approximately cost (56[Sample struct] + 8[pointer]) x 4096 = 256K configRawHistBufLimit int32 = EnvOrDefaultInt[int32]("MO_METRIC_RAWHIST_BUF_LIMIT", 4096) configGatherInterval int64 = EnvOrDefaultInt[int64]("MO_METRIC_GATHER_INTERVAL", 15000) // 15s - configStatsGatherInterval int64 = EnvOrDefaultInt[int64]("MO_STATS_GATHER_INTERVAL", 15000) // 15s + configStatsGatherInterval int64 = EnvOrDefaultInt[int64]("MO_STATS_GATHER_INTERVAL", 150000) // 15s configExportToProm int32 = EnvOrDefaultBool("MO_METRIC_EXPORT_TO_PROM", 1) configForceReinit int32 = EnvOrDefaultBool("MO_METRIC_DROP_AND_INIT", 0) // TODO: find a better way to init metrics and remove this one ) diff --git a/pkg/util/metric/mometric/cron_task.go b/pkg/util/metric/mometric/cron_task.go index 5948bba376201..e5be91705d5f7 100644 --- a/pkg/util/metric/mometric/cron_task.go +++ b/pkg/util/metric/mometric/cron_task.go @@ -467,9 +467,13 @@ func checkNewAccountSize(ctx context.Context, logger *log.MOLogger, sqlExecutor // done query. // update new accounts metric - logger.Info("new account storage_usage", zap.String("account", account), zap.Uint32("account_id", accountId), zap.Float64("sizeMB", sizeMB), - zap.Float64("snapshot", snapshotSizeMB), - zap.String("created_time", createdTime)) + logger.Info( + "storage_usage.new_account", + zap.String("name", account), + zap.Float64("size-mb", sizeMB), + zap.Float64("snapshot-mb", snapshotSizeMB), + zap.String("created-time", createdTime), + ) metric.StorageUsage(account, accountId).Set(sizeMB) metric.SnapshotUsage(account, accountId).Set(snapshotSizeMB) diff --git a/pkg/util/metric/mometric/stats_log_writer.go b/pkg/util/metric/mometric/stats_log_writer.go index 122168ee834c1..d94aac42cb905 100644 --- a/pkg/util/metric/mometric/stats_log_writer.go +++ b/pkg/util/metric/mometric/stats_log_writer.go @@ -16,14 +16,11 @@ package mometric import ( "context" - "fmt" "sync" "sync/atomic" "time" "github.com/matrixorigin/matrixone/pkg/common/log" - "github.com/matrixorigin/matrixone/pkg/objectio" - "github.com/matrixorigin/matrixone/pkg/pb/metadata" "github.com/matrixorigin/matrixone/pkg/util/metric/stats" ) @@ -91,38 +88,4 @@ func (e *StatsLogWriter) gatherAndWrite(ctx context.Context) { e.logger.Info(statsFName, statsFamily...) } } - - // logging block read statistics info here - v := ctx.Value(ServiceTypeKey).(string) - if v == metadata.ServiceType_name[int32(metadata.ServiceType_CN)] || v == LaunchMode { - e.writeBlkReadStats() - } -} - -func (e *StatsLogWriter) writeBlkReadStats() { - blkHit, blkTotal := objectio.BlkReadStats.BlkCacheHitStats.ExportW() - blkHitRate := float32(1) - if blkTotal != 0 { - blkHitRate = float32(blkHit) / float32(blkTotal) - } - - entryHit, entryTotal := objectio.BlkReadStats.EntryCacheHitStats.ExportW() - entryHitRate := float32(1) - if entryTotal != 0 { - entryHitRate = float32(entryHit) / float32(entryTotal) - } - - readerNum, blkNum := objectio.BlkReadStats.BlksByReaderStats.ExportW() - blksInEachReader := float32(1) - if readerNum != 0 { - blksInEachReader = float32(blkNum) / float32(readerNum) - } - - e.logger.Info(fmt.Sprintf("duration: %d, "+ - "blk hit rate: %d/%d=%.4f, entry hit rate: %d/%d=%.4f, (average) blks in each reader: %d/%d=%.4f", - e.gatherInterval, - blkHit, blkTotal, blkHitRate, - entryHit, entryTotal, entryHitRate, - blkNum, readerNum, blksInEachReader)) - } diff --git a/pkg/util/metric/mometric/stats_log_writer_test.go b/pkg/util/metric/mometric/stats_log_writer_test.go deleted file mode 100644 index 876f2086746dc..0000000000000 --- a/pkg/util/metric/mometric/stats_log_writer_test.go +++ /dev/null @@ -1,202 +0,0 @@ -// Copyright 2023 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 mometric - -import ( - "context" - "fmt" - "math/rand" - "sync" - "testing" - "time" - - "github.com/matrixorigin/matrixone/pkg/common/moerr" - "github.com/matrixorigin/matrixone/pkg/common/runtime" - "github.com/matrixorigin/matrixone/pkg/logutil" - "github.com/matrixorigin/matrixone/pkg/objectio" - "github.com/matrixorigin/matrixone/pkg/pb/metadata" - "github.com/matrixorigin/matrixone/pkg/util/metric/stats" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - "go.uber.org/zap" - "go.uber.org/zap/zapcore" -) - -// MockService for testing stats Registry -type MockService struct { - stats *MockStats -} - -type MockStats struct { - reads stats.Counter - hits stats.Counter -} - -func NewMockService() *MockService { - return &MockService{ - stats: &MockStats{}, - } -} - -func (d *MockService) Do() { - d.stats.reads.Add(2) - d.stats.hits.Add(1) -} - -func (d *MockService) Stats() *MockStats { - return d.stats -} - -// LogExporter for the Mock Service declared above -type MockServiceLogExporter struct { - service *MockService -} - -func NewMockServiceLogExporter(service *MockService) stats.LogExporter { - return &MockServiceLogExporter{ - service: service, - } -} - -func (c *MockServiceLogExporter) Export() []zap.Field { - var fields []zap.Field - - stats := c.service.Stats() - - reads := stats.reads.SwapW(0) - hits := stats.hits.SwapW(0) - - fields = append(fields, zap.Any("reads", reads)) - fields = append(fields, zap.Any("hits", hits)) - - return fields -} - -func TestStatsLogWriter(t *testing.T) { - // 1. Register Dev Stats - service := NewMockService() - serviceLogExporter := NewMockServiceLogExporter(service) - stats.Register("MockServiceStats", stats.WithLogExporter(serviceLogExporter)) - - //2.1 Setup a Runtime - runtime.SetupServiceBasedRuntime("", runtime.NewRuntime(metadata.ServiceType_CN, "test", logutil.GetGlobalLogger())) - - //2.2 Create custom Hook logger - type threadSafeWrittenLog struct { - content []zapcore.Entry - // This is because, BusyLoop and StatsLogger read (ie len) and write (content) to the same field. - sync.Mutex - } - - writtenLogs := threadSafeWrittenLog{} - customLogger := runtime.ServiceRuntime("").Logger().WithOptions(zap.Hooks(func(entry zapcore.Entry) error { - writtenLogs.Lock() - defer writtenLogs.Unlock() - writtenLogs.content = append(writtenLogs.content, entry) - return nil - })) - - // 2.3 Start the LogWriter - c := newStatsLogWriter(stats.DefaultRegistry, customLogger, 100*time.Millisecond) - serviceCtx := context.WithValue(context.Background(), ServiceTypeKey, "DN") - assert.True(t, c.Start(serviceCtx)) - - // 3. Perform operations on Dev Stats - service.Do() - - // 4. Wait for log to print in console. (Busy Loop) - err := waitUtil(60*time.Second, 100*time.Millisecond, func() bool { - writtenLogs.Lock() - defer writtenLogs.Unlock() - return len(writtenLogs.content) >= 10 - }) - require.NoError(t, err) - - // 5. Stop the LogWriter - if ch, effect := c.Stop(true); effect { - <-ch - } - println("StatsLogWriter has stopped gracefully.") - - //6. Validate the log printed. - writtenLogs.Lock() - defer writtenLogs.Unlock() - assert.True(t, len(writtenLogs.content) >= 10) - for _, log := range writtenLogs.content { - assert.Contains(t, log.Message, "Stats") - } - - // 7. (Optional) Read from the console and validate the log. Example log: - // 2023/03/15 02:37:31.767463 -0500 INFO cn-service mometric/stats_log_writer.go:86 MockServiceStats stats {"uuid": "test", "reads": 2, "hits": 1} - // 2023/03/15 02:37:33.767659 -0500 INFO cn-service mometric/stats_log_writer.go:86 MockServiceStats stats {"uuid": "test", "reads": 0, "hits": 0} - // 2023/03/15 02:37:35.767608 -0500 INFO cn-service mometric/stats_log_writer.go:86 MockServiceStats stats {"uuid": "test", "reads": 0, "hits": 0} - // StatsLogWriter has stopped gracefully. - -} - -// waitUtil Busy Loop to wait until check() is true. -func waitUtil(timeout, checkInterval time.Duration, check func() bool) error { - timeoutTimer := time.After(timeout) - for { - select { - case <-timeoutTimer: - return moerr.NewInternalError(context.TODO(), "timeout") - default: - if check() { - return nil - } - time.Sleep(checkInterval) - } - } -} - -func TestWriteBlkReadStats(t *testing.T) { - h1, t1 := rand.Int(), rand.Int()+1 - objectio.BlkReadStats.BlksByReaderStats.Record(h1, t1) - - h2, t2 := rand.Int(), rand.Int()+1 - objectio.BlkReadStats.EntryCacheHitStats.Record(h2, t2) - - h3, t3 := rand.Int(), rand.Int()+1 - objectio.BlkReadStats.BlkCacheHitStats.Record(h3, t3) - - s := new(StatsLogWriter) - type threadSafeWrittenLog struct { - content []zapcore.Entry - // This is because, BusyLoop and StatsLogger read (ie len) and write (content) to the same field. - sync.Mutex - } - - writtenLogs := threadSafeWrittenLog{} - runtime.SetupServiceBasedRuntime("", runtime.NewRuntime(metadata.ServiceType_CN, "test", logutil.GetGlobalLogger())) - s.logger = runtime.ServiceRuntime("").Logger().WithOptions(zap.Hooks(func(entry zapcore.Entry) error { - writtenLogs.Lock() - defer writtenLogs.Unlock() - writtenLogs.content = append(writtenLogs.content, entry) - return nil - })) - s.writeBlkReadStats() - - expected := fmt.Sprintf("duration: %d, "+ - "blk hit rate: %d/%d=%.4f, entry hit rate: %d/%d=%.4f, (average) blks in each reader: %d/%d=%.4f", - s.gatherInterval, - h3, t3, float32(h3)/float32(t3), - h2, t2, float32(h2)/float32(t2), - t1, h1, float32(t1)/float32(h1), - ) - - require.Equal(t, writtenLogs.content[0].Level, zapcore.InfoLevel) - require.Equal(t, writtenLogs.content[0].Message, expected) -} diff --git a/pkg/vectorindex/sqlexec/sqlexec.go b/pkg/vectorindex/sqlexec/sqlexec.go index cb87ff1acc5cd..25ce76d8942a0 100644 --- a/pkg/vectorindex/sqlexec/sqlexec.go +++ b/pkg/vectorindex/sqlexec/sqlexec.go @@ -144,7 +144,8 @@ func RunSql(sqlproc *SqlProcess, sql string) (executor.Result, error) { WithDatabase(proc.GetSessionInfo().Database). WithTimeZone(proc.GetSessionInfo().TimeZone). WithAccountID(accountId). - WithResolveVariableFunc(proc.GetResolveVariableFunc()) + WithResolveVariableFunc(proc.GetResolveVariableFunc()). + WithStatementOption(executor.StatementOption{}.WithDisableLog()) return exec.Exec(topContext, sql, opts) } else { @@ -163,7 +164,8 @@ func RunSql(sqlproc *SqlProcess, sql string) (executor.Result, error) { WithDisableIncrStatement(). WithTxn(sqlctx.Txn()). WithAccountID(accountId). - WithResolveVariableFunc(sqlctx.GetResolveVariableFunc()) + WithResolveVariableFunc(sqlctx.GetResolveVariableFunc()). + WithStatementOption(executor.StatementOption{}.WithDisableLog()) return exec.Exec(sqlctx.Ctx, sql, opts) } @@ -201,7 +203,8 @@ func RunStreamingSql( WithTimeZone(proc.GetSessionInfo().TimeZone). WithAccountID(accountId). WithStreaming(stream_chan, error_chan). - WithResolveVariableFunc(proc.GetResolveVariableFunc()) + WithResolveVariableFunc(proc.GetResolveVariableFunc()). + WithStatementOption(executor.StatementOption{}.WithDisableLog()) return exec.Exec(ctx, sql, opts) } else { @@ -222,7 +225,8 @@ func RunStreamingSql( WithTxn(sqlctx.Txn()). WithAccountID(accountId). WithStreaming(stream_chan, error_chan). - WithResolveVariableFunc(sqlctx.GetResolveVariableFunc()) + WithResolveVariableFunc(sqlctx.GetResolveVariableFunc()). + WithStatementOption(executor.StatementOption{}.WithDisableLog()) return exec.Exec(ctx, sql, opts) } diff --git a/pkg/vm/engine/disttae/cache/catalog.go b/pkg/vm/engine/disttae/cache/catalog.go index ecb074262b01c..862e4c21801d6 100644 --- a/pkg/vm/engine/disttae/cache/catalog.go +++ b/pkg/vm/engine/disttae/cache/catalog.go @@ -18,7 +18,6 @@ import ( "sort" "strings" "sync" - "time" "go.uber.org/zap" @@ -62,9 +61,11 @@ func (cc *CatalogCache) UpdateDuration(start types.TS, end types.TS) { defer cc.mu.Unlock() cc.mu.start = start cc.mu.end = end - logutil.Info("FIND_TABLE CACHE update serve range", + logutil.Info( + "catalog.cache.update.start.end", zap.String("start", cc.mu.start.ToString()), - zap.String("end", cc.mu.end.ToString())) + zap.String("end", cc.mu.end.ToString()), + ) } func (cc *CatalogCache) UpdateStart(ts types.TS) { @@ -72,9 +73,11 @@ func (cc *CatalogCache) UpdateStart(ts types.TS) { defer cc.mu.Unlock() if cc.mu.start != types.MaxTs() && ts.GT(&cc.mu.start) { cc.mu.start = ts - logutil.Info("FIND_TABLE CACHE update serve range (by start)", + logutil.Info( + "catalog.cache.update.start", zap.String("start", cc.mu.start.ToString()), - zap.String("end", cc.mu.end.ToString())) + zap.String("end", cc.mu.end.ToString()), + ) } } @@ -113,7 +116,6 @@ func (cc *CatalogCache) GC(ts timestamp.Timestamp) GCReport { */ - inst := time.Now() r := GCReport{} { // table cache gc var prevName string @@ -195,8 +197,6 @@ func (cc *CatalogCache) GC(ts timestamp.Timestamp) GCReport { } } cc.UpdateStart(types.TimestampToTS(ts)) - duration := time.Since(inst) - logutil.Info("FIND_TABLE CACHE gc", zap.Any("report", r), zap.Duration("cost", duration)) return r } diff --git a/pkg/vm/engine/disttae/engine.go b/pkg/vm/engine/disttae/engine.go index 7e0b5d333d410..d87bbbd6b86e1 100644 --- a/pkg/vm/engine/disttae/engine.go +++ b/pkg/vm/engine/disttae/engine.go @@ -44,7 +44,6 @@ import ( client2 "github.com/matrixorigin/matrixone/pkg/queryservice/client" "github.com/matrixorigin/matrixone/pkg/txn/client" v2 "github.com/matrixorigin/matrixone/pkg/util/metric/v2" - "github.com/matrixorigin/matrixone/pkg/util/stack" "github.com/matrixorigin/matrixone/pkg/version" "github.com/matrixorigin/matrixone/pkg/vm/engine" "github.com/matrixorigin/matrixone/pkg/vm/engine/disttae/cache" @@ -297,13 +296,18 @@ func (e *Engine) Create(ctx context.Context, name string, op client.TxnOperator) func (e *Engine) loadDatabaseFromStorage( ctx context.Context, accountID uint32, - name string, op client.TxnOperator) (*cache.DatabaseItem, error) { + name string, + op client.TxnOperator, +) (*cache.DatabaseItem, error) { sql := fmt.Sprintf(catalog.MoDatabaseAllQueryFormat, accountID, name) now := time.Now() defer func() { if time.Since(now) > time.Second { - logutil.Info("FIND_TABLE slow loadDatabaseFromStorage", - zap.String("sql", sql), zap.Duration("cost", time.Since(now))) + logutil.Info( + "engine.database.load.from.storage.slow", + zap.String("sql", sql), + zap.Duration("cost", time.Since(now)), + ) } }() res, err := execReadSql(ctx, op, sql, true) @@ -312,10 +316,14 @@ func (e *Engine) loadDatabaseFromStorage( } defer res.Close() logerror := func() { - logutil.Error("FIND_TABLE bad loadDatabaseFromStorage", zap.String("batch", stringifySlice(res.Batches, func(a any) string { - bat := a.(*batch.Batch) - return common.MoBatchToString(bat, 10) - })), zap.String("sql", sql)) + logutil.Error( + "engine.database.load.from.storage.bad", + zap.String("sql", sql), + zap.String("batch", stringifySlice(res.Batches, func(a any) string { + bat := a.(*batch.Batch) + return common.MoBatchToString(bat, 10) + })), + ) } if len(res.Batches) != 1 { // not found @@ -391,7 +399,12 @@ func (e *Engine) Database( if ok := catalog.GetDatabase(item); !ok { if !catalog.CanServe(types.TimestampToTS(op.SnapshotTS())) { - logutil.Info("FIND_TABLE loadDatabaseFromStorage", zap.String("name", name), zap.String("cacheTs", catalog.GetStartTS().ToString()), zap.String("txn", op.Txn().DebugString())) + logutil.Info( + "engine.database.load.from.storage", + zap.String("name", name), + zap.String("cache-start", catalog.GetStartTS().ToString()), + zap.String("txn", op.Txn().DebugString()), + ) // read batch from storage if item, err = e.loadDatabaseFromStorage(ctx, accountId, name, op); err != nil { return nil, err @@ -441,7 +454,12 @@ func (e *Engine) GetNameById(ctx context.Context, op client.TxnOperator, tableId return } -func loadNameByIdFromStorage(ctx context.Context, op client.TxnOperator, accountId uint32, tableId uint64) (dbName string, tblName string, err error) { +func loadNameByIdFromStorage( + ctx context.Context, + op client.TxnOperator, + accountId uint32, + tableId uint64, +) (dbName string, tblName string, err error) { sql := fmt.Sprintf(catalog.MoTablesQueryNameById, accountId, tableId) tblanmes, dbnames := []string{}, []string{} result, err := execReadSql(ctx, op, sql, true) @@ -455,9 +473,14 @@ func loadNameByIdFromStorage(ctx context.Context, op client.TxnOperator, account } } if len(tblanmes) != 1 { - logutil.Warn("FIND_TABLE GetRelationById sql failed", - zap.Uint64("tableId", tableId), zap.Uint32("accountId", accountId), - zap.Strings("tblanmes", tblanmes), zap.Strings("dbnames", dbnames), zap.String("txn", op.Txn().DebugString())) + logutil.Warn( + "engine.relation.load.from.storage.bad", + zap.Uint64("table-id", tableId), + zap.Uint32("account-id", accountId), + zap.Strings("table-names", tblanmes), + zap.Strings("db-names", dbnames), + zap.String("txn", op.Txn().DebugString()), + ) } else { tblName = tblanmes[0] dbName = dbnames[0] @@ -489,7 +512,7 @@ func (e *Engine) GetRelationById(ctx context.Context, op client.TxnOperator, tab txn := op.GetWorkspace().(*Transaction) dbName, tableName, deleted := txn.tableOps.queryNameByTid(tableId) if tableName == "" && deleted { - return "", "", nil, moerr.NewInternalErrorf(ctx, "can not find table by id %d: accountId: %v. Deleted in txn", tableId, accountId) + return "", "", nil, moerr.NewInternalErrorf(ctx, "can not find table by id %d: accountId: %d. Deleted in txn", tableId, accountId) } // not found in tableOps, try cache @@ -501,9 +524,14 @@ func (e *Engine) GetRelationById(ctx context.Context, op client.TxnOperator, tab dbName = cacheItem.DatabaseName } else if !cache.CanServe(types.TimestampToTS(op.SnapshotTS())) { // not found in cache, try storage - logutil.Info("FIND_TABLE loadNameByIdFromStorage", zap.String("txn", op.Txn().DebugString()), zap.Uint64("tableId", tableId)) - dbName, tableName, err = loadNameByIdFromStorage(ctx, op, accountId, tableId) - if err != nil { + logutil.Info( + "engine.relation.load.from.storage", + zap.String("txn", op.Txn().DebugString()), + zap.Uint64("table-id", tableId), + ) + if dbName, tableName, err = loadNameByIdFromStorage( + ctx, op, accountId, tableId, + ); err != nil { return "", "", nil, err } } @@ -511,9 +539,11 @@ func (e *Engine) GetRelationById(ctx context.Context, op client.TxnOperator, tab if tableName == "" { accountId, _ := defines.GetAccountId(ctx) - logutil.Error("FIND_TABLE GetRelationById failed", - zap.Uint64("tableId", tableId), zap.Uint32("accountId", accountId), zap.String("workspace", txn.PPString())) - return "", "", nil, moerr.NewInternalErrorf(ctx, "can not find table by id %d: accountId: %v ", tableId, accountId) + return "", "", nil, moerr.NewInternalErrorf( + ctx, + "can not find table by id %d: accountId: %d", + tableId, accountId, + ) } txnDb, err := e.Database(ctx, dbName, op) @@ -534,15 +564,6 @@ func (e *Engine) AllocateIDByKey(ctx context.Context, key string) (uint64, error } func (e *Engine) Delete(ctx context.Context, name string, op client.TxnOperator) (err error) { - defer func() { - if err != nil { - if strings.Contains(name, "sysbench_db") { - logutil.Errorf("delete database %s failed: %v", name, err) - logutil.Errorf("stack: %s", stack.Callers(3)) - logutil.Errorf("txnmeta %v", op.Txn().DebugString()) - } - } - }() if op.IsSnapOp() { return moerr.NewInternalErrorNoCtx("delete database in snapshot txn") } @@ -576,20 +597,24 @@ func (e *Engine) Delete(ctx context.Context, name string, op client.TxnOperator) if err != nil { return err } - res, err := execReadSql(ctx, op, fmt.Sprintf(catalog.MoDatabaseRowidQueryFormat, accountId, name), true) + res, err := execReadSql( + ctx, op, fmt.Sprintf(catalog.MoDatabaseRowidQueryFormat, accountId, name), true, + ) if err != nil { return err } if len(res.Batches) != 1 || res.Batches[0].Vecs[0].Length() != 1 { - logutil.Error("FIND_TABLE deleteDatabaseError", + logutil.Error( + "engine.delete.relation.bad", + zap.Uint64("db-id", databaseId), + zap.Uint32("account-id", accountId), + zap.String("name", name), + zap.String("workspace", op.GetWorkspace().PPString()), zap.String("bat", stringifySlice(res.Batches, func(a any) string { bat := a.(*batch.Batch) return common.MoBatchToString(bat, 10) })), - zap.Uint32("accountId", accountId), - zap.String("name", name), - zap.Uint64("did", databaseId), - zap.String("workspace", op.GetWorkspace().PPString())) + ) panic("delete table failed: query failed") } rowId := vector.GetFixedAtNoTypeCheck[types.Rowid](res.Batches[0].Vecs[0], 0) @@ -863,7 +888,7 @@ func (e *Engine) RunGCScheduler(ctx context.Context) { for { select { case <-ctx.Done(): - logutil.Infof("GC scheduler exit.") + logutil.Info("engine.gc.scheduler.stopped") return case <-unusedTableTicker.C: @@ -889,6 +914,5 @@ func (e *Engine) gcPartitionState(ctx context.Context) { if !e.pClient.receivedLogTailTime.ready.Load() { return } - logutil.Debugf("Running partition state GC") e.pClient.doGCPartitionState(ctx, e) } diff --git a/pkg/vm/engine/disttae/logtail_consumer.go b/pkg/vm/engine/disttae/logtail_consumer.go index 3c5094fd9200d..48fddd2caaa3e 100644 --- a/pkg/vm/engine/disttae/logtail_consumer.go +++ b/pkg/vm/engine/disttae/logtail_consumer.go @@ -278,7 +278,7 @@ func (c *connector) run(ctx context.Context) { for { select { case <-ctx.Done(): - logutil.Infof("%s logtail consumer stopped", logTag) + logutil.Info("logtail.consumer.stopped") return case <-c.signal: @@ -539,7 +539,11 @@ func (c *PushClient) subSysTables(ctx context.Context) error { } if err != nil { - logutil.Errorf("%s %s: connect to tn log tail server failed, err %v", logTag, c.serviceID, err) + logutil.Error( + "logtail.consumer.connect.to.tn.logtail.server.failed", + zap.String("service", c.serviceID), + zap.Error(err), + ) } return err } @@ -558,7 +562,7 @@ func (c *PushClient) pause(s bool) { case c.pauseC <- s: c.mu.paused = true default: - logutil.Infof("%s already set to pause", logTag) + logutil.Info("logtail.consumer.already.set.to.pause") } } @@ -569,7 +573,7 @@ func (c *PushClient) resume() { case c.resumeC <- struct{}{}: c.mu.paused = false default: - logutil.Infof("%s not in pause state", logTag) + logutil.Info("logtail.consumer.not.in.pause.state") } } @@ -588,7 +592,10 @@ func (c *PushClient) receiveOneLogtail(ctx context.Context, e *Engine) error { if resp.err != nil { resp.err = moerr.AttachCause(ctx, resp.err) // POSSIBLE ERROR: context deadline exceeded, rpc closed, decode error. - logutil.Errorf("%s receive an error from log tail client, err: %s", logTag, resp.err) + logutil.Error( + "logtail.consumer.receive.error.from.logtail.client", + zap.Error(resp.err), + ) return resp.err } @@ -598,7 +605,10 @@ func (c *PushClient) receiveOneLogtail(ctx context.Context, e *Engine) error { v2.LogtailSubscribeReceivedCounter.Inc() if err := dispatchSubscribeResponse(ctx, e, res, c.receiver, receiveAt); err != nil { err = moerr.AttachCause(ctx, err) - logutil.Errorf("%s dispatch subscribe response failed, err: %s", logTag, err) + logutil.Error( + "logtail.consumer.dispatch.subscribe.response.failed", + zap.Error(err), + ) return err } } else if res := resp.response.GetUpdateResponse(); res != nil { // consume update response @@ -610,7 +620,10 @@ func (c *PushClient) receiveOneLogtail(ctx context.Context, e *Engine) error { if err := dispatchUpdateResponse(ctx, e, res, c.receiver, receiveAt); err != nil { err = moerr.AttachCause(ctx, err) - logutil.Errorf("%s dispatch update response failed, err: %s", logTag, err) + logutil.Error( + "logtail.consumer.dispatch.update.response.failed", + zap.Error(err), + ) return err } } else if unResponse := resp.response.GetUnsubscribeResponse(); unResponse != nil { // consume unsubscribe response @@ -618,7 +631,10 @@ func (c *PushClient) receiveOneLogtail(ctx context.Context, e *Engine) error { if err := dispatchUnSubscribeResponse(ctx, e, unResponse, c.receiver, receiveAt); err != nil { err = moerr.AttachCause(ctx, err) - logutil.Errorf("%s dispatch unsubscribe response failed, err: %s", logTag, err) + logutil.Error( + "logtail.consumer.dispatch.unsubscribe.response.failed", + zap.Error(err), + ) return err } } else if errRsp := resp.response.GetError(); errRsp != nil { @@ -639,7 +655,7 @@ func (c *PushClient) receiveLogtails(ctx context.Context, e *Engine) { return case s := <-c.pauseC: - logutil.Infof("%s logtail receiver paused", logTag) + logutil.Info("logtail.consumer.receiver.paused") if s { c.sendConnectSig() } @@ -651,11 +667,14 @@ func (c *PushClient) receiveLogtails(ctx context.Context, e *Engine) { case <-c.resumeC: } - logutil.Infof("%s logtail receiver resumed", logTag) + logutil.Info("logtail.consumer.receiver.resumed") default: if err := c.receiveOneLogtail(ctx, e); err != nil { - logutil.Errorf("%s receive one logtail failed, err: %v", logTag, err) + logutil.Error( + "logtail.consumer.receive.one.logtail.failed", + zap.Error(err), + ) c.pause(!c.connector.first.Load()) } } @@ -1067,7 +1086,7 @@ func (c *PushClient) partitionStateGCTicker(ctx context.Context, e *Engine) { for { select { case <-ctx.Done(): - logutil.Infof("%s GC partition_state process exit.", logTag) + logutil.Info("logtail.consumer.partition.state.gc.ticker.stopped") return case <-ticker.C: @@ -1091,7 +1110,6 @@ func (c *PushClient) TryGC(ctx context.Context) { if !c.subscriber.ready() { return } - logutil.Debugf("%s Running unused table GC", logTag) c.doGCUnusedTable(ctx) } @@ -1250,10 +1268,11 @@ func (c *PushClient) waitUntilSubscribingChanged(ctx context.Context, dbId, tblI } } } - logutil.Errorf("%s wait for tbl[db: %d, tbl: %d] subscribing changed timeout[%s]", - logTag, dbId, tblId, maxTimeToCheckTableSubscribeSucceed) - return InvalidSubState, moerr.NewInternalErrorf(ctx, "Wait for tbl[db:%d, tbl:%d] subscribing changed timeout", - dbId, tblId) + return InvalidSubState, moerr.NewInternalErrorf( + ctx, + "wait for table subscribing changed timeout: db-id: %d, tbl-id: %d, timeout: %s", + dbId, tblId, maxTimeToCheckTableSubscribeSucceed, + ) } func (c *PushClient) waitUntilUnsubscribingChanged(ctx context.Context, dbId, tblId uint64) (SubscribeState, error) { @@ -1274,10 +1293,12 @@ func (c *PushClient) waitUntilUnsubscribingChanged(ctx context.Context, dbId, tb } } } - logutil.Errorf("%s wait for tbl[db: %d, tbl: %d] unsubscribing changed timeout[%s]", - logTag, dbId, tblId, maxTimeToCheckTableUnSubscribeSucceed) - return InvalidSubState, moerr.NewInternalErrorf(ctx, "Wait for tbl[db:%d, tbl:%d] unsubscribing changed timeout", - dbId, tblId) + + return InvalidSubState, moerr.NewInternalErrorf( + ctx, + "wait for table unsubscribing changed timeout: db-id: %d, tbl-id: %d, timeout: %s", + dbId, tblId, maxTimeToCheckTableUnSubscribeSucceed, + ) } func (c *PushClient) isNotSubscribing(ctx context.Context, dbId, tblId uint64) (bool, SubscribeState, error) { @@ -1349,8 +1370,11 @@ func (s *subscribedTable) setTableSubNotExist(dbId, tblId uint64) { SubState: SubRspTableNotExist, LatestTime: time.Now(), } - logutil.Errorf("%s received incorrect subscribe response, table[db: %d, tbl: %d] is not exist", - logTag, dbId, tblId) + logutil.Error( + "logtail.consumer.set.table.sub.not.exist", + zap.Uint64("db-id", dbId), + zap.Uint64("tbl-id", tblId), + ) } func (s *subscribedTable) clearTable(dbId, tblId uint64) { @@ -1367,7 +1391,11 @@ func (s *subscribedTable) setTableSubscribed(dbId, tblId uint64) { SubState: Subscribed, LatestTime: time.Now(), } - logutil.Infof("%s subscribe tbl[db: %d, tbl: %d] succeed", logTag, dbId, tblId) + logutil.Info( + "logtail.consumer.set.table.subscribed", + zap.Uint64("db-id", dbId), + zap.Uint64("tbl-id", tblId), + ) } func (s *subscribedTable) setTableSubRspReceived(dbId, tblId uint64) { @@ -1378,12 +1406,12 @@ func (s *subscribedTable) setTableSubRspReceived(dbId, tblId uint64) { SubState: SubRspReceived, LatestTime: time.Now(), } - logutil.Infof("%s %s subscribe tbl[db: %d, tbl: %d] resp received, %p", - s.eng.service, - logTag, - dbId, - tblId, - s, + logutil.Info( + "logtail.consumer.set.table.sub.rsp.received", + zap.String("service", s.eng.service), + zap.Uint64("db-id", dbId), + zap.Uint64("tbl-id", tblId), + zap.Any("subscribed-table", s), ) } @@ -1392,7 +1420,11 @@ func (s *subscribedTable) setTableUnsubscribe(dbId, tblId uint64) { defer s.mutex.Unlock() s.eng.cleanMemoryTableWithTable(dbId, tblId) delete(s.m, tblId) - logutil.Infof("%s unsubscribe tbl[db: %d, tbl: %d] succeed", logTag, dbId, tblId) + logutil.Info( + "logtail.consumer.set.table.unsubscribe", + zap.Uint64("db-id", dbId), + zap.Uint64("tbl-id", tblId), + ) } // syncLogTailTimestamp is a global log tail timestamp for a cn node. @@ -1648,7 +1680,10 @@ func waitServerReady(addr string) { if address.RemoteAddressAvail(network, addr, defaultDialServerTimeout) { return } - logutil.Warnf("%s logtail server %s is not ready yet", logTag, addr) + logutil.Warn( + "logtail.consumer.wait.server.ready", + zap.String("addr", addr), + ) case <-serverFatal.C: panic(fmt.Sprintf("could not connect to logtail server for %s", defaultServerTimeout)) @@ -1657,41 +1692,28 @@ func waitServerReady(addr string) { } func (e *Engine) getLogTailServiceAddr() string { - getFn := func() string { - tnServices := e.GetTNServices() - if len(tnServices) != 0 { - return tnServices[0].LogTailServiceAddress - } - return "" - } - - var addr string - logutil.Infof("%s try to get logtail service address", logTag) - addr = getFn() - if len(addr) > 0 { - logutil.Infof("%s got logtail service address: %s", - logTag, addr) - return addr - } - logutil.Warnf("%s cannot get logtail service address", logTag) - + start := time.Now() timeout := time.NewTimer(defaultGetLogTailAddrTimeoutDuration) defer timeout.Stop() ticker := time.NewTicker(time.Millisecond * 20) defer ticker.Stop() + for { + tnServices := e.GetTNServices() + if len(tnServices) > 0 && tnServices[0].LogTailServiceAddress != "" { + addr := tnServices[0].LogTailServiceAddress + logutil.Info("logtail.consumer.get.logtail.service.addr", + zap.String("addr", addr), + zap.Duration("cost", time.Since(start)), + ) + return addr + } + select { case <-timeout.C: panic(fmt.Sprintf("cannot get logtail service address, timeout %s", defaultGetLogTailAddrTimeoutDuration)) - case <-ticker.C: - addr = getFn() - logutil.Infof("%s got logtail service address: %s", - logTag, addr) - if len(addr) > 0 { - return addr - } } } } @@ -1705,13 +1727,19 @@ func (e *Engine) InitLogTailPushModel(ctx context.Context, timestampWaiter clien // try to init log tail client. if failed, retry. for { if err := ctx.Err(); err != nil { - logutil.Infof("%s mo context has done, init log tail client failed.", logTag) + logutil.Info( + "logtail.consumer.init.push.model.failed", + zap.Error(err), + ) return err } // get log tail service address. if err := e.pClient.init(logTailServerAddr, timestampWaiter, e); err != nil { - logutil.Errorf("%s client init failed, err is %s", logTag, err) + logutil.Error( + "logtail.consumer.init.push.model.client.failed", + zap.Error(err), + ) continue } break @@ -1747,8 +1775,12 @@ func dispatchSubscribeResponse( defer func() { tDuration := time.Since(startTime) if tDuration > time.Millisecond*5 { - logutil.Warnf("%s consume subscribe response for tbl[dbId: %d, tblID: %d] cost %s", - logTag, tbl.DbId, tbl.TbId, tDuration.String()) + logutil.Warn( + "logtail.consumer.slow.subscribe.response", + zap.Uint64("db-id", tbl.DbId), + zap.Uint64("tbl-id", tbl.TbId), + zap.Duration("cost", tDuration), + ) } }() @@ -1833,8 +1865,11 @@ func dispatchUnSubscribeResponse( tbl := response.Table notDistribute := ifShouldNotDistribute(tbl.DbId, tbl.TbId) if notDistribute { - logutil.Errorf("%s unexpected unsubscribe response for tbl[dbId: %d, tblID: %d]", - logTag, tbl.DbId, tbl.TbId) + logutil.Error( + "logtail.consumer.dispatch.unsubscribe.response.unexpected", + zap.Uint64("db-id", tbl.DbId), + zap.Uint64("tbl-id", tbl.TbId), + ) return nil } routineIndex := tbl.TbId % consumerNumber @@ -1862,7 +1897,11 @@ func (rc *routineController) sendSubscribeResponse( receiveAt time.Time) { if l := len(rc.signalChan); l > rc.warningBufferLen { rc.warningBufferLen = l - logutil.Infof("%s consume-routine %d signalChan len is %d, maybe consume is too slow", logTag, rc.routineId, l) + logutil.Info( + "logtail.consumer.slow.consume.routine", + zap.Int("routine-id", rc.routineId), + zap.Int("signal-chan-len", l), + ) } rc.signalChan <- &cmdToConsumeSub{log: r, receiveAt: receiveAt} @@ -1871,7 +1910,11 @@ func (rc *routineController) sendSubscribeResponse( func (rc *routineController) sendTableLogTail(r logtail.TableLogtail, receiveAt time.Time) { if l := len(rc.signalChan); l > rc.warningBufferLen { rc.warningBufferLen = l - logutil.Infof("%s consume-routine %d signalChan len is %d, maybe consume is too slow", logTag, rc.routineId, l) + logutil.Info( + "logtail.consumer.slow.send.table.log.tail", + zap.Int("routine-id", rc.routineId), + zap.Int("signal-chan-len", l), + ) } log := rc.cmdLogPool.Get().(*cmdToConsumeLog) @@ -1885,7 +1928,11 @@ func (rc *routineController) updateTimeFromT( receiveAt time.Time) { if l := len(rc.signalChan); l > rc.warningBufferLen { rc.warningBufferLen = l - logutil.Infof("%s consume-routine %d signalChan len is %d, maybe consume is too slow", logTag, rc.routineId, l) + logutil.Info( + "logtail.consumer.slow.update.time", + zap.Int("routine-id", rc.routineId), + zap.Int("signal-chan-len", l), + ) } updateTime := rc.cmdTimePool.Get().(*cmdToUpdateTime) @@ -1898,7 +1945,11 @@ func (rc *routineController) sendUnSubscribeResponse(r *logtail.UnSubscribeRespo // debug for issue #10138. if l := len(rc.signalChan); l > rc.warningBufferLen { rc.warningBufferLen = l - logutil.Infof("%s consume-routine %d signalChan len is %d, maybe consume is too slow", logTag, rc.routineId, l) + logutil.Info( + "logtail.consumer.slow.send.unsubscribe.response", + zap.Int("routine-id", rc.routineId), + zap.Int("signal-chan-len", l), + ) } rc.signalChan <- &cmdToConsumeUnSub{log: r, receiveAt: receiveAt} @@ -2114,7 +2165,12 @@ func updatePartitionOfPush( } if err != nil { - logutil.Errorf("%s consume %d-%s log tail error: %v\n", logTag, tblId, partition.TableInfo.Name, err) + logutil.Error( + "logtail.consumer.update.partition.of.push.error", + zap.Uint64("tbl-id", tblId), + zap.String("table-name", partition.TableInfo.Name), + zap.Error(err), + ) return err } diff --git a/pkg/vm/engine/disttae/logtail_consumer_test.go b/pkg/vm/engine/disttae/logtail_consumer_test.go index 2e545a5b55e1e..51acb011881e3 100644 --- a/pkg/vm/engine/disttae/logtail_consumer_test.go +++ b/pkg/vm/engine/disttae/logtail_consumer_test.go @@ -39,6 +39,7 @@ import ( "github.com/matrixorigin/matrixone/pkg/objectio" "github.com/matrixorigin/matrixone/pkg/pb/api" log "github.com/matrixorigin/matrixone/pkg/pb/logservice" + "github.com/matrixorigin/matrixone/pkg/pb/logtail" "github.com/matrixorigin/matrixone/pkg/pb/timestamp" "github.com/matrixorigin/matrixone/pkg/testutil" "github.com/matrixorigin/matrixone/pkg/txn/client" @@ -786,3 +787,234 @@ func TestPushClient_LoadAndConsumeLatestCkp(t *testing.T) { assert.NoError(t, err) assert.Equal(t, Unsubscribing, state) } + +// TestRoutineControllerSendMethods verifies that routine controller send methods work correctly +func TestRoutineControllerSendMethods(t *testing.T) { + t.Run("routineController initialization with pools", func(t *testing.T) { + rc := &routineController{ + routineId: 1, + closeChan: make(chan bool, 1), // Buffered channel to avoid blocking + signalChan: make(chan routineControlCmd, 5), + cmdLogPool: sync.Pool{ + New: func() any { + return &cmdToConsumeLog{} + }, + }, + cmdTimePool: sync.Pool{ + New: func() any { + return &cmdToUpdateTime{} + }, + }, + } + + // Verify that existing pools are properly initialized + assert.NotNil(t, rc.cmdLogPool.New) + assert.NotNil(t, rc.cmdTimePool.New) + + // Ensure cleanup to avoid goroutine leaks + defer func() { + select { + case rc.closeChan <- true: + default: + } + // Drain signalChan to prevent blocking + for len(rc.signalChan) > 0 { + <-rc.signalChan + } + }() + }) + + t.Run("sendSubscribeResponse creates commands correctly", func(t *testing.T) { + rc := &routineController{ + routineId: 1, + closeChan: make(chan bool, 1), // Buffered channel to avoid blocking + signalChan: make(chan routineControlCmd, 5), + } + + // Ensure cleanup + defer func() { + select { + case rc.closeChan <- true: + default: + } + // Drain signalChan to prevent blocking + for len(rc.signalChan) > 0 { + <-rc.signalChan + } + }() + + // Call sendSubscribeResponse multiple times + ctx := context.Background() + for i := 0; i < 3; i++ { + rc.sendSubscribeResponse(ctx, &logtail.SubscribeResponse{}, time.Now()) + } + + // Verify that commands were added to the channel + assert.Equal(t, 3, len(rc.signalChan)) + + // Drain the channel and verify the commands + for i := 0; i < 3; i++ { + cmd := <-rc.signalChan + assert.IsType(t, &cmdToConsumeSub{}, cmd) + } + }) + + t.Run("sendUnSubscribeResponse creates commands correctly", func(t *testing.T) { + rc := &routineController{ + routineId: 1, + closeChan: make(chan bool, 1), // Buffered channel to avoid blocking + signalChan: make(chan routineControlCmd, 5), + } + + // Ensure cleanup + defer func() { + select { + case rc.closeChan <- true: + default: + } + // Drain signalChan to prevent blocking + for len(rc.signalChan) > 0 { + <-rc.signalChan + } + }() + + // Call sendUnSubscribeResponse multiple times + for i := 0; i < 3; i++ { + rc.sendUnSubscribeResponse(&logtail.UnSubscribeResponse{}, time.Now()) + } + + // Verify that commands were added to the channel + assert.Equal(t, 3, len(rc.signalChan)) + + // Drain the channel and verify the commands + for i := 0; i < 3; i++ { + cmd := <-rc.signalChan + assert.IsType(t, &cmdToConsumeUnSub{}, cmd) + } + }) + + t.Run("sendTableLogTail creates commands correctly", func(t *testing.T) { + rc := &routineController{ + routineId: 1, + closeChan: make(chan bool, 1), // Buffered channel to avoid blocking + signalChan: make(chan routineControlCmd, 5), + cmdLogPool: sync.Pool{ + New: func() any { + return &cmdToConsumeLog{} + }, + }, + } + + // Ensure cleanup + defer func() { + select { + case rc.closeChan <- true: + default: + } + // Drain signalChan to prevent blocking + for len(rc.signalChan) > 0 { + <-rc.signalChan + } + }() + + // Call sendTableLogTail multiple times + for i := 0; i < 3; i++ { + rc.sendTableLogTail(logtail.TableLogtail{}, time.Now()) + } + + // Verify that commands were added to the channel + assert.Equal(t, 3, len(rc.signalChan)) + + // Drain the channel and verify the commands + for i := 0; i < 3; i++ { + cmd := <-rc.signalChan + assert.IsType(t, &cmdToConsumeLog{}, cmd) + } + }) + + t.Run("updateTimeFromT creates commands correctly", func(t *testing.T) { + rc := &routineController{ + routineId: 1, + closeChan: make(chan bool, 1), // Buffered channel to avoid blocking + signalChan: make(chan routineControlCmd, 5), + cmdTimePool: sync.Pool{ + New: func() any { + return &cmdToUpdateTime{} + }, + }, + } + + // Ensure cleanup + defer func() { + select { + case rc.closeChan <- true: + default: + } + // Drain signalChan to prevent blocking + for len(rc.signalChan) > 0 { + <-rc.signalChan + } + }() + + // Call updateTimeFromT multiple times + for i := 0; i < 3; i++ { + rc.updateTimeFromT(timestamp.Timestamp{ + PhysicalTime: 123456, + LogicalTime: 1, + NodeID: 1, + }, time.Now()) + } + + // Verify that commands were added to the channel + assert.Equal(t, 3, len(rc.signalChan)) + + // Drain the channel and verify the commands + for i := 0; i < 3; i++ { + cmd := <-rc.signalChan + assert.IsType(t, &cmdToUpdateTime{}, cmd) + } + }) +} + +// TestCommandActions verifies that command actions can be created and their basic functionality works +func TestCommandActions(t *testing.T) { + t.Run("cmdToConsumeSub creation and basic properties", func(t *testing.T) { + // Test that we can create a cmdToConsumeSub command + log := &logtail.SubscribeResponse{ + Logtail: logtail.TableLogtail{ + // Set some basic properties for TableLogtail if needed + }, + } + receiveAt := time.Now() + + cmd := &cmdToConsumeSub{ + log: log, + receiveAt: receiveAt, + } + + // Verify the command has the correct properties + assert.Equal(t, log, cmd.log) + assert.Equal(t, receiveAt, cmd.receiveAt) + }) + + t.Run("cmdToConsumeUnSub creation and basic properties", func(t *testing.T) { + // Test that we can create a cmdToConsumeUnSub command + log := &logtail.UnSubscribeResponse{ + Table: &api.TableID{ + DbId: 1, + TbId: 2, + }, + } + receiveAt := time.Now() + + cmd := &cmdToConsumeUnSub{ + log: log, + receiveAt: receiveAt, + } + + // Verify the command has the correct properties + assert.Equal(t, log, cmd.log) + assert.Equal(t, receiveAt, cmd.receiveAt) + }) + +} diff --git a/pkg/vm/engine/disttae/logtailreplay/blocks_iter.go b/pkg/vm/engine/disttae/logtailreplay/blocks_iter.go index c2389e45eb924..52090bb215bd8 100644 --- a/pkg/vm/engine/disttae/logtailreplay/blocks_iter.go +++ b/pkg/vm/engine/disttae/logtailreplay/blocks_iter.go @@ -16,10 +16,9 @@ package logtailreplay import ( "bytes" - "fmt" + "github.com/matrixorigin/matrixone/pkg/common/moerr" "github.com/matrixorigin/matrixone/pkg/container/types" - "github.com/matrixorigin/matrixone/pkg/logutil" "github.com/matrixorigin/matrixone/pkg/objectio" "github.com/tidwall/btree" ) @@ -125,10 +124,10 @@ func (p *PartitionState) NewObjectsIter( visitTombstone bool, ) (objectio.ObjectIter, error) { if !p.IsEmpty() && snapshot.LT(&p.start) { - logutil.Infof("NewObjectsIter: tid:%v, ps:%p, snapshot ts:%s, minTS:%s", - p.tid, p, snapshot.ToString(), p.start.ToString()) - msg := fmt.Sprintf("(%s<%s)", snapshot.ToString(), p.start.ToString()) - return nil, moerr.NewTxnStaleNoCtx(msg) + return nil, moerr.NewTxnStaleNoCtxf( + "(%s<%s)", + snapshot.ToString(), p.start.ToString(), + ) } if visitTombstone { diff --git a/pkg/vm/engine/disttae/logtailreplay/blocks_iter_test.go b/pkg/vm/engine/disttae/logtailreplay/blocks_iter_test.go index ba9688579bae6..67ed7945c0944 100644 --- a/pkg/vm/engine/disttae/logtailreplay/blocks_iter_test.go +++ b/pkg/vm/engine/disttae/logtailreplay/blocks_iter_test.go @@ -237,3 +237,10 @@ func TestPartitionState_CollectObjectsBetweenInProgress(t *testing.T) { } } } + +func TestPartitionState_NewBlocksIter(t *testing.T) { + pState := NewPartitionState("", false, 0x3fff, false) + pState.start = types.BuildTS(100, 0) + _, err := pState.NewObjectsIter(types.BuildTS(99, 0), false, true) + require.Error(t, err) +} diff --git a/pkg/vm/engine/disttae/logtailreplay/partition.go b/pkg/vm/engine/disttae/logtailreplay/partition.go index e0fc2219e0083..b24e9a8577645 100644 --- a/pkg/vm/engine/disttae/logtailreplay/partition.go +++ b/pkg/vm/engine/disttae/logtailreplay/partition.go @@ -228,7 +228,7 @@ func (p *Partition) Truncate(ctx context.Context, ids [2]uint64, ts types.TS) er } logutil.Info( - "PS-Truncate", + "partition.state.truncate", zap.String("name", p.TableInfo.Name), zap.Uint64("id", p.TableInfo.ID), zap.String("prev-state", fmt.Sprintf("%p", curState)), diff --git a/pkg/vm/engine/disttae/logtailreplay/partition_state.go b/pkg/vm/engine/disttae/logtailreplay/partition_state.go index d6763d1d941e2..9f6a4e88540ca 100644 --- a/pkg/vm/engine/disttae/logtailreplay/partition_state.go +++ b/pkg/vm/engine/disttae/logtailreplay/partition_state.go @@ -937,7 +937,7 @@ func NewPartitionState( prefetch: prefetch, } logutil.Info( - "PS-CREATED", + "partition.state.created", zap.Uint64("table-id", tid), zap.String("service", service), zap.String("addr", fmt.Sprintf("%p", ps)), @@ -969,7 +969,7 @@ func (p *PartitionState) truncateTombstoneObjects( if gcLog.Len() > 0 { logutil.Info( - "PS-GC-TombstoneIndex", + "partition.state.gc.tombstone.index", zap.String("db.tbl", fmt.Sprintf("%d.%d", dbId, tblId)), zap.String("ts", ts.ToString()), zap.String("files", gcLog.String())) @@ -1030,7 +1030,7 @@ func (p *PartitionState) truncate(ids [2]uint64, ts types.TS) (updated bool) { } if gced { logutil.Info( - "PS-GC-DataObject", + "partition.state.gc.data.object", zap.String("ts", ts.ToString()), zap.String("db.tbl", fmt.Sprintf("%d.%d", ids[0], ids[1])), zap.String("files", objectsToDelete), @@ -1068,7 +1068,7 @@ func (p *PartitionState) truncate(ids [2]uint64, ts types.TS) (updated bool) { objsToDelete := objectsToDeleteBuilder.String() if objGced { logutil.Info( - "PS-GC-NameIndex", + "partition.state.gc.name.index", zap.String("ts", ts.ToString()), zap.String("db.tbl", fmt.Sprintf("%d.%d", ids[0], ids[1])), zap.String("files", objsToDelete), diff --git a/pkg/vm/engine/disttae/mo_table_stats.go b/pkg/vm/engine/disttae/mo_table_stats.go index 34e6b3f932cad..09c053c37c64e 100644 --- a/pkg/vm/engine/disttae/mo_table_stats.go +++ b/pkg/vm/engine/disttae/mo_table_stats.go @@ -271,7 +271,7 @@ const ( defaultGamaCycleDur = time.Minute defaultGetTableListLimit = options.DefaultBlockMaxRows - logHeader = "MO-TABLE-STATS-TASK" + logHeader = "mo.table.stats.task" ) const ( @@ -333,8 +333,9 @@ func initMoTableStatsConfig( defer func() { eng.dynamicCtx.defaultConf = eng.dynamicCtx.conf if err != nil { - logutil.Error(logHeader, - zap.String("source", "init mo table stats config"), + logutil.Error( + logHeader, + zap.String("action", "init.config"), zap.Error(err)) } }() @@ -417,8 +418,9 @@ func initMoTableStatsConfig( runtime.NumCPU(), ants.WithNonblocking(false), ants.WithPanicHandler(func(e interface{}) { - logutil.Error(logHeader, - zap.String("source", "gama task panic"), + logutil.Error( + logHeader, + zap.String("action", "beta.panic.handler"), zap.Any("error", e)) })); err != nil { return @@ -428,8 +430,9 @@ func initMoTableStatsConfig( runtime.NumCPU(), ants.WithNonblocking(false), ants.WithPanicHandler(func(e interface{}) { - logutil.Error(logHeader, - zap.String("source", "gama task panic"), + logutil.Error( + logHeader, + zap.String("action", "gama.panic.handler"), zap.Any("error", e)) })); err != nil { return @@ -444,9 +447,11 @@ func initMoTableStatsConfig( task.launchTimes++ task.running = true - logutil.Info(logHeader, - zap.String("source", fmt.Sprintf("launch %s", hint)), - zap.Int("times", task.launchTimes)) + logutil.Info( + logHeader, + zap.String("action", fmt.Sprintf("launch.%s", hint)), + zap.Int("times", task.launchTimes), + ) go func() { defer func() { @@ -483,9 +488,10 @@ func initMoTableStatsConfig( ) defer func() { - logutil.Info(logHeader, - zap.String("source", "wait the mo service started"), - zap.Duration("duration", moServerStarted.Sub(start)), + logutil.Info( + logHeader, + zap.String("action", "wait.mo.service.started"), + zap.Duration("takes", moServerStarted.Sub(start)), ) }() @@ -539,9 +545,11 @@ func (d *dynamicCtx) initCronTask( insertTask := func() { sql, err = predefine.GenInitCronTaskSQL(int32(task.TaskCode_MOTableStats)) if err != nil { - logutil.Error(logHeader, - zap.String("source", "init cron task"), - zap.Error(err)) + logutil.Error( + logHeader, + zap.String("action", "init.cron.task"), + zap.Error(err), + ) } d.executeSQL(ctx, sql, "init cron task") @@ -565,7 +573,10 @@ func (d *dynamicCtx) initCronTask( } if checkTask() { - logutil.Info(logHeader, zap.String("source", "init cron task succeed")) + logutil.Info( + logHeader, + zap.String("action", "init.cron.task.succeed"), + ) return true } @@ -821,9 +832,11 @@ func (d *dynamicCtx) checkMoveOnTask() bool { disable := d.conf.DisableStatsTask - logutil.Info(logHeader, - zap.String("source", "check move on"), - zap.Bool("disable", disable)) + logutil.Info( + logHeader, + zap.String("action", "check.move.on"), + zap.Bool("state", disable), + ) return disable } @@ -868,9 +881,11 @@ func (d *dynamicCtx) setMoveOnTask(newVal bool) string { d.conf.DisableStatsTask = !newVal ret := fmt.Sprintf("move on: %v to %v", oldState, newVal) - logutil.Info(logHeader, - zap.String("source", "set move on"), - zap.String("state", ret)) + logutil.Info( + logHeader, + zap.String("action", "set.move.on"), + zap.String("state", ret), + ) return ret } @@ -884,9 +899,11 @@ func (d *dynamicCtx) setUseOldImpl(newVal bool) string { d.conf.StatsUsingOldImpl = newVal ret := fmt.Sprintf("use old impl: %v to %v", oldState, newVal) - logutil.Info(logHeader, - zap.String("source", "set use old impl"), - zap.String("state", ret)) + logutil.Info( + logHeader, + zap.String("action", "set.use.old.impl"), + zap.String("state", ret), + ) return ret } @@ -900,9 +917,11 @@ func (d *dynamicCtx) setForceUpdate(newVal bool) string { d.conf.ForceUpdate = newVal ret := fmt.Sprintf("force update: %v to %v", oldState, newVal) - logutil.Info(logHeader, - zap.String("source", "set force update"), - zap.String("state", ret)) + logutil.Info( + logHeader, + zap.String("action", "set.force.update"), + zap.String("state", ret), + ) return ret } @@ -1036,7 +1055,7 @@ func (d *dynamicCtx) executeSQL(ctx context.Context, sql string, hint string) ie ret := exec.(ie.InternalExecutor).Query(newCtx, sql, d.sqlOpts) if ret.Error() != nil { logutil.Info(logHeader, - zap.String("source", hint), + zap.String("action", hint), zap.Error(ret.Error()), zap.String("sql", sql)) } @@ -1268,12 +1287,13 @@ func (d *dynamicCtx) QueryTableStatsByAccounts( ctx, sql, "query table stats by account", wantedStatsIdxes, forceUpdate, resetUpdateTime) - logutil.Info(logHeader, - zap.String("source", "QueryTableStatsByAccounts"), - zap.Int("acc cnt", len(accs)), - zap.Int("tbl cnt", len(tbls)), - zap.Bool("forceUpdate", forceUpdate), - zap.Bool("resetUpdateTime", resetUpdateTime), + logutil.Info( + logHeader, + zap.String("action", "query.table.stats.by.accounts"), + zap.Int("account-count", len(accs)), + zap.Int("table-count", len(tbls)), + zap.Bool("force-update", forceUpdate), + zap.Bool("reset-update-time", resetUpdateTime), zap.Duration("takes", time.Since(now)), zap.Bool("ok", ok), zap.Error(err)) @@ -1304,15 +1324,17 @@ func (d *dynamicCtx) QueryTableStatsByDatabase( statsVals, _, retDb, tbls, ok, err = d.queryTableStatsByXXX( ctx, sql, "query table stats by database", wantedStatsIdxes, forceUpdate, resetUpdateTime) - logutil.Info(logHeader, - zap.String("source", "QueryTableStatsByDatabase"), - zap.Int("db cnt", len(dbIds)), - zap.Int("tbl cnt", len(tbls)), - zap.Bool("forceUpdate", forceUpdate), - zap.Bool("resetUpdateTime", resetUpdateTime), + logutil.Info( + logHeader, + zap.String("action", "query.table.stats.by.database"), + zap.Int("database-count", len(dbIds)), + zap.Int("table-count", len(tbls)), + zap.Bool("force-update", forceUpdate), + zap.Bool("reset-update-time", resetUpdateTime), zap.Duration("takes", time.Since(now)), zap.Bool("ok", ok), - zap.Error(err)) + zap.Error(err), + ) return statsVals, retDb, ok, err } @@ -1338,14 +1360,16 @@ func (d *dynamicCtx) QueryTableStatsByTable( statsVals, _, _, retTbls, ok, err = d.queryTableStatsByXXX( ctx, sql, "query table stats by table", wantedStatsIdxes, forceUpdate, resetUpdateTime) - logutil.Info(logHeader, - zap.String("source", "QueryTableStatsByTable"), - zap.Int("tbl cnt", len(tblIds)), - zap.Bool("forceUpdate", forceUpdate), - zap.Bool("resetUpdateTime", resetUpdateTime), + logutil.Info( + logHeader, + zap.String("action", "query.table.stats.by.table"), + zap.Int("table-count", len(tblIds)), + zap.Bool("force-update", forceUpdate), + zap.Bool("reset-update-time", resetUpdateTime), zap.Duration("takes", time.Since(now)), zap.Bool("ok", ok), - zap.Error(err)) + zap.Error(err), + ) return statsVals, retTbls, ok, err } @@ -1654,7 +1678,7 @@ func (d *dynamicCtx) tableStatsExecutor( if !d.moStatsCronTaskInit.Load() { logutil.Info(logHeader, - zap.String("source", "table stats executor"), + zap.String("action", "table.stats.executor"), zap.String("state", "waiting mo stats cron task init")) continue } @@ -2703,11 +2727,12 @@ func (d *dynamicCtx) updateSpecialStatsStart( start := stats[specialStart].(string) old := oldStart.ToTimestamp().ToStdTime().Format("2006-01-02 15:04:05.000000") if old != start { - logutil.Info(logHeader, - zap.String("source", "update special stats start"), - zap.String("given up update", "the start changed already"), - zap.String("current", start), - zap.String("last read", old)) + logutil.Info( + logHeader, + zap.String("action", "update.special.stats.start"), + zap.String("start", start), + zap.String("last", old), + ) return false, nil } diff --git a/pkg/vm/engine/disttae/txn_table.go b/pkg/vm/engine/disttae/txn_table.go index 10fd4367aba25..ec745f20d6f84 100644 --- a/pkg/vm/engine/disttae/txn_table.go +++ b/pkg/vm/engine/disttae/txn_table.go @@ -1853,7 +1853,7 @@ func extractPStateFromRelData( logutil.Warn("RELDATA-WITH-EMPTY-PSTATE", zap.String("db", tbl.db.databaseName), zap.String("table", tbl.tableName), - zap.String("sql", sql), + zap.String("sql", commonUtil.Abbreviate(sql, 500)), zap.String("relDataType", fmt.Sprintf("%T", relData)), zap.String("relDataContent", relData.String()), zap.String("stack", string(debug.Stack()))) @@ -2015,15 +2015,14 @@ func (tbl *txnTable) BuildShardingReaders( func (tbl *txnTable) getPartitionState( ctx context.Context, ) (ps *logtailreplay.PartitionState, err error) { - - defer func() { - if tbl.tableId == catalog.MO_COLUMNS_ID { - logutil.Info("open partition state for mo_columns", - zap.String("txn", tbl.db.op.Txn().DebugString()), - zap.String("desc", ps.Desc(true)), - zap.String("pointer", fmt.Sprintf("%p", ps))) - } - }() + // defer func() { + // if tbl.tableId == catalog.MO_COLUMNS_ID { + // logutil.Info("open partition state for mo_columns", + // zap.String("txn", tbl.db.op.Txn().DebugString()), + // zap.String("desc", ps.Desc(true)), + // zap.String("pointer", fmt.Sprintf("%p", ps))) + // } + // }() var ( eng = tbl.eng.(*Engine) @@ -2109,10 +2108,10 @@ func (tbl *txnTable) getPartitionState( start, end = types.MaxTs(), types.MinTs() if ps != nil { start, end = ps.GetDuration() - msg = "Txn-Table-GetSSPS-Succeed" + msg = "table.get.snapshot.state.succeed" } else { logger = logutil.Error - msg = "Txn-Table-GetSSPS-Failed" + msg = "table.get.snapshot.state.failed" } logger( diff --git a/pkg/vm/engine/disttae/util.go b/pkg/vm/engine/disttae/util.go index e8eba37efa01f..3f2747fc341a7 100644 --- a/pkg/vm/engine/disttae/util.go +++ b/pkg/vm/engine/disttae/util.go @@ -655,7 +655,12 @@ func stringifyMap(req any, f func(any, any) string) string { return buf.String() } -func execReadSql(ctx context.Context, op client.TxnOperator, sql string, disableLog bool) (executor.Result, error) { +func execReadSql( + ctx context.Context, + op client.TxnOperator, + sql string, + disableLog bool, +) (executor.Result, error) { // copy from compile.go runSqlWithResult service := op.GetWorkspace().(*Transaction).proc.GetService() v, ok := moruntime.ServiceRuntime(service).GetGlobalVariables(moruntime.InternalSQLExecutor) diff --git a/pkg/vm/engine/tae/txn/txnimpl/table_space.go b/pkg/vm/engine/tae/txn/txnimpl/table_space.go index e0c337213f2f5..a3762d05cade6 100644 --- a/pkg/vm/engine/tae/txn/txnimpl/table_space.go +++ b/pkg/vm/engine/tae/txn/txnimpl/table_space.go @@ -169,12 +169,12 @@ func (space *tableSpace) prepareApplyANode(node *anode, startOffset uint32) erro for appended < node.Rows() { appender, err := space.tableHandle.GetAppender() if moerr.IsMoErrCode(err, moerr.ErrAppendableObjectNotFound) { - objH, err := space.table.CreateObject(space.isTombstone) - if err != nil { - return err + objH, err2 := space.table.CreateObject(space.isTombstone) + if err2 != nil { + return err2 } appender = space.tableHandle.SetAppender(objH.Fingerprint()) - logutil.Info("CreateObject", zap.String("objH", appender.GetID().ObjectString()), zap.String("txn", node.GetTxn().String())) + // logutil.Info("CreateObject", zap.String("objH", appender.GetID().ObjectString()), zap.String("txn", node.GetTxn().String())) objH.Close() } if !appender.IsSameColumns(space.table.GetLocalSchema(space.isTombstone)) {