มาเริ่มต้นใช้งาน tracing กับ OpenTelemetry ด้วย Go
Tags: opentelemetry, go
Published: 2020-02-09 12:19:51

OpenTelemetry เป็นโครงการเพื่อช่วยจัดการเรื่อง tracing กับ metrics และทำให้ application ไม่เกิด vendor lock-in กับระบบ tracing หรือ metrics เจ้าใดเจ้านึง ซึ่งโครงการนี้ต่อยอดมาจาก OpenTracing กับ OpenCensus และทำตามมาตรฐาน [W3 Tracing Context](https://www.w3.org/TR/trace-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 ก่อน

```go
// 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 

```go
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


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

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

## ใช้งาน tracing 

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

```go
func main() {
	initTrace()

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

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

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

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

```shell
$ 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 เช่น

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

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

```shell
$ 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 ดู


```go
// 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
})
```

```shell
$ 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 วินาทีนั่นเอง