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:
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"constprogram =Effect .void .pipe (Effect .delay ("100 millis"))constinstrumented =program .pipe (Effect .withSpan ("myspan"))
ts
import {Effect } from "effect"constprogram =Effect .void .pipe (Effect .delay ("100 millis"))constinstrumented =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"constprogram =Effect .void .pipe (Effect .delay ("100 millis"))constinstrumented =program .pipe (Effect .withSpan ("myspan"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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"constprogram =Effect .void .pipe (Effect .delay ("100 millis"))constinstrumented =program .pipe (Effect .withSpan ("myspan"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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:
Field | Description |
---|---|
traceId | A unique identifier for the entire trace, helping trace requests or operations as they move through an application. |
parentId | Identifies the parent span of the current span, marked as undefined in the output when there is no parent span, making it a root span. |
name | Describes the name of the span, indicating the operation being tracked (e.g., "myspan"). |
id | A unique identifier for the current span, distinguishing it from other spans within a trace. |
timestamp | A timestamp representing when the span started, measured in microseconds since the Unix epoch. |
duration | Specifies the duration of the span, representing the time taken to complete the operation (e.g., 2895.769 microseconds). |
attributes | Spans 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. |
status | The 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) |
events | Spans 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. |
links | Links 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"constprogram =Effect .fail ("Oh no!").pipe (Effect .delay ("100 millis"),Effect .withSpan ("myspan"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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"constprogram =Effect .fail ("Oh no!").pipe (Effect .delay ("100 millis"),Effect .withSpan ("myspan"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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"constprogram =Effect .void .pipe (Effect .delay ("100 millis"),Effect .tap (() =>Effect .annotateCurrentSpan ("key", "value")),Effect .withSpan ("myspan"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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"constprogram =Effect .void .pipe (Effect .delay ("100 millis"),Effect .tap (() =>Effect .annotateCurrentSpan ("key", "value")),Effect .withSpan ("myspan"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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"constprogram =Effect .log ("Hello").pipe (Effect .delay ("100 millis"),Effect .withSpan ("myspan"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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"constprogram =Effect .log ("Hello").pipe (Effect .delay ("100 millis"),Effect .withSpan ("myspan"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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"constchild =Effect .void .pipe (Effect .delay ("100 millis"),Effect .withSpan ("child"))constparent =Effect .gen (function* (_ ) {yield*_ (Effect .sleep ("20 millis"))yield*_ (child )yield*_ (Effect .sleep ("10 millis"))}).pipe (Effect .withSpan ("parent"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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"constchild =Effect .void .pipe (Effect .delay ("100 millis"),Effect .withSpan ("child"))constparent =Effect .gen (function* (_ ) {yield*_ (Effect .sleep ("20 millis"))yield*_ (child )yield*_ (Effect .sleep ("10 millis"))}).pipe (Effect .withSpan ("parent"))constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newConsoleSpanExporter ())}))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:
-
Visit the Docker website at https://www.docker.com/.
-
Download Docker Desktop for your operating system (Windows or macOS) and install it.
-
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.
-
Download Docker Files. Download the required Docker files: docker.zip.
-
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:Terminalbashdocker-compose upTerminalbashdocker-compose up -
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
tsimport {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 subtasksconsttask = (name : string,delay : number,children :ReadonlyArray <Effect .Effect <void>> = []) =>Effect .gen (function* (_ ) {yield*_ (Effect .log (name ))yield*_ (Effect .sleep (`${delay } millis`))for (constchild ofchildren ) {yield*_ (child )}yield*_ (Effect .sleep (`${delay } millis`))}).pipe (Effect .withSpan (name ))constpoll =task ("/poll", 1)// Create a program with tasks and subtasksconstprogram =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)])])])constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newOTLPTraceExporter ())}))Effect .runPromise (program .pipe (Effect .provide (NodeSdkLive ),Effect .catchAllCause (Effect .logError )))/*Output:timestamp=... level=INFO fiber=#0 message=clienttimestamp=... level=INFO fiber=#0 message=/apitimestamp=... level=INFO fiber=#0 message=/authNtimestamp=... level=INFO fiber=#0 message=/authZtimestamp=... level=INFO fiber=#0 message="/payment Gateway"timestamp=... level=INFO fiber=#0 message=DBtimestamp=... level=INFO fiber=#0 message="Ext. Merchant"timestamp=... level=INFO fiber=#0 message=/dispatchtimestamp=... level=INFO fiber=#0 message=/dispatch/searchtimestamp=... level=INFO fiber=#3 message=/polltimestamp=... level=INFO fiber=#4 message=/polltimestamp=... level=INFO fiber=#5 message=/polltimestamp=... level=INFO fiber=#0 message=/pollDriver/{id}*/tsimport {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 subtasksconsttask = (name : string,delay : number,children :ReadonlyArray <Effect .Effect <void>> = []) =>Effect .gen (function* (_ ) {yield*_ (Effect .log (name ))yield*_ (Effect .sleep (`${delay } millis`))for (constchild ofchildren ) {yield*_ (child )}yield*_ (Effect .sleep (`${delay } millis`))}).pipe (Effect .withSpan (name ))constpoll =task ("/poll", 1)// Create a program with tasks and subtasksconstprogram =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)])])])constNodeSdkLive =NodeSdk .layer (() => ({resource : {serviceName : "example" },spanProcessor : newBatchSpanProcessor (newOTLPTraceExporter ())}))Effect .runPromise (program .pipe (Effect .provide (NodeSdkLive ),Effect .catchAllCause (Effect .logError )))/*Output:timestamp=... level=INFO fiber=#0 message=clienttimestamp=... level=INFO fiber=#0 message=/apitimestamp=... level=INFO fiber=#0 message=/authNtimestamp=... level=INFO fiber=#0 message=/authZtimestamp=... level=INFO fiber=#0 message="/payment Gateway"timestamp=... level=INFO fiber=#0 message=DBtimestamp=... level=INFO fiber=#0 message="Ext. Merchant"timestamp=... level=INFO fiber=#0 message=/dispatchtimestamp=... level=INFO fiber=#0 message=/dispatch/searchtimestamp=... level=INFO fiber=#3 message=/polltimestamp=... level=INFO fiber=#4 message=/polltimestamp=... level=INFO fiber=#5 message=/polltimestamp=... level=INFO fiber=#0 message=/pollDriver/{id}*/ -
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.
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.