Skip to content

Commit a12c319

Browse files
XuPeng-SHXuPeng-SH
authored
update fatal print with more context (#21607)
### **User description** ## What type of PR is this? - [ ] API-change - [ ] BUG - [ ] Improvement - [ ] Documentation - [ ] Feature - [ ] Test and CI - [x] Code Refactoring ## Which issue(s) this PR fixes: issue #21602 ## What this PR does / why we need it: update fatal print with more context ___ ### **PR Type** Enhancement, Bug fix ___ ### **Description** - Refactored logging to provide more context and consistency: - Replaced `logutil.Infof` with `logutil.Debugf` or `logutil.Info` for better log level usage. - Enhanced error and debug logs with additional context using `zap` fields. - Updated fatal logs to include transaction IDs for debugging. - Removed unused or commented-out code to improve codebase maintainability. - Improved function signatures to include additional parameters for better traceability. - Enhanced garbage collection and snapshot-related logging for better traceability. ___ ### **Changes walkthrough** 📝 <table><thead><tr><th></th><th align="left">Relevant files</th></tr></thead><tbody><tr><td><strong>Enhancement</strong></td><td><details><summary>8 files</summary><table> <tr> <td><strong>stats.go</strong><dd><code>Updated logging levels and added context to debug logs</code>&nbsp; &nbsp; &nbsp; </dd></td> <td><a href="https://github.com/matrixorigin/matrixone/pull/21607/files#diff-d0f8ce84135a062e5992dcb3d1175993ee396beae48de126969255cd9240d02b">+1/-1</a>&nbsp; &nbsp; &nbsp; </td> </tr> <tr> <td><strong>txn_table.go</strong><dd><code>Enhanced logging with error handling and removed unused code</code></dd></td> <td><a href="https://github.com/matrixorigin/matrixone/pull/21607/files#diff-ec8d7fbb6765aa12484ff5529b88835dc1da369005256b065fb3db4972f2d32f">+19/-79</a>&nbsp; </td> </tr> <tr> <td><strong>types.go</strong><dd><code>Added transaction ID context to fatal logs</code>&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; </dd></td> <td><a href="https://github.com/matrixorigin/matrixone/pull/21607/files#diff-2d4ca99c63be4d7a3464a5089669767530c849522edfe3030145a5b059775852">+4/-4</a>&nbsp; &nbsp; &nbsp; </td> </tr> <tr> <td><strong>catalog.go</strong><dd><code>Updated function to include reason parameter in logging</code>&nbsp; &nbsp; </dd></td> <td><a href="https://github.com/matrixorigin/matrixone/pull/21607/files#diff-c942af281aef8741f696ca2ae2ccc57aa59dee5520fdfb7a0f4c67a4e70f939c">+1/-1</a>&nbsp; &nbsp; &nbsp; </td> </tr> <tr> <td><strong>database.go</strong><dd><code>Enhanced logging with reason parameter for table removal</code>&nbsp; </dd></td> <td><a href="https://github.com/matrixorigin/matrixone/pull/21607/files#diff-c54ecf2f56733033a88c6ae533ad878909366fd7d5166d12149e23fdec8e5116">+7/-3</a>&nbsp; &nbsp; &nbsp; </td> </tr> <tr> <td><strong>table.go</strong><dd><code>Updated rollback logging to include reason for removal</code>&nbsp; &nbsp; &nbsp; </dd></td> <td><a href="https://github.com/matrixorigin/matrixone/pull/21607/files#diff-e8150a24b9afd22197ca003bbc47e435ee0357a8b96474a0a118a8e8222c7dd7">+1/-1</a>&nbsp; &nbsp; &nbsp; </td> </tr> <tr> <td><strong>snapshot.go</strong><dd><code>Improved snapshot and garbage collection logging</code>&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; </dd></td> <td><a href="https://github.com/matrixorigin/matrixone/pull/21607/files#diff-111781ff442a07a8deefe4a9fa1e799b2b5da03309f03c042a9b9b83e33a21be">+40/-19</a>&nbsp; </td> </tr> <tr> <td><strong>table_space.go</strong><dd><code>Enhanced logging for object creation in table space</code>&nbsp; &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; </dd></td> <td><a href="https://github.com/matrixorigin/matrixone/pull/21607/files#diff-eb2583ca6c5dea86857b6c9ba7eff911e281c04e71c85d0dfa46eec9f80f3178">+5/-1</a>&nbsp; &nbsp; &nbsp; </td> </tr> </table></details></td></tr></tr></tbody></table> ___ > <details> <summary> Need help?</summary><li>Type <code>/help how to ...</code> in the comments thread for any questions about Qodo Merge usage.</li><li>Check out the <a href="https://qodo-merge-docs.qodo.ai/usage-guide/">documentation</a> for more information.</li></details>
1 parent 8383dc6 commit a12c319

File tree

11 files changed

+162
-166
lines changed

11 files changed

+162
-166
lines changed

‎pkg/vm/engine/disttae/engine.go‎

Lines changed: 21 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -441,7 +441,13 @@ func loadNameByIdFromStorage(ctx context.Context, op client.TxnOperator, account
441441
return
442442
}
443443

444-
func (e *Engine) GetRelationById(ctx context.Context, op client.TxnOperator, tableId uint64) (dbName, tableName string, rel engine.Relation, err error) {
444+
func (e *Engine) GetRelationById(
445+
ctx context.Context,
446+
op client.TxnOperator,
447+
tableId uint64,
448+
) (
449+
dbName, tableName string, rel engine.Relation, err error,
450+
) {
445451
if catalog.IsSystemTable(tableId) {
446452
dbName = catalog.MO_CATALOG
447453
db := &txnDatabase{
@@ -524,8 +530,7 @@ func (e *Engine) Delete(ctx context.Context, name string, op client.TxnOperator)
524530
}
525531

526532
var txn *Transaction
527-
txn, err = txnIsValid(op)
528-
if err != nil {
533+
if txn, err = txnIsValid(op); err != nil {
529534
return err
530535
}
531536

@@ -624,10 +629,12 @@ func (e *Engine) New(ctx context.Context, op client.TxnOperator) error {
624629
func (e *Engine) Nodes(
625630
isInternal bool, tenant string, username string, cnLabel map[string]string,
626631
) (engine.Nodes, error) {
627-
var ncpu = system.GoMaxProcs()
628-
var nodes engine.Nodes
632+
var (
633+
nodes engine.Nodes
634+
ncpu = system.GoMaxProcs()
635+
start = time.Now()
636+
)
629637

630-
start := time.Now()
631638
defer func() {
632639
v2.TxnStatementNodesHistogram.Observe(time.Since(start).Seconds())
633640
}()
@@ -700,11 +707,14 @@ func (e *Engine) BuildBlockReaders(
700707
expr *plan.Expr,
701708
def *plan.TableDef,
702709
relData engine.RelData,
703-
num int) ([]engine.Reader, error) {
704-
var rds []engine.Reader
705-
proc := p.(*process.Process)
706-
blkCnt := relData.DataCnt()
707-
newNum := num
710+
num int,
711+
) ([]engine.Reader, error) {
712+
var (
713+
rds []engine.Reader
714+
proc = p.(*process.Process)
715+
blkCnt = relData.DataCnt()
716+
newNum = num
717+
)
708718
if blkCnt < num {
709719
newNum = blkCnt
710720
for i := 0; i < num-blkCnt; i++ {

‎pkg/vm/engine/disttae/stats.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -945,7 +945,7 @@ func UpdateStats(ctx context.Context, req *updateStatsRequest, executor Concurre
945945
if req.statsInfo.MaxValMap[colName] < req.statsInfo.MinValMap[colName] {
946946
logutil.Errorf("error happended in stats!")
947947
}
948-
logutil.Infof("debug: table %v tablecnt %v col %v max %v min %v ndv %v overlap %v maxndv %v maxobj %v ndvinmaxobj %v minobj %v ndvinminobj %v",
948+
logutil.Debugf("debug: table %v tablecnt %v col %v max %v min %v ndv %v overlap %v maxndv %v maxobj %v ndvinmaxobj %v minobj %v ndvinminobj %v",
949949
baseTableDef.Name, info.TableCnt, colName, req.statsInfo.MaxValMap[colName], req.statsInfo.MinValMap[colName],
950950
req.statsInfo.NdvMap[colName], overlap, info.MaxNDVs[i], info.MaxOBJSize, info.NDVinMaxOBJ[i], info.MinOBJSize, info.NDVinMinOBJ[i])
951951
}

‎pkg/vm/engine/disttae/txn_database.go‎

Lines changed: 40 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -192,28 +192,37 @@ func (db *txnDatabase) Delete(ctx context.Context, name string) error {
192192
// 2. useAlterNote means that the batch sent to TN will be just used
193193
// to insert into or delete from mo_tables and mo_columns,
194194
// rather than trigger an actual create or delete operation for table.
195-
func (db *txnDatabase) deleteTable(ctx context.Context, name string, forAlter bool, useAlterNote bool) ([]engine.TableDef, error) {
196-
var id uint64
197-
var rowid types.Rowid
198-
var rowids []types.Rowid
199-
var colPKs [][]byte
200-
var defs []engine.TableDef
201-
var packer *types.Packer
195+
func (db *txnDatabase) deleteTable(
196+
ctx context.Context,
197+
name string,
198+
forAlter bool,
199+
useAlterNote bool,
200+
) (defs []engine.TableDef, err error) {
201+
var (
202+
id uint64
203+
accountId uint32
204+
rowid types.Rowid
205+
rowids []types.Rowid
206+
colPKs [][]byte
207+
packer *types.Packer
208+
)
202209
if db.op.IsSnapOp() {
203210
return nil, moerr.NewInternalErrorNoCtx("delete table in snapshot transaction")
204211
}
205212

206-
accountId, err := defines.GetAccountId(ctx)
207-
if err != nil {
213+
if accountId, err = defines.GetAccountId(ctx); err != nil {
208214
return nil, err
209215
}
210-
txn := db.getTxn()
211-
putter := txn.engine.packerPool.Get(&packer)
216+
217+
var (
218+
rel engine.Relation
219+
txn = db.getTxn()
220+
putter = txn.engine.packerPool.Get(&packer)
221+
)
212222
defer putter.Put()
213223

214224
// 1. Get id and columns infortmation to prepate delete batch
215-
rel, err := db.Relation(ctx, name, nil)
216-
if err != nil {
225+
if rel, err = db.Relation(ctx, name, nil); err != nil {
217226
return nil, err
218227
}
219228

@@ -266,8 +275,12 @@ func (db *txnDatabase) deleteTable(ctx context.Context, name string, forAlter bo
266275
rowid = vector.GetFixedAtNoTypeCheck[types.Rowid](res.Batches[0].Vecs[0], 0)
267276

268277
// 1.2 table column rowids
269-
res, err = execReadSql(ctx, db.op, fmt.Sprintf(catalog.MoColumnsRowidsQueryFormat, accountId, db.databaseName, name, id), true)
270-
if err != nil {
278+
if res, err = execReadSql(
279+
ctx,
280+
db.op,
281+
fmt.Sprintf(catalog.MoColumnsRowidsQueryFormat, accountId, db.databaseName, name, id),
282+
true,
283+
); err != nil {
271284
return nil, err
272285
}
273286
for _, b := range res.Batches {
@@ -369,7 +382,11 @@ func (db *txnDatabase) Truncate(ctx context.Context, name string) (uint64, error
369382
return newId, nil
370383
}
371384

372-
func (db *txnDatabase) Create(ctx context.Context, name string, defs []engine.TableDef) error {
385+
func (db *txnDatabase) Create(
386+
ctx context.Context,
387+
name string,
388+
defs []engine.TableDef,
389+
) (err error) {
373390
if db.op.IsSnapOp() {
374391
return moerr.NewInternalErrorNoCtx("create table in snapshot transaction")
375392
}
@@ -384,8 +401,11 @@ func (db *txnDatabase) Create(ctx context.Context, name string, defs []engine.Ta
384401

385402
func (db *txnDatabase) createWithID(
386403
ctx context.Context,
387-
name string, tableId uint64, defs []engine.TableDef, useAlterNote bool,
388-
) error {
404+
name string,
405+
tableId uint64,
406+
defs []engine.TableDef,
407+
useAlterNote bool,
408+
) (err error) {
389409
if db.op.IsSnapOp() {
390410
return moerr.NewInternalErrorNoCtx("create table in snapshot transaction")
391411
}
@@ -556,8 +576,7 @@ func (db *txnDatabase) loadTableFromStorage(
556576
{
557577
tblSql := fmt.Sprintf(catalog.MoTablesAllQueryFormat, accountID, db.databaseName, name)
558578
var res executor.Result
559-
res, err = execReadSql(ctx, db.op, tblSql, true)
560-
if err != nil {
579+
if res, err = execReadSql(ctx, db.op, tblSql, true); err != nil {
561580
return
562581
}
563582
defer res.Close()
@@ -583,8 +602,7 @@ func (db *txnDatabase) loadTableFromStorage(
583602
// fresh columns
584603
colSql := fmt.Sprintf(catalog.MoColumnsAllQueryFormat, accountID, db.databaseName, name, tblid)
585604
var res executor.Result
586-
res, err = execReadSql(ctx, db.op, colSql, true)
587-
if err != nil {
605+
if res, err = execReadSql(ctx, db.op, colSql, true); err != nil {
588606
return
589607
}
590608
defer res.Close()

‎pkg/vm/engine/disttae/txn_table.go‎

Lines changed: 34 additions & 94 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ package disttae
1717
import (
1818
"bytes"
1919
"context"
20+
"encoding/hex"
2021
"fmt"
2122
"runtime/debug"
2223
"strconv"
@@ -156,9 +157,8 @@ func (tbl *txnTable) PrefetchAllMeta(ctx context.Context) bool {
156157
return true
157158
}
158159

159-
func (tbl *txnTable) Stats(ctx context.Context, sync bool) (*pb.StatsInfo, error) {
160-
_, err := tbl.getPartitionState(ctx)
161-
if err != nil {
160+
func (tbl *txnTable) Stats(ctx context.Context, sync bool) (info *pb.StatsInfo, err error) {
161+
if _, err = tbl.getPartitionState(ctx); err != nil {
162162
logutil.Errorf("failed to get partition state of table %d: %v", tbl.tableId, err)
163163
return nil, err
164164
}
@@ -169,11 +169,7 @@ func (tbl *txnTable) Stats(ctx context.Context, sync bool) (*pb.StatsInfo, error
169169
TableID: tbl.tableId,
170170
}, sync), nil
171171
}
172-
info, err := tbl.stats(ctx)
173-
if err != nil {
174-
return nil, err
175-
}
176-
return info, nil
172+
return tbl.stats(ctx)
177173
}
178174

179175
func (tbl *txnTable) stats(ctx context.Context) (*pb.StatsInfo, error) {
@@ -305,8 +301,8 @@ func ForeachVisibleDataObject(
305301
fn func(obj objectio.ObjectEntry) error,
306302
executor ConcurrentExecutor,
307303
) (err error) {
308-
iter, err := state.NewObjectsIter(ts, true, false)
309-
if err != nil {
304+
var iter objectio.ObjectIter
305+
if iter, err = state.NewObjectsIter(ts, true, false); err != nil {
310306
return err
311307
}
312308
defer iter.Close()
@@ -742,7 +738,11 @@ func (tbl *txnTable) doRanges(ctx context.Context, rangesParam engine.RangesPara
742738
err != nil ||
743739
tbl.enableLogFilterExpr.Load() ||
744740
cost > 5*time.Second {
745-
logutil.Info(
741+
logger := logutil.Info
742+
if err != nil {
743+
logger = logutil.Error
744+
}
745+
logger(
746746
"TXN-FILTER-RANGE-LOG",
747747
zap.String("name", tbl.tableDef.Name),
748748
zap.String("exprs", plan2.FormatExprs(rangesParam.BlockFilters)),
@@ -773,9 +773,6 @@ func (tbl *txnTable) doRanges(ctx context.Context, rangesParam engine.RangesPara
773773
err)
774774

775775
v2.TxnTableRangeDurationHistogram.Observe(cost.Seconds())
776-
if err != nil {
777-
logutil.Errorf("txn: %s, error: %v", tbl.db.op.Txn().DebugString(), err)
778-
}
779776
}()
780777

781778
if rangesParam.Policy&engine.Policy_CollectUncommittedPersistedData != 0 {
@@ -1009,10 +1006,13 @@ func (tbl *txnTable) rangesOnePart(
10091006
// Parameters:
10101007
// - txnOffset: Transaction writes offset used to specify the starting position for reading data.
10111008
// - fromSnapshot: Boolean indicating if the data is from a snapshot.
1012-
func (tbl *txnTable) collectUnCommittedDataObjs(txnOffset int) ([]objectio.ObjectStats, map[objectio.ObjectNameShort]struct{}) {
1013-
var unCommittedObjects []objectio.ObjectStats
1014-
unCommittedObjNames := make(map[objectio.ObjectNameShort]struct{})
1015-
1009+
func (tbl *txnTable) collectUnCommittedDataObjs(
1010+
txnOffset int,
1011+
) (
1012+
unCommittedObjects []objectio.ObjectStats,
1013+
unCommittedObjNames map[objectio.ObjectNameShort]struct{},
1014+
) {
1015+
unCommittedObjNames = make(map[objectio.ObjectNameShort]struct{})
10161016
if tbl.db.op.IsSnapOp() {
10171017
txnOffset = tbl.getTxn().GetSnapshotWriteOffset()
10181018
}
@@ -1040,68 +1040,6 @@ func (tbl *txnTable) collectUnCommittedDataObjs(txnOffset int) ([]objectio.Objec
10401040
return unCommittedObjects, unCommittedObjNames
10411041
}
10421042

1043-
//func (tbl *txnTable) collectDirtyBlocks(
1044-
// state *logtailreplay.PartitionState,
1045-
// uncommittedObjects []objectio.ObjectStats,
1046-
// txnOffset int, // Transaction writes offset used to specify the starting position for reading data.
1047-
//) map[types.Blockid]struct{} {
1048-
// dirtyBlks := make(map[types.Blockid]struct{})
1049-
// //collect partitionState.dirtyBlocks which may be invisible to this txn into dirtyBlks.
1050-
// {
1051-
// iter := state.NewDirtyBlocksIter()
1052-
// for iter.Next() {
1053-
// entry := iter.Entry()
1054-
// //lazy load deletes for block.
1055-
// dirtyBlks[entry] = struct{}{}
1056-
// }
1057-
// iter.Close()
1058-
//
1059-
// }
1060-
//
1061-
// //only collect dirty blocks in PartitionState.blocks into dirtyBlks.
1062-
// for _, bid := range tbl.GetDirtyPersistedBlks(state) {
1063-
// dirtyBlks[bid] = struct{}{}
1064-
// }
1065-
//
1066-
// if tbl.getTxn().hasDeletesOnUncommitedObject() {
1067-
// ForeachBlkInObjStatsList(true, nil, func(blk objectio.BlockInfo, _ objectio.BlockObject) bool {
1068-
// if tbl.getTxn().hasUncommittedDeletesOnBlock(&blk.BlockID) {
1069-
// dirtyBlks[blk.BlockID] = struct{}{}
1070-
// }
1071-
// return true
1072-
// }, uncommittedObjects...)
1073-
// }
1074-
//
1075-
// if tbl.db.op.IsSnapOp() {
1076-
// txnOffset = tbl.getTxn().GetSnapshotWriteOffset()
1077-
// }
1078-
//
1079-
// tbl.getTxn().ForEachTableWrites(
1080-
// tbl.db.databaseId,
1081-
// tbl.tableId,
1082-
// txnOffset,
1083-
// func(entry Entry) {
1084-
// // the CN workspace can only handle `INSERT` and `DELETE` operations. Other operations will be skipped,
1085-
// // TODO Adjustments will be made here in the future
1086-
// if entry.typ == DELETE || entry.typ == DELETE_TXN {
1087-
// if entry.IsGeneratedByTruncate() {
1088-
// return
1089-
// }
1090-
// //deletes in tbl.writes maybe comes from PartitionState.rows or PartitionState.blocks.
1091-
// if entry.fileName == "" &&
1092-
// entry.tableId != catalog.MO_DATABASE_ID && entry.tableId != catalog.MO_TABLES_ID && entry.tableId != catalog.MO_COLUMNS_ID {
1093-
// vs := vector.MustFixedColWithTypeCheck[types.Rowid](entry.bat.GetVector(0))
1094-
// for _, v := range vs {
1095-
// id, _ := v.Decode()
1096-
// dirtyBlks[id] = struct{}{}
1097-
// }
1098-
// }
1099-
// }
1100-
// })
1101-
//
1102-
// return dirtyBlks
1103-
//}
1104-
11051043
// the return defs has no rowid column
11061044
func (tbl *txnTable) TableDefs(ctx context.Context) ([]engine.TableDef, error) {
11071045
//return tbl.defs, nil
@@ -1997,12 +1935,12 @@ func (tbl *txnTable) getPartitionState(
19971935
ps = tbl.getTxn().engine.GetOrCreateLatestPart(tbl.db.databaseId, tbl.tableId).Snapshot()
19981936
}
19991937

2000-
if tbl.tableId == catalog.MO_COLUMNS_ID {
2001-
logutil.Info("open partition state for mo_columns",
2002-
zap.String("txn", tbl.db.op.Txn().DebugString()),
2003-
zap.String("desc", ps.Desc(true)),
2004-
zap.String("pointer", fmt.Sprintf("%p", ps)))
2005-
}
1938+
// if tbl.tableId == catalog.MO_COLUMNS_ID {
1939+
// logutil.Info("open partition state for mo_columns",
1940+
// zap.String("txn", tbl.db.op.Txn().DebugString()),
1941+
// zap.String("desc", ps.Desc(true)),
1942+
// zap.String("pointer", fmt.Sprintf("%p", ps)))
1943+
// }
20061944

20071945
return ps, nil
20081946
}
@@ -2015,13 +1953,13 @@ func (tbl *txnTable) getPartitionState(
20151953
if err != nil {
20161954
return nil, err
20171955
}
2018-
logutil.Infof("Get partition state for snapshot read, tbl:%p, table name:%s, tid:%v, txn:%s, ps:%p",
2019-
tbl,
2020-
tbl.tableName,
2021-
tbl.tableId,
2022-
tbl.db.op.Txn().DebugString(),
2023-
ps)
2024-
1956+
logutil.Info(
1957+
"Txn-GetPartitionState-SS",
1958+
zap.String("txn", hex.EncodeToString(tbl.db.op.Txn().ID)),
1959+
zap.String("name", tbl.tableName),
1960+
zap.String("id", fmt.Sprintf("%v", tbl.tableId)),
1961+
zap.String("ps", fmt.Sprintf("%p", ps)),
1962+
)
20251963
return ps, nil
20261964
}
20271965

@@ -2278,7 +2216,9 @@ func (tbl *txnTable) primaryKeysMayBeChanged(
22782216
snap,
22792217
from,
22802218
to,
2281-
keysVector, checkTombstone)
2219+
keysVector,
2220+
checkTombstone,
2221+
)
22822222
}
22832223

22842224
func (tbl *txnTable) MergeObjects(

0 commit comments

Comments
 (0)