Skip to content

Commit

Permalink
chore: first metric (verb call counter) (#2130)
Browse files Browse the repository at this point in the history
Instrument our first metric. Next: check if this metric pipes through to
DD correctly.

Locally, the output via `just otel-stream` looks like:
```
ScopeMetrics #1
ScopeMetrics SchemaURL: 
InstrumentationScope ftl.call 

Metric #0
Descriptor:
     -> Name: requests
     -> Description: Count of FTL verb calls via the controller
     -> Unit: 
     -> DataType: Sum
     -> IsMonotonic: true
     -> AggregationTemporality: Cumulative

NumberDataPoints #0
Data point attributes:
     -> ftl.module.name: Str(time)
     -> ftl.verb.name: Str(time)
StartTimestamp: 2024-07-23 00:25:50.782759 +0000 UTC
Timestamp: 2024-07-23 00:25:59.069408 +0000 UTC
Value: 1

NumberDataPoints #1
Data point attributes:
     -> ftl.module.name: Str(echo)
     -> ftl.verb.name: Str(echo)
StartTimestamp: 2024-07-23 00:25:50.782759 +0000 UTC
Timestamp: 2024-07-23 00:25:59.069408 +0000 UTC
Value: 1
	{"kind": "exporter", "data_type": "metrics", "name": "debug"}
2024-07-23T00:26:00.745Z	info	MetricsExporter	{"kind": "exporter", "data_type": "metrics", "name": "debug", "resource metrics": 1, "metrics": 10, "data points": 15}
2024-07-23
T00:26:00.745Z	info	ResourceMetrics #0
Resource SchemaURL: https://opentelemetry.io/schemas/1.25.0
Resource attributes:
     -> service.name: Str(echo)
     -> service.version: Str(HEAD)
     -> telemetry.sdk.language: Str(go)
     -> telemetry.sdk.name: Str(opentelemetry)
     -> telemetry.sdk.version: Str(1.27.0)
```

Interestingly, it looks like the metric logging races in a slightly
inconsistent way. If you call a verb that calls another verb, you would
expect just one verb to get bumped to 1 first, and then the other verb.
Sometimes, it does behave that way. However, other times, the first time
it appears in `otel-stream` _will already_ be with both verbs. So
essentially, there is no guarantee that transient values actually show
up in the stream, but the ultimate value will be correct.

This does appear the report the correct count in even error cases. e.g.
I tried calling `echo` before the deploy was done, so that the verb call
would fail without calling out to `time`. It would correctly log a
single call in that case. And if you made another successful call
afterwards, the metric would correctly increment to include both
successful calls.
  • Loading branch information
deniseli authored Jul 23, 2024
1 parent c5635ba commit c9b430c
Show file tree
Hide file tree
Showing 3 changed files with 18 additions and 1 deletion.
2 changes: 2 additions & 0 deletions Justfile
Original file line number Diff line number Diff line change
Expand Up @@ -223,4 +223,6 @@ otel-dev *args:

grpcPort=$(cat docker-compose.yml | grep "OTLP gRPC" | sed 's/:.*//' | sed -r 's/ +- //')
export OTEL_EXPORTER_OTLP_ENDPOINT="http://localhost:${grpcPort}"
# Uncomment this line for much richer debug logs
# export FTL_O11Y_LOG_LEVEL="debug"
ftl dev {{args}}
15 changes: 15 additions & 0 deletions backend/controller/controller.go
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,9 @@ import (
"github.com/jackc/pgx/v5/pgxpool"
"github.com/jellydator/ttlcache/v3"
"github.com/jpillora/backoff"
"go.opentelemetry.io/otel"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/metric"
"golang.org/x/exp/maps"
"golang.org/x/sync/errgroup"
"google.golang.org/protobuf/proto"
Expand Down Expand Up @@ -930,6 +933,18 @@ func (s *Service) callWithRequest(
sourceAddress string,
) (*connect.Response[ftlv1.CallResponse], error) {
start := time.Now()

logger := log.FromContext(ctx)

requestCounter, err := otel.GetMeterProvider().Meter("ftl.call").Int64Counter(
"requests",
metric.WithDescription("Count of FTL verb calls via the controller"))
if err != nil {
logger.Errorf(err, "Failed to instrument otel metric `ftl.call.requests`")
} else {
requestCounter.Add(ctx, 1, metric.WithAttributes(attribute.String("ftl.module.name", req.Msg.Verb.Module), attribute.String("ftl.verb.name", req.Msg.Verb.Name)))
}

if req.Msg.Verb == nil {
return nil, connect.NewError(connect.CodeInvalidArgument, errors.New("verb is required"))
}
Expand Down
2 changes: 1 addition & 1 deletion internal/observability/client.go
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,7 @@ func Init(ctx context.Context, serviceName, serviceVersion string, config Config
return nil
}

logger.Debugf("OTEL is enabled, exporting to %s", os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT"))
logger.Debugf("OTEL is enabled, exporting to %s at log level %s", os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT"), os.Getenv("FTL_O11Y_LOG_LEVEL"))

otelLogger := NewOtelLogger(logger, config.LogLevel)
otel.SetLogger(otelLogger)
Expand Down

0 comments on commit c9b430c

Please sign in to comment.