Skip to content

Commit

Permalink
Write prototype implementation and benchmarks
Browse files Browse the repository at this point in the history
  • Loading branch information
@pellared
pellared committed Nov 24, 2023
1 parent 2704436 commit a718f69
Show file tree
Hide file tree
Showing 12 changed files with 659 additions and 103 deletions.
77 changes: 4 additions & 73 deletions log/DESIGN.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -43,78 +43,12 @@ type LoggerProvider interface{
### Logger

The [`Logger` abstraction](https://opentelemetry.io/docs/specs/otel/logs/bridge-api/#logger)
is defined as an interface.

```go
type Logger interface{
embedded.Logger
Emit(ctx context.Context, record Record)
}
```
is defined as an interface in [logger.go](logger.go).

### Record

The [`LogRecord` abstraction](https://opentelemetry.io/docs/specs/otel/logs/bridge-api/#logger)
is defined as a struct.

```go
type Record struct {
Timestamp time.Time
ObservedTimestamp time.Time
Severity Severity
SeverityText string
Body string

// The fields below are for optimizing the implementation of
// Attributes and AddAttributes.

// Allocation optimization: an inline array sized to hold
// the majority of log calls (based on examination of open-source
// code). It holds the start of the list of attributes.
front [nAttrsInline]attribute.KeyValue

// The number of attributes in front.
nFront int

// The list of attributes except for those in front.
// Invariants:
// - len(back) > 0 iff nFront == len(front)
// - Unused array elements are zero. Used to detect mistakes.
back []attribute.KeyValue
}

const nAttrsInline = 5

type Severity int

const (
SeverityUndefined Severity = iota
SeverityTrace
SeverityTrace2
SeverityTrace3
SeverityTrace4
SeverityDebug
SeverityDebug2
SeverityDebug3
SeverityDebug4
SeverityInfo
SeverityInfo2
SeverityInfo3
SeverityInfo4
SeverityWarn
SeverityWarn2
SeverityWarn3
SeverityWarn4
SeverityError
SeverityError2
SeverityError3
SeverityError4
SeverityFatal
SeverityFatal2
SeverityFatal3
SeverityFatal4
)
```
is defined as a struct in [record.go](record.go).

`Record` has `Attributes` and `AddAttributes` methods,
like [`slog.Record.Attrs`](https://pkg.go.dev/log/slog#Record.Attrs)
Expand All @@ -133,18 +67,15 @@ naive implementation.
```go
type handler struct {
logger log.Logger
level slog.Level
attrs []attribute.KeyValue
prefix string
}

func (h *handler) Handle(ctx context.Context, r slog.Record) error {
lvl := convertLevel(r.Level)

record := Record{Timestamp: r.Time, Severity: lvl, Body: r.Message}

if r.NumAttrs() > 5 {
attrs := make([]attribute.KeyValue, 0, len(r.NumAttrs()))
if r.AttributesLen() > 5 {
attrs := make([]attribute.KeyValue, 0, len(r.AttributesLen()))
r.Attrs(func(a slog.Attr) bool {
attrs = append(attrs, convertAttr(a))
return true
Expand Down
30 changes: 0 additions & 30 deletions log/bench_test.go
View file

This file was deleted.

170 changes: 170 additions & 0 deletions log/benchmark/bench_test.go
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,170 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0

// Copyright 2022 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package benchmark

import (
"context"
"io"
"testing"
"time"

"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/log"
"go.opentelemetry.io/otel/log/noop"
)

var (
ctx = context.Background()
testTimestamp = time.Date(1988, time.November, 17, 0, 0, 0, 0, time.UTC)
testBody = "log message"
testSeverity = log.SeverityInfo
testFloat = 1.2345
testString = "7e3b3b2aaeff56a7108fe11e154200dd/7819479873059528190"
testInt = 32768
testBool = true
)

// These benchmarks are based on slog/internal/benchmarks.
//
// They test a complete log record, from the user's call to its return.
//
// WriterLogger is an optimistic version of a real logger, doing real-world
// tasks as fast as possible . This gives us an upper bound
// on handler performance, so we can evaluate the (logger-independent) core
// activity of the package in an end-to-end context without concern that a
// slow logger implementation is skewing the results. The writerLogger
// allocates memory only when using strconv.
func BenchmarkEmit(b *testing.B) {
for _, tc := range []struct {
name string
logger log.Logger
}{
{"noop", noop.Logger{}},
{"writer", &writerLogger{w: io.Discard}},
} {
b.Run(tc.name, func(b *testing.B) {
for _, call := range []struct {
name string
f func()
}{
{
"no attrs",
func() {
r := log.Record{Timestamp: testTimestamp, Severity: testSeverity, Body: testBody}
tc.logger.Emit(ctx, r)
},
},
{
"3 attrs",
func() {
r := log.Record{Timestamp: testTimestamp, Severity: testSeverity, Body: testBody}
r.AddAttributes(
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
)
tc.logger.Emit(ctx, r)
},
},
{
// The number should match nAttrsInline in record.go.
// This should exercise the code path where no allocations
// happen in Record or Attr. If there are allocations, they
// should only be from strconv used in writerLogger.
"5 attrs",
func() {
r := log.Record{Timestamp: testTimestamp, Severity: testSeverity, Body: testBody}
r.AddAttributes(
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
)
tc.logger.Emit(ctx, r)
},
},
{
"10 attrs",
func() {
r := log.Record{Timestamp: testTimestamp, Severity: testSeverity, Body: testBody}
r.AddAttributes(
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
)
tc.logger.Emit(ctx, r)
},
},
{
"40 attrs",
func() {
r := log.Record{Timestamp: testTimestamp, Severity: testSeverity, Body: testBody}
r.AddAttributes(
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
attribute.String("string", testString),
attribute.Float64("float", testFloat),
attribute.Int("int", testInt),
attribute.Bool("bool", testBool),
attribute.String("string", testString),
)
tc.logger.Emit(ctx, r)
},
},
} {
b.Run(call.name, func(b *testing.B) {
b.ReportAllocs()
for i := 0; i < b.N; i++ {
call.f()
}
})
}
})
}
}
67 changes: 67 additions & 0 deletions log/benchmark/impl.go
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,67 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0

// Copyright 2022 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package benchmark

import (
"context"
"fmt"
"io"
"strconv"

"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/log"
"go.opentelemetry.io/otel/log/embedded"
)

// writerLogger is a logger that writes to a provided io.Writer without any locking.
// It is intended to represent a high-performance logger that synchronously
// writes text.
type writerLogger struct {
embedded.Logger
w io.Writer
}

func (l *writerLogger) Emit(_ context.Context, r log.Record) {
if !r.Timestamp.IsZero() {
l.write("timestamp=")
l.write(strconv.FormatInt(r.Timestamp.Unix(), 10))
l.write(" ")
}
l.write("severity=")
l.write(strconv.FormatInt(int64(r.Severity), 10))
l.write(" ")
l.write("body=")
l.write(r.Body)
r.Attributes(func(kv attribute.KeyValue) bool {
l.write(" ")
l.write(string(kv.Key))
l.write("=")
l.appendValue(kv.Value)
return true
})
l.write("\n")
}

func (l *writerLogger) appendValue(v attribute.Value) {
switch v.Type() {
case attribute.STRING:
l.write(v.AsString())
case attribute.INT64:
l.write(strconv.FormatInt(v.AsInt64(), 10)) // strconv.FormatInt allocates memory.
case attribute.FLOAT64:
l.write(strconv.FormatFloat(v.AsFloat64(), 'g', -1, 64)) // strconv.FormatFloat allocates memory.
case attribute.BOOL:
l.write(strconv.FormatBool(v.AsBool()))
default:
panic(fmt.Sprintf("unhandled attribute type: %s", v.Type()))

Check warning on line 61 in log/benchmark/impl.go

View check run for this annotation

Codecov / codecov/patch

log/benchmark/impl.go#L60-L61 

Added lines #L60 - L61 were not covered by tests
}
}

func (l *writerLogger) write(s string) {
_, _ = io.WriteString(l.w, s)
}
Loading

0 comments on commit a718f69

Please sign in to comment.