มาเริ่มต้นใช้งาน tracing กับ OpenTelemetry ด้วย Go

OpenTelemetry เป็นโครงการเพื่อช่วยจัดการเรื่อง tracing กับ metrics และทำให้ application ไม่เกิด vendor lock-in กับระบบ tracing หรือ metrics เจ้าใดเจ้านึง ซึ่งโครงการนี้ต่อยอดมาจาก OpenTracing กับ OpenCensus และทำตามมาตรฐาน W3 Tracing Context (ผมยังไม่ได้อ่านรายละเอียดของ Tracing Context มากเท่าไหร่ เดี๋ยวว่างๆ ค่อยมาสรุปอีกที)

เจ้าตัว OpenTelemetry เองก็ support programming language หลายภาษาอยู่เหมือน เช่น Go, Java, Python, Erlang, Rust เป็นต้น โดยในบล็อคนี้จะเน้น Go และการทำ tracing เป็นหลัก (ภาษาอื่นเขียนไม่เป็น 555)

ขั้นแรกสร้าง module

$ mkdir otel-todo
$ cd otel-todo && go mod init github.com/wingyplus/otel-todo
go: creating new go.mod: module github.com/wingyplus/otel-todo

ทำการ initialize tracing

ในการ initialize tracing นั้นจะมีสามขั้นตอน ขั้นแรกคือสร้าง exporter เพื่อบอก OpenTelemetry ว่าจะ export trace ไปที่ระบบไหน ซึ่งตอนนี้ opentelemetry-go ซัพพอร์ตแค่สามระบบ

1. stdout ง่ายๆ คือ print ออก stdout ในรูปแบบ json format
2. jaeger เป็นระบบ distributed tracing ของ Uber
3. stackdriver ของ Google Cloud

ตอนนี้เราจะเริ่มง่ายๆ ด้วยการใช้ stdout ก่อน

// main.go
package main

import (
    "log"

    "go.opentelemetry.io/otel/exporter/trace/stdout"
)

func initTrace() {
    exporter, err := stdout.NewExporter(stdout.Options{PrettyPrint: true})
    if err != nil {
        log.Fatalf("have some errors while creating stdout exporter: %v", err)
    }

    // ...
}

ต่อมาทำการสร้าง provider เพื่อบอกความถี่ในการ sync trace ไปหา exporter

import (
    // ...
    sdktrace "go.opentelemetry.io/otel/sdk/trace"
)


// in initTrace().
provider, err := sdktrace.NewProvider(
    sdktrace.WithConfig(sdktrace.Config{DefaultSampler: sdktrace.AlwaysSample()}),
    sdktrace.WithSyncer(exporter),
)
if err != nil {
    log.Fatalf("have some problems while creating provider: %v", err)
}

ในตัวอย่างข้างบนนั้นผมใส่เป็น AlwaysSample() เพื่อเอาทุก trace ที่เกิดขึ้นในระบบ

ขั้นตอนสุดท้ายทำการ set provider เข้าไปที่ package global

import (
    // ...
    "go.opentelemetry.io/otel/api/global"
)

// in initTrace().
global.SetTraceProvider(provider)

ใช้งาน tracing

ขั้นแรกทำการดึง provider ออกมาจาก global

func main() {
    initTrace()

    tracer := global.TraceProvider().Tracer("github.com/wingyplus/basic")
}

จากนั้นทำการสร้าง span ด้วย tracer.WithSpan

// in main().
tracer.WithSpan(context.Background(), "foo", func(ctx context.Context) error {
    return nil
})

ลองทดสอบการทำงานด้วย go run

$ go run .
{
        "SpanContext": {
                "TraceID": "5883cc5d9604907026cf1cc8f651206a",
                "SpanID": "73ebe6c408d24147",
                "TraceFlags": 1
        },
        "ParentSpanID": "0000000000000000",
        "SpanKind": 1,
        "Name": "github.com/wingyplus/basic/foo",
        "StartTime": "2020-02-09T19:10:49.844055+07:00",
        "EndTime": "2020-02-09T19:10:49.844060721+07:00",
        "Attributes": null,
        "MessageEvents": null,
        "Links": null,
        "Status": 0,
        "HasRemoteParent": false,
        "DroppedAttributeCount": 0,
        "DroppedMessageEventCount": 0,
        "DroppedLinkCount": 0,
        "ChildSpanCount": 0
}

เราสามารถสร้าง span ภายใน WithSpan ได้อีกโดยใช้ context ของ WithSpan ที่เป็นตัว root เช่น

tracer.WithSpan(context.Background(), "foo", func(ctx context.Context) error {
    tracer.WithSpan(ctx, "bar", func(ctx context.Context) error {
        return nil
    })
    return nil
})

ถ้าลองรันดู จะเห็นว่าจะมีสอง span เกิดขึ้นมา

$ go run .
{
    "SpanContext": {
        "TraceID": "58e32b2438efda4d90db7b0ce0db9371",
        "SpanID": "040c29233e95fca5",
        "TraceFlags": 1
    },
    "ParentSpanID": "8fc213b9e9b84a98",
    "SpanKind": 1,
    "Name": "github.com/wingyplus/basic/bar",
    "StartTime": "2020-02-09T19:13:36.753668+07:00",
    "EndTime": "2020-02-09T19:13:36.75367142+07:00",
    "Attributes": null,
    "MessageEvents": null,
    "Links": null,
    "Status": 0,
    "HasRemoteParent": false,
    "DroppedAttributeCount": 0,
    "DroppedMessageEventCount": 0,
    "DroppedLinkCount": 0,
    "ChildSpanCount": 0
}
{
    "SpanContext": {
        "TraceID": "58e32b2438efda4d90db7b0ce0db9371",
        "SpanID": "8fc213b9e9b84a98",
        "TraceFlags": 1
    },
    "ParentSpanID": "0000000000000000",
    "SpanKind": 1,
    "Name": "github.com/wingyplus/basic/foo",
    "StartTime": "2020-02-09T19:13:36.753663+07:00",
    "EndTime": "2020-02-09T19:13:36.754156451+07:00",
    "Attributes": null,
    "MessageEvents": null,
    "Links": null,
    "Status": 0,
    "HasRemoteParent": false,
    "DroppedAttributeCount": 0,
    "DroppedMessageEventCount": 0,
    "DroppedLinkCount": 0,
    "ChildSpanCount": 1
}

จะสังเกตเห็นว่า span ที่มีชื่อว่า "github.com/wingyplus/basic/bar" จะมี parent เป็น "8fc213b9e9b84a98" ซึ่งเป็น span id ที่อยู่ใน SpanContext ของ span ที่ชื่อ "github.com/wingyplus/basic/foo"

ที่นี่ลองหน่วงการทำงานของ span ดู

// in main().
tracer.WithSpan(context.Background(), "foo", func(ctx context.Context) error {
    time.Sleep(3 * time.Second)
    tracer.WithSpan(ctx, "bar", func(ctx context.Context) error {
        time.Sleep(5 * time.Second)
        return nil
    })
    return nil
})

$ go run .
{
    "SpanContext": {
        "TraceID": "cbbff287daac4270963300393e1122f4",
        "SpanID": "6a7e00be07802205",
        "TraceFlags": 1
    },
    "ParentSpanID": "a7afe9f612e34427",
    "SpanKind": 1,
    "Name": "github.com/wingyplus/basic/bar",
    "StartTime": "2020-02-09T19:16:30.103175+07:00",
    "EndTime": "2020-02-09T19:16:35.106123127+07:00",
    "Attributes": null,
    "MessageEvents": null,
    "Links": null,
    "Status": 0,
    "HasRemoteParent": false,
    "DroppedAttributeCount": 0,
    "DroppedMessageEventCount": 0,
    "DroppedLinkCount": 0,
    "ChildSpanCount": 0
}
{
    "SpanContext": {
        "TraceID": "cbbff287daac4270963300393e1122f4",
        "SpanID": "a7afe9f612e34427",
        "TraceFlags": 1
    },
    "ParentSpanID": "0000000000000000",
    "SpanKind": 1,
    "Name": "github.com/wingyplus/basic/foo",
    "StartTime": "2020-02-09T19:16:27.102542+07:00",
    "EndTime": "2020-02-09T19:16:35.107031106+07:00",
    "Attributes": null,
    "MessageEvents": null,
    "Links": null,
    "Status": 0,
    "HasRemoteParent": false,
    "DroppedAttributeCount": 0,
    "DroppedMessageEventCount": 0,
    "DroppedLinkCount": 0,
    "ChildSpanCount": 1
}

จะเห็นว่า span "github.com/wingyplus/basic/foo" จะมี start time กับ end time ห่างกันประมาณ 8 วินาที เพราะ span "github.com/wingyplus/basic/bar" ใช้เวลา 5 วินาทีนั่นเอง