Частая проблема при разработке распределённых систем состоит в следующем. Предположим, вы отправили системе запрос, и этот запрос обрабатывается очень долго. При этом внутри системы он распадается на запросы к нескольким внутренним микросервисам, которые могут превратиться в несколько подзапросов и выполняться параллельно. Как в этом случае определить, что тормозит систему? На помощь приходит Jaeger — сервис для сбора и отображения трейсов в распределённых системах. 

Что такое распределённая трассировка и зачем она нужна

Распределённая трассировка — диагностическая методика, позволяющая инженерам локализовать сбои и проблемы с производительностью в приложениях, особенно те, которые охватывают несколько серверов или процессов.

С точки зрения архитектуры микросервисов, один сервис отвечает за одну бизнес-возможность. Это приводит к необходимости трассировки микросервисной архитектуры, что намного сложнее, чем трассировка монолита. В монолитной архитектуре весь жизненный цикл процесса находится в одном проекте. В микросервисной архитектуре для обработки одного запроса необходимо вызвать n-количество других сервисов.

Кажется, что достаточно создать отдельный лог-сервис, который будет записывать запросы для каждой службы. Но когда API обрабатывает сотни запросов в секунду, откуда вы знаете, что один запрос лога в сервисе A соответствует логу в сервисе B и так далее?

Лучше понять поведение программного обеспечения помогает распределённая трассировка. Она показывает, где происходят сбои и что вызывает неоптимальную производительность.

Как работает трассировка

Разберём на примере Даши-путешественницы, которой дали задание добраться до замка из песка из дома на дереве. Вот карта:

Чтобы добраться до замка из песка, нужно пройти через лес, пересечь озеро и преодолеть пирамиду. Только после этого Даша окажется в замке. Каждое препятствие, встречающееся на пути, занимает время. Вы хотите знать, сколько всего времени требуется, чтобы преодолеть дистанцию от домика на дереве до замка из песка. Это просто — нужно зафиксировать время перед отъездом и по прибытию.

Предположим, что вы хотите не просто знать, сколько занимает путь, а понимать, какое препятствие требует больше всего времени и почему. Для этого вы можете записывать время начала и время окончания преодоления каждого препятствия, фиксировать любую другую информацию, которую сочтёте полезной для отчёта. Это работает примерно так: 

Каждое препятствие похоже на функцию, тогда как путь между ними — это вызовы функций, которые можно не учитывать, так как они должны быть быстрыми.

Let’s coding!

Перенесём путешествие Даши в код и проанализируем, что она делает на каждом препятствии. Для начала нам нужно создать 4 функции:

func startTheJourneyFromTreeHouse(parent context.Context, param int64) (out int64, err error) {
	span, ctx := opentracing.StartSpanFromContext(parent, "startTheJourneyFromTreeHouse")
	defer func() {
		ctx.Done()
		span.Finish()
	}()

	time.Sleep(2 * time.Millisecond)
	span.SetTag("message", "prepare some food")

	out = param + 2
	return
}

func passTheForest(parent context.Context, param int64) (out int64, err error) {
	span, ctx := opentracing.StartSpanFromContext(parent, "passTheForest")
	defer func() {
		ctx.Done()
		span.Finish()
	}()

	time.Sleep(5 * time.Millisecond)
	span.SetTag("message", "oh it's a long forest and I'm getting tired now!")

	out = param + 5
	return
}

func crossTheLake(parent context.Context, param int64, isRainyDay bool) (out int64, err error) {
	span, ctx := opentracing.StartSpanFromContext(parent, "crossTheLake")
	defer func() {
		ctx.Done()
		span.Finish()
	}()

	time.Sleep(10 * time.Millisecond)
	out = param + 10

	if isRainyDay {
		time.Sleep(20 * time.Millisecond)
		span.SetTag("message", "It's a rainy day and "+
			"I must extra careful since I don't want my boat drowned with me")
	} else {
		span.SetTag("message", "Clear weather and I enjoy the view from the lake!")
	}

	span.SetTag("isRainyDay", isRainyDay)

	return
}

func enterThePyramid(parent context.Context, param int64) (out int64, err error) {
	span, ctx := opentracing.StartSpanFromContext(parent, "enterThePyramid")
	defer func() {
		ctx.Done()
		span.Finish()
	}()

	time.Sleep(10 * time.Millisecond)
	out = param + 10

	span.SetTag("message", "Whoa, everywhere's dark!")
	return
}

• startTheJourneyFromTreeHouse — Даша готовит еду своего путешествия;

• passTheForest — Даша гуляет с обезьяной Бутом по лесу;

• crossTheLake — Даша пересекает озеро. Здесь мы добавим условие: если день дождливый, то процесс будет медленнее. Это условие также показывает, что трассировка позволяет точно определить, где произошло замедление процесса;

• enterThePyramid — Даша входит в пирамиду и выходит из темной комнаты внутри пирамиды.

В первом аргументе каждой функции всегда есть параметр context. На его основе вы создаёте интервал, используя opentracing.StartSpanFromContext. Каждый интервал представляет собой функциональный процесс и должен завершаться с использованием отложенной функции. В context есть информация о трассировке, поэтому при вызове функции passTheForest он будет содержать информацию из предыдущего вызова функции startTheJourneyFromTreeHouse.

Вызов функции будет выполнен следующим образом:

serverSpan := eCtx.Get("serverSpan").(opentracing.Span)
ctx := opentracing.ContextWithSpan(
   context.Background(),
   serverSpan,
)
defer ctx.Done()
...
out, _ = startTheJourneyFromTreeHouse(ctx, in)
out, _ = passTheForest(ctx, out)
out, _ = crossTheLake(ctx, out, isRainyDay)
out, _ = enterThePyramid(ctx, out)

Переменная serverSpan — значение, которое уже задано в traceMiddleware. Оно содержит родительский интервал, который обертывает весь интервал вызовов функций:

spanCtx, _ := opentracing.GlobalTracer().Extract(
   opentracing.HTTPHeaders,
   opentracing.HTTPHeadersCarrier(req.Header),
)
serverSpan := opentracing.StartSpan(
   c.Request().URL.Path,
   ext.RPCServerOption(spanCtx),
)

c.Set("serverSpan", serverSpan)

Каждый раз, когда вы вызываете функцию, она несет информацию из предыдущего вызова функции. И вы получаете трассировку стека (которая визуализируется с помощью интервала), которая выглядит следующим образом:

В каждом интервале вы записываете информацию и можете увидеть подробности, развернув его:

Самый длинный процесс — функция crossTheLake с параметром is_rainy_day true. Чтобы убедиться, что это не аномалия, вы можете попробовать найти другую трассировку в той же конечной точке. С помощью этой подсказки вы можете попытаться оптимизировать функцию, не угадывая, как провидец, а опираясь на данные.

Заключительные слова

При высоком трафике довольно сложно определить точную проблему в серверной части. Свести к минимуму трудности, связанные с поиском узких мест, помогает трассировка. Она работает путём конвейерной передачи информации с использованием context и отправки этой информации с использованием UDP в Jaeger. 

«DevOps Tools для разработчиков»

Материал основан на статье «Understand Your System Behavior By Implement Distributed Tracing Using Jaeger»