From 6613e71bb5db0f1b66b3b40fcbcfc70ceea9470c Mon Sep 17 00:00:00 2001 From: liaoshiwei Date: Thu, 20 Oct 2022 09:28:27 +0800 Subject: [PATCH 1/2] fix: redis's pipeline logs are not printed completely --- core/stores/redis/hook.go | 21 ++++++++++++++------- 1 file changed, 14 insertions(+), 7 deletions(-) diff --git a/core/stores/redis/hook.go b/core/stores/redis/hook.go index 7994fdd75654..37f3644f553f 100644 --- a/core/stores/redis/hook.go +++ b/core/stores/redis/hook.go @@ -56,7 +56,7 @@ func (h hook) AfterProcess(ctx context.Context, cmd red.Cmder) error { duration := timex.Since(start) if duration > slowThreshold.Load() { - logDuration(ctx, cmd, duration) + logDuration(ctx, []red.Cmder{cmd}, duration) } metricReqDur.Observe(int64(duration/time.Millisecond), cmd.Name()) @@ -103,7 +103,7 @@ func (h hook) AfterProcessPipeline(ctx context.Context, cmds []red.Cmder) error duration := timex.Since(start) if duration > slowThreshold.Load()*time.Duration(len(cmds)) { - logDuration(ctx, cmds[0], duration) + logDuration(ctx, cmds, duration) } metricReqDur.Observe(int64(duration/time.Millisecond), "Pipeline") @@ -136,13 +136,20 @@ func formatError(err error) string { } } -func logDuration(ctx context.Context, cmd red.Cmder, duration time.Duration) { +func logDuration(ctx context.Context, cmds []red.Cmder, duration time.Duration) { var buf strings.Builder - for i, arg := range cmd.Args() { - if i > 0 { - buf.WriteByte(' ') + for k, cmd := range cmds { + if k > 0 { + buf.WriteByte('\n') } - buf.WriteString(mapping.Repr(arg)) + var build strings.Builder + for i, arg := range cmd.Args() { + if i > 0 { + build.WriteByte(' ') + } + build.WriteString(mapping.Repr(arg)) + } + buf.WriteString(mapping.Repr(build.String())) } logx.WithContext(ctx).WithDuration(duration).Slowf("[REDIS] slowcall on executing: %s", buf.String()) } From b795e73ca6408170fd38ad52fd254515c5a51d6f Mon Sep 17 00:00:00 2001 From: liaoshiwei Date: Fri, 21 Oct 2022 10:11:37 +0800 Subject: [PATCH 2/2] add unit test Signed-off-by: liaoshiwei --- core/stores/redis/hook_test.go | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/core/stores/redis/hook_test.go b/core/stores/redis/hook_test.go index ed10f549a66f..7fb7551c6bf0 100644 --- a/core/stores/redis/hook_test.go +++ b/core/stores/redis/hook_test.go @@ -163,6 +163,17 @@ func TestHookProcessPipelineCase5(t *testing.T) { assert.True(t, buf.Len() == 0) } +func TestLogDuration(t *testing.T) { + w, restore := injectLog() + defer restore() + + logDuration(context.Background(), []red.Cmder{red.NewCmd(context.Background(), "get", "foo")}, 1*time.Second) + assert.True(t, strings.Contains(w.String(), "get foo")) + + logDuration(context.Background(), []red.Cmder{red.NewCmd(context.Background(), "get", "foo"), red.NewCmd(context.Background(), "set", "bar", 0)}, 1*time.Second) + assert.True(t, strings.Contains(w.String(), "get foo\\nset bar 0")) +} + func injectLog() (r *strings.Builder, restore func()) { var buf strings.Builder w := logx.NewWriter(&buf)