debugmode: reduce the data we collect (#784)

Signed-off-by: spacewander <[email protected]>
mosn · Oct 28, 2024 · d20f408 · d20f408
1 parent e0c9ce2
commit d20f408
Show file tree

Hide file tree

Showing 5 changed files with 40 additions and 32 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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 {