From d20f408cc78b3da8fdcf2f51817695a563cda589 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E7=BD=97=E6=B3=BD=E8=BD=A9?= Date: Mon, 28 Oct 2024 09:58:51 +0800 Subject: [PATCH] debugmode: reduce the data we collect (#784) Signed-off-by: spacewander --- api/pkg/filtermanager/model/model.go | 2 +- api/pkg/filtermanager/wrapper.go | 28 ++++++++++---------- api/pkg/filtermanager/wrapper_test.go | 23 +++++++++++----- plugins/plugins/debugmode/filter.go | 13 ++++----- plugins/tests/integration/debug_mode_test.go | 6 ++--- 5 files changed, 40 insertions(+), 32 deletions(-) diff --git a/api/pkg/filtermanager/model/model.go b/api/pkg/filtermanager/model/model.go index 0ae4bf89..008ee258 100644 --- a/api/pkg/filtermanager/model/model.go +++ b/api/pkg/filtermanager/model/model.go @@ -51,5 +51,5 @@ func NewFilterWrapper(name string, f api.Filter) *FilterWrapper { type ExecutionRecord struct { PluginName string - Record map[string]time.Duration + Record time.Duration } diff --git a/api/pkg/filtermanager/wrapper.go b/api/pkg/filtermanager/wrapper.go index 570195c8..b29bb245 100644 --- a/api/pkg/filtermanager/wrapper.go +++ b/api/pkg/filtermanager/wrapper.go @@ -129,57 +129,57 @@ func NewDebugFilter(name string, internal api.Filter, callbacks api.FilterCallba } } -func (f *debugFilter) recordExecution(start time.Time, method string) { +func (f *debugFilter) recordExecution(start time.Time) { duration := time.Since(start) executionRecords := f.callbacks.PluginState().Get("debugMode", "executionRecords") if executionRecords == nil { - executionRecords = []model.ExecutionRecord{} + executionRecords = []*model.ExecutionRecord{} f.callbacks.PluginState().Set("debugMode", "executionRecords", executionRecords) } - records, ok := executionRecords.([]model.ExecutionRecord) + records, ok := executionRecords.([]*model.ExecutionRecord) if !ok { panic(fmt.Sprintf("unexpected type: %s", reflect.TypeOf(executionRecords))) } for _, record := range records { if record.PluginName == f.name { - record.Record[method] += duration + record.Record += duration return } } - f.callbacks.PluginState().Set("debugMode", "executionRecords", append(records, model.ExecutionRecord{ + f.callbacks.PluginState().Set("debugMode", "executionRecords", append(records, &model.ExecutionRecord{ PluginName: f.name, - Record: map[string]time.Duration{method: duration}, + Record: duration, })) } func (f *debugFilter) DecodeHeaders(headers api.RequestHeaderMap, endStream bool) api.ResultAction { - defer f.recordExecution(time.Now(), "DecodeHeaders") + defer f.recordExecution(time.Now()) return f.internal.DecodeHeaders(headers, endStream) } func (f *debugFilter) DecodeData(data api.BufferInstance, endStream bool) api.ResultAction { - defer f.recordExecution(time.Now(), "DecodeData") + defer f.recordExecution(time.Now()) return f.internal.DecodeData(data, endStream) } func (f *debugFilter) DecodeTrailers(trailers api.RequestTrailerMap) api.ResultAction { - defer f.recordExecution(time.Now(), "DecodeTrailers") + defer f.recordExecution(time.Now()) return f.internal.DecodeTrailers(trailers) } func (f *debugFilter) EncodeHeaders(headers api.ResponseHeaderMap, endStream bool) api.ResultAction { - defer f.recordExecution(time.Now(), "EncodeHeaders") + defer f.recordExecution(time.Now()) return f.internal.EncodeHeaders(headers, endStream) } func (f *debugFilter) EncodeData(data api.BufferInstance, endStream bool) api.ResultAction { - defer f.recordExecution(time.Now(), "EncodeData") + defer f.recordExecution(time.Now()) return f.internal.EncodeData(data, endStream) } func (f *debugFilter) EncodeTrailers(trailers api.ResponseTrailerMap) api.ResultAction { - defer f.recordExecution(time.Now(), "EncodeTrailers") + defer f.recordExecution(time.Now()) return f.internal.EncodeTrailers(trailers) } @@ -191,11 +191,11 @@ func (f *debugFilter) OnLog(reqHeaders api.RequestHeaderMap, reqTrailers api.Req } func (f *debugFilter) DecodeRequest(headers api.RequestHeaderMap, data api.BufferInstance, trailers api.RequestTrailerMap) api.ResultAction { - defer f.recordExecution(time.Now(), "DecodeRequest") + defer f.recordExecution(time.Now()) return f.internal.DecodeRequest(headers, data, trailers) } func (f *debugFilter) EncodeResponse(headers api.ResponseHeaderMap, data api.BufferInstance, trailers api.ResponseTrailerMap) api.ResultAction { - defer f.recordExecution(time.Now(), "EncodeResponse") + defer f.recordExecution(time.Now()) return f.internal.EncodeResponse(headers, data, trailers) } diff --git a/api/pkg/filtermanager/wrapper_test.go b/api/pkg/filtermanager/wrapper_test.go index 55604d96..92bbe50b 100644 --- a/api/pkg/filtermanager/wrapper_test.go +++ b/api/pkg/filtermanager/wrapper_test.go @@ -35,29 +35,40 @@ func TestDebugFilter(t *testing.T) { f2.DecodeHeaders(nil, true) f1.DecodeHeaders(nil, true) - records := cb.PluginState().Get("debugMode", "executionRecords").([]model.ExecutionRecord) + records := cb.PluginState().Get("debugMode", "executionRecords").([]*model.ExecutionRecord) t.Logf("get records %+v\n", records) // for debug when test failed assert.Equal(t, 2, len(records)) assert.Equal(t, "two", records[0].PluginName) - assert.True(t, records[0].Record["DecodeHeaders"] > 0) + assert.True(t, records[0].Record > 0) assert.Equal(t, "one", records[1].PluginName) - assert.True(t, records[1].Record["DecodeHeaders"] > 0) + assert.True(t, records[1].Record > 0) + decodeHeadersCost := records[1].Record patches := gomonkey.ApplyMethodFunc(raw1, "DecodeData", func(data api.BufferInstance, endStream bool) api.ResultAction { time.Sleep(100 * time.Millisecond) return api.Continue }) + patches.ApplyMethodFunc(raw1, "EncodeHeaders", func(headers api.ResponseHeaderMap, endStream bool) api.ResultAction { + time.Sleep(50 * time.Millisecond) + return api.Continue + }) + patches.ApplyMethodFunc(raw1, "EncodeData", func(data api.BufferInstance, endStream bool) api.ResultAction { + time.Sleep(20 * time.Millisecond) + return api.Continue + }) defer patches.Reset() f1.DecodeData(nil, false) f1.DecodeData(nil, true) + f1.EncodeHeaders(nil, false) + f1.EncodeData(nil, true) - records = cb.PluginState().Get("debugMode", "executionRecords").([]model.ExecutionRecord) + records = cb.PluginState().Get("debugMode", "executionRecords").([]*model.ExecutionRecord) t.Logf("get records %+v\n", records) // for debug when test failed assert.Equal(t, 2, len(records)) assert.Equal(t, "one", records[1].PluginName) // Should be the sum of multiple calls delta := 10 * time.Millisecond - rec := records[1].Record["DecodeData"] - assert.True(t, 200*time.Millisecond-delta < rec && rec < 200*time.Millisecond+delta, rec) + rec := records[1].Record - decodeHeadersCost + assert.True(t, 270*time.Millisecond-delta < rec && rec < 270*time.Millisecond+delta, rec) } diff --git a/plugins/plugins/debugmode/filter.go b/plugins/plugins/debugmode/filter.go index 4e3bfd05..2e1f9706 100644 --- a/plugins/plugins/debugmode/filter.go +++ b/plugins/plugins/debugmode/filter.go @@ -38,8 +38,8 @@ type filter struct { } type executionPlugin struct { - Name string `json:"name"` - PerPhaseCostSeconds map[string]float64 `json:"per_phase_cost_seconds"` + Name string `json:"name"` + CostSeconds float64 `json:"cost_seconds"` } type SlowLogReport struct { @@ -104,14 +104,11 @@ func (f *filter) OnLog(reqHeaders api.RequestHeaderMap, reqTrailers api.RequestT // This is a private API and we don't guarantee its stablibity r := f.callbacks.PluginState().Get("debugMode", "executionRecords") if r != nil { - executionRecords := r.([]model.ExecutionRecord) + executionRecords := r.([]*model.ExecutionRecord) for _, record := range executionRecords { p := executionPlugin{ - Name: record.PluginName, - } - p.PerPhaseCostSeconds = make(map[string]float64) - for k, v := range record.Record { - p.PerPhaseCostSeconds[k] = v.Seconds() + Name: record.PluginName, + CostSeconds: record.Record.Seconds(), } report.ExecutedPlugins = append(report.ExecutedPlugins, p) } diff --git a/plugins/tests/integration/debug_mode_test.go b/plugins/tests/integration/debug_mode_test.go index 2bf15e16..dd3b4a49 100644 --- a/plugins/tests/integration/debug_mode_test.go +++ b/plugins/tests/integration/debug_mode_test.go @@ -31,7 +31,7 @@ func TestDebugModeSlowLog(t *testing.T) { dp, err := dataplane.StartDataPlane(t, &dataplane.Option{ NoErrorLogCheck: true, ExpectLogPattern: []string{ - `slow log report:.+"executed_plugins":\[.+"name":"limitReq","per_phase_cost_seconds":\{"DecodeHeaders":.+`, + `slow log report:.+"executed_plugins":\[.+"name":"limitReq","cost_seconds":.+`, }, }) if err != nil { @@ -75,7 +75,7 @@ func TestDebugModeSlowLogNoPlugin(t *testing.T) { dp, err := dataplane.StartDataPlane(t, &dataplane.Option{ NoErrorLogCheck: true, ExpectNoLogPattern: []string{ - `slow log report:.+"executed_plugins":\[.+"name":"limitReq","per_phase_cost_seconds":\{"DecodeHeaders":.+`, + `slow log report:.+"executed_plugins":\[.+"name":"limitReq","cost_seconds":.+`, }, ExpectLogPattern: []string{ `slow log report:.+"server":\["envoy"\]`, @@ -196,7 +196,7 @@ func TestDebugModeSlowLogWithFiltersFromConsumer(t *testing.T) { LogLevel: "debug", NoErrorLogCheck: true, ExpectLogPattern: []string{ - `slow log report:.+"executed_plugins":\[.+"name":"limitReq","per_phase_cost_seconds":\{"DecodeHeaders":.+`, + `slow log report:.+"executed_plugins":\[.+"name":"limitReq","cost_seconds":.+`, }, }) if err != nil {