diff --git a/core/stores/redis/hook.go b/core/stores/redis/hook.go index 7994fdd7..37f3644f 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()) } diff --git a/core/stores/redis/hook_test.go b/core/stores/redis/hook_test.go index ed10f549..7fb7551c 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)