From 421249d4df4a7a82b0c569d2dcb84cc525ba197e Mon Sep 17 00:00:00 2001 From: hlts2 Date: Mon, 5 Jun 2023 11:32:34 +0900 Subject: [PATCH 1/5] add save index operation log Signed-off-by: hlts2 --- pkg/agent/core/ngt/service/ngt.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/pkg/agent/core/ngt/service/ngt.go b/pkg/agent/core/ngt/service/ngt.go index ca121f784e..25a1dc4b73 100644 --- a/pkg/agent/core/ngt/service/ngt.go +++ b/pkg/agent/core/ngt/service/ngt.go @@ -1063,6 +1063,8 @@ func (n *ngt) SaveIndex(ctx context.Context) (err error) { } }() if !n.inMem { + log.Info("save index operation started") + defer log.Infof("save index operation finished") return n.saveIndex(ctx) } return nil From 59a2f3763f17da868c5091e25a5c52bff0b7d32a Mon Sep 17 00:00:00 2001 From: hlts2 Date: Mon, 5 Jun 2023 15:43:31 +0900 Subject: [PATCH 2/5] add save index operation phase log Signed-off-by: hlts2 --- pkg/agent/core/ngt/service/ngt.go | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/pkg/agent/core/ngt/service/ngt.go b/pkg/agent/core/ngt/service/ngt.go index 25a1dc4b73..2c2acbd7ca 100644 --- a/pkg/agent/core/ngt/service/ngt.go +++ b/pkg/agent/core/ngt/service/ngt.go @@ -1063,8 +1063,6 @@ func (n *ngt) SaveIndex(ctx context.Context) (err error) { } }() if !n.inMem { - log.Info("save index operation started") - defer log.Infof("save index operation finished") return n.saveIndex(ctx) } return nil @@ -1097,6 +1095,8 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { defer n.gc() defer n.saving.Store(false) + log.Infof("save index operation started, the number of create index execution = %d", nocie) + defer log.Info("save index operation finished") log.Debug("cleanup invalid index started") n.removeInvalidIndex(ctx) log.Debug("cleanup invalid index finished") @@ -1117,6 +1117,8 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { n.smu.Lock() defer n.smu.Unlock() eg.Go(safety.RecoverFunc(func() (err error) { + log.Debugf("start save operation for kvsdb, the number of kvsdb = %d", n.kvs.Len()) + defer log.Debug("save operation for kvsdb finished") if n.kvs.Len() > 0 && path != "" { m := make(map[string]uint32, n.Len()) mt := make(map[string]int64, n.Len()) @@ -1192,6 +1194,8 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { n.fmu.Lock() fl := len(n.fmap) n.fmu.Unlock() + log.Debugf("start save operation for invalid kvsdb, the number of invalid kvsdb = %d", fl) + defer log.Debug("save operation for invalid kvsdb finished") if fl > 0 && path != "" { var f *os.File f, err = file.Open( @@ -1226,6 +1230,8 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { })) eg.Go(safety.RecoverFunc(func() error { + log.Debug("start save operation for index") + defer log.Debug("save operation for index") return n.core.SaveIndexWithPath(path) })) @@ -1234,6 +1240,8 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { return err } + log.Debug("start save operation for metadata json file") + defer log.Debug("save operation for index") err = metadata.Store( file.Join(path, metadata.AgentMetadataFileName), &metadata.Metadata{ From 334466731aa7c1a589e0e71ddf8ff9b1b8df08be Mon Sep 17 00:00:00 2001 From: hlts2 Date: Mon, 5 Jun 2023 16:32:48 +0900 Subject: [PATCH 3/5] delete defer logging for save index operation Signed-off-by: hlts2 --- pkg/agent/core/ngt/service/ngt.go | 37 +++++++++++++++++++++++-------- 1 file changed, 28 insertions(+), 9 deletions(-) diff --git a/pkg/agent/core/ngt/service/ngt.go b/pkg/agent/core/ngt/service/ngt.go index 2c2acbd7ca..8830db6331 100644 --- a/pkg/agent/core/ngt/service/ngt.go +++ b/pkg/agent/core/ngt/service/ngt.go @@ -1095,8 +1095,6 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { defer n.gc() defer n.saving.Store(false) - log.Infof("save index operation started, the number of create index execution = %d", nocie) - defer log.Info("save index operation finished") log.Debug("cleanup invalid index started") n.removeInvalidIndex(ctx) log.Debug("cleanup invalid index finished") @@ -1116,9 +1114,10 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { } n.smu.Lock() defer n.smu.Unlock() + log.Infof("save index operation started, the number of create index execution = %d", nocie) + eg.Go(safety.RecoverFunc(func() (err error) { log.Debugf("start save operation for kvsdb, the number of kvsdb = %d", n.kvs.Len()) - defer log.Debug("save operation for kvsdb finished") if n.kvs.Len() > 0 && path != "" { m := make(map[string]uint32, n.Len()) mt := make(map[string]int64, n.Len()) @@ -1138,6 +1137,7 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { fs.ModePerm, ) if err != nil { + log.Warnf("failed to create or open kvsdb file, err: %v", err) return err } defer func() { @@ -1151,10 +1151,12 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { gob.Register(map[string]uint32{}) err = gob.NewEncoder(f).Encode(&m) if err != nil { + log.Warnf("failed to encode kvsdb data, err: %v", err) return err } err = f.Sync() if err != nil { + log.Warnf("failed to flush all kvsdb data to storage, err: %v", err) return err } m = make(map[string]uint32) @@ -1166,6 +1168,7 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { fs.ModePerm, ) if err != nil { + log.Warn("failed to create or open kvs timestamp file, err: %v", err) return err } defer func() { @@ -1179,14 +1182,17 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { gob.Register(map[string]int64{}) err = gob.NewEncoder(ft).Encode(&mt) if err != nil { + log.Warn("failed to encode kvs timestamp data, err: %v", err) return err } err = ft.Sync() if err != nil { + log.Warnf("failed to flush all kvsdb timestamp data to storage, err: %v", err) return err } mt = make(map[string]int64) } + log.Debug("save operation for kvsdb finished") return nil })) @@ -1195,7 +1201,6 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { fl := len(n.fmap) n.fmu.Unlock() log.Debugf("start save operation for invalid kvsdb, the number of invalid kvsdb = %d", fl) - defer log.Debug("save operation for invalid kvsdb finished") if fl > 0 && path != "" { var f *os.File f, err = file.Open( @@ -1204,6 +1209,7 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { fs.ModePerm, ) if err != nil { + log.Warnf("failed to create or open invalid kvsdb file, err: %v", err) return err } defer func() { @@ -1219,20 +1225,27 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { err = gob.NewEncoder(f).Encode(&n.fmap) n.fmu.Unlock() if err != nil { + log.Warnf("failed to encode invalid kvsdb data, err: %v", err) return err } err = f.Sync() if err != nil { + log.Warnf("failed to flush all invalid kvsdb data to storage, err: %v", err) return err } } + log.Debug("start save operation for invalid kvsdb finished") return nil })) eg.Go(safety.RecoverFunc(func() error { log.Debug("start save operation for index") - defer log.Debug("save operation for index") - return n.core.SaveIndexWithPath(path) + if err := n.core.SaveIndexWithPath(path); err != nil { + log.Warnf("failed to save index with path, err: %v\tpath: %s", err, path) + return err + } + log.Debug("save operation for index finished") + return nil })) err = eg.Wait() @@ -1240,8 +1253,7 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { return err } - log.Debug("start save operation for metadata json file") - defer log.Debug("save operation for index") + log.Debug("start save operation for metadata file") err = metadata.Store( file.Join(path, metadata.AgentMetadataFileName), &metadata.Metadata{ @@ -1252,10 +1264,16 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { }, ) if err != nil { + log.Warnf("failed to save metadata file, err: %v", err) return err } + log.Debug("save operation for metadata file finished") - return n.moveAndSwitchSavedData(ctx) + if err := n.moveAndSwitchSavedData(ctx); err != nil { + return err + } + log.Info("save index operation finished") + return nil } func (n *ngt) CreateAndSaveIndex(ctx context.Context, poolSize uint32) (err error) { @@ -1282,6 +1300,7 @@ func (n *ngt) moveAndSwitchSavedData(ctx context.Context) (err error) { } n.cowmu.Lock() defer n.cowmu.Unlock() + log.Debug("start move and switch saved data operation for copy on write") err = file.MoveDir(ctx, n.path, n.oldPath) if err != nil { log.Warnf("failed to backup backup data from %s to %s error: %v", n.path, n.oldPath, err) From 20ed5e3d92454078cb24bcf4e47dab4096aea37c Mon Sep 17 00:00:00 2001 From: hlts2 Date: Mon, 5 Jun 2023 16:35:09 +0900 Subject: [PATCH 4/5] fix warn function Signed-off-by: hlts2 --- pkg/agent/core/ngt/service/ngt.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/pkg/agent/core/ngt/service/ngt.go b/pkg/agent/core/ngt/service/ngt.go index 8830db6331..f93e96b0dd 100644 --- a/pkg/agent/core/ngt/service/ngt.go +++ b/pkg/agent/core/ngt/service/ngt.go @@ -1168,7 +1168,7 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { fs.ModePerm, ) if err != nil { - log.Warn("failed to create or open kvs timestamp file, err: %v", err) + log.Warnf("failed to create or open kvs timestamp file, err: %v", err) return err } defer func() { @@ -1182,7 +1182,7 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { gob.Register(map[string]int64{}) err = gob.NewEncoder(ft).Encode(&mt) if err != nil { - log.Warn("failed to encode kvs timestamp data, err: %v", err) + log.Warnf("failed to encode kvs timestamp data, err: %v", err) return err } err = ft.Sync() From 49d722bba49629e0fafba8dc93a6b93f16bff2d7 Mon Sep 17 00:00:00 2001 From: hlts2 Date: Mon, 5 Jun 2023 16:38:29 +0900 Subject: [PATCH 5/5] added warn log when the copy on write operation failed Signed-off-by: hlts2 --- pkg/agent/core/ngt/service/ngt.go | 1 + 1 file changed, 1 insertion(+) diff --git a/pkg/agent/core/ngt/service/ngt.go b/pkg/agent/core/ngt/service/ngt.go index f93e96b0dd..56d2f6a46a 100644 --- a/pkg/agent/core/ngt/service/ngt.go +++ b/pkg/agent/core/ngt/service/ngt.go @@ -1270,6 +1270,7 @@ func (n *ngt) saveIndex(ctx context.Context) (err error) { log.Debug("save operation for metadata file finished") if err := n.moveAndSwitchSavedData(ctx); err != nil { + log.Warnf("failed to move and switch saved data for copy on write, err: %v", err) return err } log.Info("save index operation finished")