You've already forked opentelemetry-go
mirror of
https://github.com/open-telemetry/opentelemetry-go.git
synced 2025-11-27 22:49:15 +02:00
Towards: https://github.com/open-telemetry/opentelemetry-go/issues/6382 This PR optimizes Logs SDK BatchProcessor. ## Why? <!-- was i so blind --> Batch processor does not check if buffer exporter is full, instead it clones records to buffer, then tries to push them to buffer exporter, and then buffer exporter will return false from EnqueueExport if it is full. It does not cause any performance issues when using NOOP exporter, because it "exports" instantly. -> Buffer exporter input channel will almost never be full. But actual implementations of exporters are not going to act that way, they need some time for export operation. And so buffer exporter will get full fairly frequently. Each export attempt to buffer exporter costs us copying entire queue inside of batch processor. In order to catch this or similar performance bottleneck in the future, new benchmark (`BatchSimulateExport`) was added which will use exporter that will simulate non-instant export by sleeping for 5ms. ## Benchmarks ```sh goos: linux goarch: amd64 pkg: go.opentelemetry.io/otel/sdk/log cpu: AMD Ryzen 9 7900X 12-Core Processor │ base.txt │ new.txt │ │ sec/op │ sec/op vs base │ Processor/Simple-24 340.9n ± 2% 343.5n ± 5% ~ (p=0.971 n=10) Processor/Batch-24 667.6n ± 2% 666.3n ± 4% ~ (p=0.896 n=10) Processor/BatchSimulateExport-24 4441.5n ± 5% 526.4n ± 4% -88.15% (p=0.000 n=10) Processor/SetTimestampSimple-24 360.0n ± 4% 351.0n ± 1% ~ (p=0.247 n=10) Processor/SetTimestampBatch-24 669.8n ± 3% 647.0n ± 5% ~ (p=0.052 n=10) Processor/AddAttributesSimple-24 383.9n ± 1% 386.6n ± 5% ~ (p=0.138 n=10) Processor/AddAttributesBatch-24 759.9n ± 6% 734.5n ± 5% ~ (p=0.481 n=10) Processor/SetAttributesSimple-24 369.9n ± 2% 372.4n ± 3% ~ (p=0.643 n=10) Processor/SetAttributesBatch-24 684.2n ± 4% 674.0n ± 8% ~ (p=0.529 n=10) geomean 639.9n 499.9n -21.88% │ base.txt │ new.txt │ │ B/op │ B/op vs base │ Processor/Simple-24 450.0 ± 0% 450.0 ± 0% ~ (p=1.000 n=10) ¹ Processor/Batch-24 1.153Ki ± 2% 1.125Ki ± 1% -2.41% (p=0.001 n=10) Processor/BatchSimulateExport-24 649.0 ± 1% 473.0 ± 0% -27.12% (p=0.000 n=10) Processor/SetTimestampSimple-24 450.0 ± 0% 450.0 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetTimestampBatch-24 1.145Ki ± 2% 1.122Ki ± 2% -2.01% (p=0.003 n=10) Processor/AddAttributesSimple-24 450.0 ± 0% 450.0 ± 0% ~ (p=1.000 n=10) ¹ Processor/AddAttributesBatch-24 1.169Ki ± 2% 1.148Ki ± 1% -1.80% (p=0.000 n=10) Processor/SetAttributesSimple-24 450.0 ± 0% 450.0 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetAttributesBatch-24 1.141Ki ± 2% 1.128Ki ± 2% -1.11% (p=0.030 n=10) geomean 719.3 688.7 -4.24% ¹ all samples are equal │ base.txt │ new.txt │ │ allocs/op │ allocs/op vs base │ Processor/Simple-24 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/Batch-24 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/BatchSimulateExport-24 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetTimestampSimple-24 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetTimestampBatch-24 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/AddAttributesSimple-24 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/AddAttributesBatch-24 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetAttributesSimple-24 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ Processor/SetAttributesBatch-24 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹ geomean 1.000 1.000 +0.00% ¹ all samples are equal ``` ## Benchmarks from issue (external) ```sh goos: linux goarch: amd64 pkg: github.com/pellared/spanevents-vs-logs cpu: AMD Ryzen 9 7900X 12-Core Processor │ spanevents.txt │ logs.base.txt │ logs.new.txt │ │ sec/op │ sec/op vs base │ sec/op vs base │ /OTLP-24 41.40µ ± 3% 2935.15µ ± 9% +6989.05% (p=0.000 n=10) 84.19µ ± 4% +103.34% (p=0.000 n=10) /STDOUT-24 39.55µ ± 4% 623.45µ ± 1% +1476.21% (p=0.000 n=10) 89.51µ ± 3% +126.29% (p=0.000 n=10) /NOOP-24 13.179µ ± 2% 4.950µ ± 1% -62.44% (p=0.000 n=10) 4.932µ ± 1% -62.58% (p=0.000 n=10) geomean 27.84µ 208.4µ +648.68% 33.37µ +19.86% │ spanevents.txt │ logs.base.txt │ logs.new.txt │ │ B/op │ B/op vs base │ B/op vs base │ /OTLP-24 98.90Ki ± 8% 210.44Ki ± 0% +112.79% (p=0.000 n=10) 52.01Ki ± 0% -47.41% (p=0.000 n=10) /STDOUT-24 91.01Ki ± 0% 286.62Ki ± 0% +214.93% (p=0.000 n=10) 81.67Ki ± 1% -10.27% (p=0.000 n=10) /NOOP-24 29840.0 ± 0% 240.0 ± 0% -99.20% (p=0.000 n=10) 240.0 ± 0% -99.20% (p=0.000 n=10) geomean 64.01Ki 24.18Ki -62.23% 9.985Ki -84.40% │ spanevents.txt │ logs.base.txt │ logs.new.txt │ │ allocs/op │ allocs/op vs base │ allocs/op vs base │ /OTLP-24 699.0 ± 20% 2174.5 ± 1% +211.09% (p=0.000 n=10) 249.5 ± 1% -64.31% (p=0.000 n=10) /STDOUT-24 646.5 ± 1% 4912.5 ± 0% +659.86% (p=0.000 n=10) 872.5 ± 2% +34.96% (p=0.000 n=10) /NOOP-24 303.000 ± 0% 3.000 ± 0% -99.01% (p=0.000 n=10) 3.000 ± 0% -99.01% (p=0.000 n=10) geomean 515.4 317.6 -38.37% 86.76 -83.17% ``` ```sh goos: linux goarch: amd64 pkg: github.com/pellared/spanevents-vs-logs cpu: AMD Ryzen 9 7900X 12-Core Processor │ logs.base.txt │ logs.new.txt │ │ sec/op │ sec/op vs base │ /OTLP-24 2935.15µ ± 9% 84.19µ ± 4% -97.13% (p=0.000 n=10) /STDOUT-24 623.45µ ± 1% 89.51µ ± 3% -85.64% (p=0.000 n=10) /NOOP-24 4.950µ ± 1% 4.932µ ± 1% ~ (p=0.342 n=10) geomean 208.4µ 33.37µ -83.99% │ logs.base.txt │ logs.new.txt │ │ B/op │ B/op vs base │ /OTLP-24 210.44Ki ± 0% 52.01Ki ± 0% -75.28% (p=0.000 n=10) /STDOUT-24 286.62Ki ± 0% 81.67Ki ± 1% -71.51% (p=0.000 n=10) /NOOP-24 240.0 ± 0% 240.0 ± 0% ~ (p=1.000 n=10) ¹ geomean 24.18Ki 9.985Ki -58.70% ¹ all samples are equal │ logs.base.txt │ logs.new.txt │ │ allocs/op │ allocs/op vs base │ /OTLP-24 2174.5 ± 1% 249.5 ± 1% -88.53% (p=0.000 n=10) /STDOUT-24 4912.5 ± 0% 872.5 ± 2% -82.24% (p=0.000 n=10) /NOOP-24 3.000 ± 0% 3.000 ± 0% ~ (p=1.000 n=10) ¹ geomean 317.6 86.76 -72.69% ¹ all samples are equal ``` --------- Co-authored-by: Robert Pająk <pellared@hotmail.com> Co-authored-by: Damien Mathieu <42@dmathieu.com>
185 lines
4.2 KiB
Go
185 lines
4.2 KiB
Go
// Copyright The OpenTelemetry Authors
|
|
// SPDX-License-Identifier: Apache-2.0
|
|
|
|
package log
|
|
|
|
import (
|
|
"context"
|
|
"testing"
|
|
"time"
|
|
|
|
"go.opentelemetry.io/otel/log"
|
|
|
|
"github.com/stretchr/testify/assert"
|
|
)
|
|
|
|
type mockDelayExporter struct{}
|
|
|
|
func (mockDelayExporter) Export(context.Context, []Record) error {
|
|
time.Sleep(time.Millisecond * 5)
|
|
return nil
|
|
}
|
|
|
|
func (mockDelayExporter) Shutdown(context.Context) error { return nil }
|
|
|
|
func (mockDelayExporter) ForceFlush(context.Context) error { return nil }
|
|
|
|
func BenchmarkProcessor(b *testing.B) {
|
|
for _, tc := range []struct {
|
|
name string
|
|
f func() []LoggerProviderOption
|
|
}{
|
|
{
|
|
name: "Simple",
|
|
f: func() []LoggerProviderOption {
|
|
return []LoggerProviderOption{WithProcessor(NewSimpleProcessor(noopExporter{}))}
|
|
},
|
|
},
|
|
{
|
|
name: "Batch",
|
|
f: func() []LoggerProviderOption {
|
|
return []LoggerProviderOption{WithProcessor(NewBatchProcessor(noopExporter{}))}
|
|
},
|
|
},
|
|
{
|
|
name: "BatchSimulateExport",
|
|
f: func() []LoggerProviderOption {
|
|
return []LoggerProviderOption{WithProcessor(NewBatchProcessor(mockDelayExporter{}))}
|
|
},
|
|
},
|
|
{
|
|
name: "SetTimestampSimple",
|
|
f: func() []LoggerProviderOption {
|
|
return []LoggerProviderOption{
|
|
WithProcessor(timestampProcessor{}),
|
|
WithProcessor(NewSimpleProcessor(noopExporter{})),
|
|
}
|
|
},
|
|
},
|
|
{
|
|
name: "SetTimestampBatch",
|
|
f: func() []LoggerProviderOption {
|
|
return []LoggerProviderOption{
|
|
WithProcessor(timestampProcessor{}),
|
|
WithProcessor(NewBatchProcessor(noopExporter{})),
|
|
}
|
|
},
|
|
},
|
|
{
|
|
name: "AddAttributesSimple",
|
|
f: func() []LoggerProviderOption {
|
|
return []LoggerProviderOption{
|
|
WithProcessor(attrAddProcessor{}),
|
|
WithProcessor(NewSimpleProcessor(noopExporter{})),
|
|
}
|
|
},
|
|
},
|
|
{
|
|
name: "AddAttributesBatch",
|
|
f: func() []LoggerProviderOption {
|
|
return []LoggerProviderOption{
|
|
WithProcessor(attrAddProcessor{}),
|
|
WithProcessor(NewBatchProcessor(noopExporter{})),
|
|
}
|
|
},
|
|
},
|
|
{
|
|
name: "SetAttributesSimple",
|
|
f: func() []LoggerProviderOption {
|
|
return []LoggerProviderOption{
|
|
WithProcessor(attrSetDecorator{}),
|
|
WithProcessor(NewSimpleProcessor(noopExporter{})),
|
|
}
|
|
},
|
|
},
|
|
{
|
|
name: "SetAttributesBatch",
|
|
f: func() []LoggerProviderOption {
|
|
return []LoggerProviderOption{
|
|
WithProcessor(attrSetDecorator{}),
|
|
WithProcessor(NewBatchProcessor(noopExporter{})),
|
|
}
|
|
},
|
|
},
|
|
} {
|
|
b.Run(tc.name, func(b *testing.B) {
|
|
provider := NewLoggerProvider(tc.f()...)
|
|
b.Cleanup(func() { assert.NoError(b, provider.Shutdown(context.Background())) })
|
|
logger := provider.Logger(b.Name())
|
|
|
|
b.ReportAllocs()
|
|
b.RunParallel(func(pb *testing.PB) {
|
|
for pb.Next() {
|
|
r := log.Record{}
|
|
r.SetBody(log.StringValue("message"))
|
|
r.SetSeverity(log.SeverityInfo)
|
|
r.AddAttributes(
|
|
log.String("foo", "bar"),
|
|
log.Float64("float", 3.14),
|
|
log.Int("int", 123),
|
|
log.Bool("bool", true),
|
|
)
|
|
logger.Emit(context.Background(), r)
|
|
}
|
|
})
|
|
})
|
|
}
|
|
}
|
|
|
|
type timestampProcessor struct{}
|
|
|
|
func (p timestampProcessor) OnEmit(ctx context.Context, r *Record) error {
|
|
r.SetObservedTimestamp(time.Date(1988, time.November, 17, 0, 0, 0, 0, time.UTC))
|
|
return nil
|
|
}
|
|
|
|
func (p timestampProcessor) Enabled(context.Context, Record) bool {
|
|
return true
|
|
}
|
|
|
|
func (p timestampProcessor) Shutdown(ctx context.Context) error {
|
|
return nil
|
|
}
|
|
|
|
func (p timestampProcessor) ForceFlush(ctx context.Context) error {
|
|
return nil
|
|
}
|
|
|
|
type attrAddProcessor struct{}
|
|
|
|
func (p attrAddProcessor) OnEmit(ctx context.Context, r *Record) error {
|
|
r.AddAttributes(log.String("add", "me"))
|
|
return nil
|
|
}
|
|
|
|
func (p attrAddProcessor) Enabled(context.Context, Record) bool {
|
|
return true
|
|
}
|
|
|
|
func (p attrAddProcessor) Shutdown(ctx context.Context) error {
|
|
return nil
|
|
}
|
|
|
|
func (p attrAddProcessor) ForceFlush(ctx context.Context) error {
|
|
return nil
|
|
}
|
|
|
|
type attrSetDecorator struct{}
|
|
|
|
func (p attrSetDecorator) OnEmit(ctx context.Context, r *Record) error {
|
|
r.SetAttributes(log.String("replace", "me"))
|
|
return nil
|
|
}
|
|
|
|
func (p attrSetDecorator) Enabled(context.Context, Record) bool {
|
|
return true
|
|
}
|
|
|
|
func (p attrSetDecorator) Shutdown(ctx context.Context) error {
|
|
return nil
|
|
}
|
|
|
|
func (p attrSetDecorator) ForceFlush(ctx context.Context) error {
|
|
return nil
|
|
}
|