Introduction to Tracing in Effect

On this page

Although logs and metrics are useful to understand the behavior of individual services, they are not enough to provide a complete overview of the lifetime of a request in a distributed system.

In a distributed system, a request can span multiple services and each service can make multiple requests to other services to fulfill the request. In such a scenario, we need to have a way to track the lifetime of a request across multiple services to diagnose what services are the bottlenecks and where the request is spending most of its time.

Spans

A span represents a unit of work or operation. It tracks specific operations that a request makes, painting a picture of what happened during the time in which that operation was executed.

A typical Span contains the following information:

  • Name: Describes the operation being tracked.

  • Time-Related Data: Timestamps to measure when the operation started and how long it took.

  • Structured Log Messages: Records essential information during the operation.

  • Metadata (Attributes): Additional data that provides context about the operation.

Traces

A trace records the paths taken by requests (made by an application or end-user) as they propagate through multi-service architectures, like microservice and serverless applications.

Without tracing, it is challenging to pinpoint the cause of performance problems in a distributed system.

A trace is made of one or more spans. The first span represents the root span. Each root span represents a request from start to finish. The spans underneath the parent provide a more in-depth context of what occurs during a request (or what steps make up a request).

Many Observability back-ends visualize traces as waterfall diagrams that may look something like this:

Sample Trace

Waterfall diagrams show the parent-child relationship between a root span and its child spans. When a span encapsulates another span, this also represents a nested relationship.

Creating Spans

You can instrument an effect with a Span using the Effect.withSpan API. Here's how you can do it:

ts
import { Effect } from "effect"
 
const program = Effect.void.pipe(Effect.delay("100 millis"))
 
const instrumented = program.pipe(Effect.withSpan("myspan"))
ts
import { Effect } from "effect"
 
const program = Effect.void.pipe(Effect.delay("100 millis"))
 
const instrumented = program.pipe(Effect.withSpan("myspan"))

It's important to note that instrumenting an effect doesn't change its type. You start with an Effect<void>, and you still get an Effect<void>.

Printing Spans

Now, let's print our Span to the console. To achieve this, we need specific tools, including

  • @effect/opentelemetry
  • @opentelemetry/sdk-metrics
  • @opentelemetry/sdk-trace-base
  • @opentelemetry/sdk-trace-node
  • @opentelemetry/sdk-trace-web

With these in place, we can visualize and understand the Spans in our application.

Here's a code snippet demonstrating how to set up the necessary environment and print the Span to the console:

ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const program = Effect.void.pipe(Effect.delay("100 millis"))
 
const instrumented = program.pipe(Effect.withSpan("myspan"))
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromise(instrumented.pipe(Effect.provide(NodeSdkLive)))
/*
Example Output:
{
  traceId: 'd0f730abfc366205806469596092b239',
  parentId: undefined,
  traceState: undefined,
  name: 'myspan',
  id: 'ab4e42592e7f1f7c',
  kind: 0,
  timestamp: 1697040012664380.5,
  duration: 2895.769,
  attributes: {},
  status: { code: 1 },
  events: [],
  links: []
}
*/
ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const program = Effect.void.pipe(Effect.delay("100 millis"))
 
const instrumented = program.pipe(Effect.withSpan("myspan"))
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromise(instrumented.pipe(Effect.provide(NodeSdkLive)))
/*
Example Output:
{
  traceId: 'd0f730abfc366205806469596092b239',
  parentId: undefined,
  traceState: undefined,
  name: 'myspan',
  id: 'ab4e42592e7f1f7c',
  kind: 0,
  timestamp: 1697040012664380.5,
  duration: 2895.769,
  attributes: {},
  status: { code: 1 },
  events: [],
  links: []
}
*/

Here's a breakdown of the output:

FieldDescription
traceIdA unique identifier for the entire trace, helping trace requests or operations as they move through an application.
parentIdIdentifies the parent span of the current span, marked as undefined in the output when there is no parent span, making it a root span.
nameDescribes the name of the span, indicating the operation being tracked (e.g., "myspan").
idA unique identifier for the current span, distinguishing it from other spans within a trace.
timestampA timestamp representing when the span started, measured in microseconds since the Unix epoch.
durationSpecifies the duration of the span, representing the time taken to complete the operation (e.g., 2895.769 microseconds).
attributesSpans may contain attributes, which are key-value pairs providing additional context or information about the operation. In this output, it's an empty object, indicating no specific attributes in this span.
statusThe status field provides information about the span's status. In this case, it has a code of 1, which typically indicates an OK status (whereas a code of 2 signifies an ERROR status)
eventsSpans can include events, which are records of specific moments during the span's lifecycle. In this output, it's an empty array, suggesting no specific events recorded.
linksLinks can be used to associate this span with other spans in different traces. In the output, it's an empty array, indicating no specific links for this span.

Let's examine the output of an effect that encountered an error:

ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const program = Effect.fail("Oh no!").pipe(
  Effect.delay("100 millis"),
  Effect.withSpan("myspan")
)
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromiseExit(program.pipe(Effect.provide(NodeSdkLive))).then(
  console.log
)
/*
Example Output:
{
  traceId: '760510a3f9a0881a09de990c87ec1cef',
  parentId: undefined,
  traceState: undefined,
  name: 'myspan',
  id: 'a528e38e82e848a5',
  kind: 0,
  timestamp: 1697091363002970.5,
  duration: 110371.664,
  attributes: {},
  status: { code: 2, message: 'Error: Oh no!' },
  events: [],
  links: []
}
{
  _id: 'Exit',
  _tag: 'Failure',
  cause: { _id: 'Cause', _tag: 'Fail', failure: 'Oh no!' }
}
*/
ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const program = Effect.fail("Oh no!").pipe(
  Effect.delay("100 millis"),
  Effect.withSpan("myspan")
)
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromiseExit(program.pipe(Effect.provide(NodeSdkLive))).then(
  console.log
)
/*
Example Output:
{
  traceId: '760510a3f9a0881a09de990c87ec1cef',
  parentId: undefined,
  traceState: undefined,
  name: 'myspan',
  id: 'a528e38e82e848a5',
  kind: 0,
  timestamp: 1697091363002970.5,
  duration: 110371.664,
  attributes: {},
  status: { code: 2, message: 'Error: Oh no!' },
  events: [],
  links: []
}
{
  _id: 'Exit',
  _tag: 'Failure',
  cause: { _id: 'Cause', _tag: 'Fail', failure: 'Oh no!' }
}
*/

Adding Annotations

You can provide extra information to a span by utilizing the Effect.annotateCurrentSpan function. This tool allows you to associate key-value pairs, offering more context about the execution of the span.

ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const program = Effect.void.pipe(
  Effect.delay("100 millis"),
  Effect.tap(() => Effect.annotateCurrentSpan("key", "value")),
  Effect.withSpan("myspan")
)
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromise(program.pipe(Effect.provide(NodeSdkLive)))
/*
Example Output:
{
  traceId: '869c9d74d9db14a4ba4393ca8e0f61db',
  parentId: undefined,
  traceState: undefined,
  name: 'myspan',
  id: '31eb49570d197f8d',
  kind: 0,
  timestamp: 1697045981663321.5,
  duration: 109563.353,
  attributes: { key: 'value' },
  status: { code: 1 },
  events: [],
  links: []
}
*/
ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const program = Effect.void.pipe(
  Effect.delay("100 millis"),
  Effect.tap(() => Effect.annotateCurrentSpan("key", "value")),
  Effect.withSpan("myspan")
)
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromise(program.pipe(Effect.provide(NodeSdkLive)))
/*
Example Output:
{
  traceId: '869c9d74d9db14a4ba4393ca8e0f61db',
  parentId: undefined,
  traceState: undefined,
  name: 'myspan',
  id: '31eb49570d197f8d',
  kind: 0,
  timestamp: 1697045981663321.5,
  duration: 109563.353,
  attributes: { key: 'value' },
  status: { code: 1 },
  events: [],
  links: []
}
*/

Logs as events

Logs are transformed into what are known as "Span Events." These events provide structured information and a timeline of occurrences within your application.

ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const program = Effect.log("Hello").pipe(
  Effect.delay("100 millis"),
  Effect.withSpan("myspan")
)
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromise(program.pipe(Effect.provide(NodeSdkLive)))
/*
Example Output:
{
  traceId: 'ad708d58c15f9e5c7b5cca2eeb6838a2',
  parentId: undefined,
  traceState: undefined,
  name: 'myspan',
  id: '4353fd47423e786a',
  kind: 0,
  timestamp: 1697043230170724.2,
  duration: 112052.514,
  attributes: {},
  status: { code: 1 },
  events: [
    {
      name: 'Hello',
      attributes: { 'effect.fiberId': '#0', 'effect.logLevel': 'INFO' },
      time: [ 1697043230, 280923805 ],
      droppedAttributesCount: 0
    }
  ],
  links: []
}
*/
ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const program = Effect.log("Hello").pipe(
  Effect.delay("100 millis"),
  Effect.withSpan("myspan")
)
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromise(program.pipe(Effect.provide(NodeSdkLive)))
/*
Example Output:
{
  traceId: 'ad708d58c15f9e5c7b5cca2eeb6838a2',
  parentId: undefined,
  traceState: undefined,
  name: 'myspan',
  id: '4353fd47423e786a',
  kind: 0,
  timestamp: 1697043230170724.2,
  duration: 112052.514,
  attributes: {},
  status: { code: 1 },
  events: [
    {
      name: 'Hello',
      attributes: { 'effect.fiberId': '#0', 'effect.logLevel': 'INFO' },
      time: [ 1697043230, 280923805 ],
      droppedAttributesCount: 0
    }
  ],
  links: []
}
*/

Spans can contain events, which are records of specific moments during the span's lifecycle. In this output, there is one event named 'Hello'. It includes associated attributes, such as 'effect.fiberId' and 'effect.logLevel', providing information about the logged event. The time field represents the timestamp when the event occurred.

Nesting Spans

Spans can be nested, creating a hierarchy of operations. This concept is illustrated in the following code:

ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const child = Effect.void.pipe(
  Effect.delay("100 millis"),
  Effect.withSpan("child")
)
 
const parent = Effect.gen(function* () {
  yield* Effect.sleep("20 millis")
  yield* child
  yield* Effect.sleep("10 millis")
}).pipe(Effect.withSpan("parent"))
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromise(parent.pipe(Effect.provide(NodeSdkLive)))
/*
Example Output:
{
  traceId: '92fe81f1454d9c099198568cf867dc59',
  parentId: 'b953d6c7d37ad93d',
  traceState: undefined,
  name: 'child',
  id: '2fd19c8c23ebc7e8',
  kind: 0,
  timestamp: 1697043815321888.2,
  duration: 106536.264,
  attributes: {},
  status: { code: 1 },
  events: [],
  links: []
}
{
  traceId: '92fe81f1454d9c099198568cf867dc59',
  parentId: undefined,
  traceState: undefined,
  name: 'parent',
  id: 'b953d6c7d37ad93d',
  kind: 0,
  timestamp: 1697043815292133.2,
  duration: 149724.295,
  attributes: {},
  status: { code: 1 },
  events: [],
  links: []
}
*/
ts
import { Effect } from "effect"
import { NodeSdk } from "@effect/opentelemetry"
import {
  ConsoleSpanExporter,
  BatchSpanProcessor
} from "@opentelemetry/sdk-trace-base"
 
const child = Effect.void.pipe(
  Effect.delay("100 millis"),
  Effect.withSpan("child")
)
 
const parent = Effect.gen(function* () {
  yield* Effect.sleep("20 millis")
  yield* child
  yield* Effect.sleep("10 millis")
}).pipe(Effect.withSpan("parent"))
 
const NodeSdkLive = NodeSdk.layer(() => ({
  resource: { serviceName: "example" },
  spanProcessor: new BatchSpanProcessor(new ConsoleSpanExporter())
}))
 
Effect.runPromise(parent.pipe(Effect.provide(NodeSdkLive)))
/*
Example Output:
{
  traceId: '92fe81f1454d9c099198568cf867dc59',
  parentId: 'b953d6c7d37ad93d',
  traceState: undefined,
  name: 'child',
  id: '2fd19c8c23ebc7e8',
  kind: 0,
  timestamp: 1697043815321888.2,
  duration: 106536.264,
  attributes: {},
  status: { code: 1 },
  events: [],
  links: []
}
{
  traceId: '92fe81f1454d9c099198568cf867dc59',
  parentId: undefined,
  traceState: undefined,
  name: 'parent',
  id: 'b953d6c7d37ad93d',
  kind: 0,
  timestamp: 1697043815292133.2,
  duration: 149724.295,
  attributes: {},
  status: { code: 1 },
  events: [],
  links: []
}
*/

As you can observe, the b953d6c7d37ad93d value plays a crucial role in maintaining the parent-child relationship between these spans. It provides a clear indication of how spans can be nested, creating a trace that helps developers understand the flow and hierarchy of operations in their applications.

Tutorial: Visualizing Traces with Docker, Prometheus, Grafana, and Tempo

In this tutorial, we'll guide you through simulating and visualizing traces using a sample instrumented Node.js application. We will use Docker, Prometheus, Grafana, and Tempo to create, collect, and visualize traces.

Tools Explained

Let's understand the tools we'll be using in simple terms:

  • Docker: Docker allows us to run applications in containers. Think of a container as a lightweight and isolated environment where your application can run consistently, regardless of the host system. It's a bit like a virtual machine but more efficient.

  • Prometheus: Prometheus is a monitoring and alerting toolkit. It collects metrics and data about your applications and stores them for further analysis. This helps in identifying performance issues and understanding the behavior of your applications.

  • Grafana: Grafana is a visualization and analytics platform. It helps in creating beautiful and interactive dashboards to visualize your application's data. You can use it to graphically represent metrics collected by Prometheus.

  • Tempo: Tempo is a distributed tracing system that allows you to trace the journey of a request as it flows through your application. It provides insights into how requests are processed and helps in debugging and optimizing your applications.

Getting Docker

To get Docker, follow these steps:

  1. Visit the Docker website at https://www.docker.com/.

  2. Download Docker Desktop for your operating system (Windows or macOS) and install it.

  3. After installation, open Docker Desktop, and it will run in the background.

Simulating Traces

Now, let's simulate traces using a sample Node.js application. We'll provide you with the code and guide you on setting up the necessary components.

  1. Download Docker Files. Download the required Docker files: docker.zip.

  2. Set Up docker. Unzip the downloaded file, navigate to the /docker/local directory in your terminal or command prompt and run the following command to start the necessary services:

    Terminal
    bash
    docker-compose up
    Terminal
    bash
    docker-compose up

  3. Simulate Traces. Run the following example code in your Node.js environment. This code simulates a set of tasks and generates traces.

    Before proceeding, you'll need to install additional libraries in addition to the latest version of effect. Here are the required libraries:

    • @effect/opentelemetry
    • @opentelemetry/exporter-trace-otlp-http
    • @opentelemetry/sdk-trace-node
    • @opentelemetry/sdk-trace-web
    ts
    import { Effect } from "effect"
    import { NodeSdk } from "@effect/opentelemetry"
    import { BatchSpanProcessor } from "@opentelemetry/sdk-trace-base"
    import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http"
     
    // Function to simulate a task with possible subtasks
    const task = (
      name: string,
      delay: number,
      children: ReadonlyArray<Effect.Effect<void>> = []
    ) =>
      Effect.gen(function* () {
        yield* Effect.log(name)
        yield* Effect.sleep(`${delay} millis`)
        for (const child of children) {
          yield* child
        }
        yield* Effect.sleep(`${delay} millis`)
      }).pipe(Effect.withSpan(name))
     
    const poll = task("/poll", 1)
     
    // Create a program with tasks and subtasks
    const program = task("client", 2, [
      task("/api", 3, [
        task("/authN", 4, [task("/authZ", 5)]),
        task("/payment Gateway", 6, [task("DB", 7), task("Ext. Merchant", 8)]),
        task("/dispatch", 9, [
          task("/dispatch/search", 10),
          Effect.all([poll, poll, poll], { concurrency: "inherit" }),
          task("/pollDriver/{id}", 11)
        ])
      ])
    ])
     
    const NodeSdkLive = NodeSdk.layer(() => ({
      resource: { serviceName: "example" },
      spanProcessor: new BatchSpanProcessor(new OTLPTraceExporter())
    }))
     
    Effect.runPromise(
      program.pipe(
        Effect.provide(NodeSdkLive),
        Effect.catchAllCause(Effect.logError)
      )
    )
    /*
    Output:
    timestamp=... level=INFO fiber=#0 message=client
    timestamp=... level=INFO fiber=#0 message=/api
    timestamp=... level=INFO fiber=#0 message=/authN
    timestamp=... level=INFO fiber=#0 message=/authZ
    timestamp=... level=INFO fiber=#0 message="/payment Gateway"
    timestamp=... level=INFO fiber=#0 message=DB
    timestamp=... level=INFO fiber=#0 message="Ext. Merchant"
    timestamp=... level=INFO fiber=#0 message=/dispatch
    timestamp=... level=INFO fiber=#0 message=/dispatch/search
    timestamp=... level=INFO fiber=#3 message=/poll
    timestamp=... level=INFO fiber=#4 message=/poll
    timestamp=... level=INFO fiber=#5 message=/poll
    timestamp=... level=INFO fiber=#0 message=/pollDriver/{id}
    */
    ts
    import { Effect } from "effect"
    import { NodeSdk } from "@effect/opentelemetry"
    import { BatchSpanProcessor } from "@opentelemetry/sdk-trace-base"
    import { OTLPTraceExporter } from "@opentelemetry/exporter-trace-otlp-http"
     
    // Function to simulate a task with possible subtasks
    const task = (
      name: string,
      delay: number,
      children: ReadonlyArray<Effect.Effect<void>> = []
    ) =>
      Effect.gen(function* () {
        yield* Effect.log(name)
        yield* Effect.sleep(`${delay} millis`)
        for (const child of children) {
          yield* child
        }
        yield* Effect.sleep(`${delay} millis`)
      }).pipe(Effect.withSpan(name))
     
    const poll = task("/poll", 1)
     
    // Create a program with tasks and subtasks
    const program = task("client", 2, [
      task("/api", 3, [
        task("/authN", 4, [task("/authZ", 5)]),
        task("/payment Gateway", 6, [task("DB", 7), task("Ext. Merchant", 8)]),
        task("/dispatch", 9, [
          task("/dispatch/search", 10),
          Effect.all([poll, poll, poll], { concurrency: "inherit" }),
          task("/pollDriver/{id}", 11)
        ])
      ])
    ])
     
    const NodeSdkLive = NodeSdk.layer(() => ({
      resource: { serviceName: "example" },
      spanProcessor: new BatchSpanProcessor(new OTLPTraceExporter())
    }))
     
    Effect.runPromise(
      program.pipe(
        Effect.provide(NodeSdkLive),
        Effect.catchAllCause(Effect.logError)
      )
    )
    /*
    Output:
    timestamp=... level=INFO fiber=#0 message=client
    timestamp=... level=INFO fiber=#0 message=/api
    timestamp=... level=INFO fiber=#0 message=/authN
    timestamp=... level=INFO fiber=#0 message=/authZ
    timestamp=... level=INFO fiber=#0 message="/payment Gateway"
    timestamp=... level=INFO fiber=#0 message=DB
    timestamp=... level=INFO fiber=#0 message="Ext. Merchant"
    timestamp=... level=INFO fiber=#0 message=/dispatch
    timestamp=... level=INFO fiber=#0 message=/dispatch/search
    timestamp=... level=INFO fiber=#3 message=/poll
    timestamp=... level=INFO fiber=#4 message=/poll
    timestamp=... level=INFO fiber=#5 message=/poll
    timestamp=... level=INFO fiber=#0 message=/pollDriver/{id}
    */

  4. Visualize Traces. Now, open your web browser and go to http://localhost:3000/explore. You will see a generated Trace ID on the web page. Click on it to see the details of the trace.

    Traces in Grafana Tempo

That's it! You've simulated and visualized traces using Docker, Prometheus, Grafana, and Tempo. You can use these tools to monitor, analyze, and gain insights into your applications' performance and behavior.