Monitoring AWS Lambda i SQS przy użyciu X-Ray

Posted on 23 maj 2020

Bardzo wiele zostało już napisane na temat monitorowania aplikacji serverless. Jednym z narzędzi wykorzystywanym w chmurze AWS jest usługa X-Ray. Przybliżałem już ten temat podczas webinarium, które można znaleźć tutaj.

AWS X-Ray

W skrócie AWS X-Ray pomaga analizować i debugować rozproszone aplikacje, w szczególności aplikacje serverless. Jedną z ważniejszych rzeczy, o których należy pamiętać jest to, że X-Ray działa na podstawie próbkowania, czyli nie analizuje całego ruchu w aplikacji, a co za tym idzie dane w nim zawarte są danymi statystycznymi. W jakich sytuacjach może się przydać X-Ray?

Po pierwsze analiza zachowania aplikacji. Uruchamiając X-Ray, z pudełka dostajemy podgląd całego przebiegu zapytań w aplikacji, a co za tym idzie, możemy podejrzeć mapę zasobów. Przykładową mapę możemy zobaczyć poniżej.

https://docs.aws.amazon.com/xray/latest/devguide/aws-xray.html

Dzięki tej funkcjonalności bardzo łatwo możemy dowiedzieć się jak przebiega komunikacja w obrębie aplikacji. Na przykładzie z powyższej mapy widzimy, że aplikacja hostowana na Elastic Beanstalku komunikuje się z różnymi tabelami w DynamoDB oraz usługą Amazon SNS. Pozwala to łatwo sprawdzić, czy aplikacja zachowuje się prawidłowo.

Drugim ważniejszym elementem jest poszukiwanie wąskich gardeł. Posiadając mapę zasobów w aplikacji, jesteśmy w stanie bardzo łatwo określić która część ma największy wpływ na czas trwania zapytania. Dodatkowym ułatwieniem jest widok przebiegów zapytań.

Analizując powyższe informacje, bardzo łatwo możemy zauważyć co trwa najdłużej i na tej podstawie podjąć decyzje, gdzie warto coś zmienić, by poprawić wydajność.

Jak podpiąć X-Ray?

Zawsze jest jakieś miejsce w aplikacji, gdzie zaczynamy śledzić zapytania. Może to być AWS Lambda, czy API hostowane na EC2, ECS lub Elastic Beanstalku. By uruchomić X-Ray dla hostowanego API, należy skonfigurować X-Ray daemon, o którym więcej przeczytasz tutaj.

Monitorowanie Lambd

Dzisiaj skupimy się na współpracy z Lambdami. By zacząć monitorować Lambdę, wystarczy ustawić Tracing na true. Poniżej widzimy przykładową definicję Lambdy w CloudFormation.

AddItemLambda:
  Type: AWS::Serverless::Function
  Properties:
    Handler: ServerlessObservability::ServerlessObservability.Functions.AddItemLambda::InvokeAsync
    CodeUri: bin/Release/netcoreapp3.1/publish
    Runtime: dotnetcore3.1
    MemorySize: 1536
    Timeout: 30
    Tracing: Active
    Role: !GetAtt AddItemLambdaRole.Arn

To ustawienie spowoduje automatyczne zbieranie danych na temat Lambdy. Przyjrzyjmy się co w tym momencie udostępnia nam X-Ray.

Mapa widoczna powyżej niestety na niewiele nam się przyda, ale już analiza przebiegów dużo bardziej.

Analizując powyższe wywołanie uzyskujemy informacje ile trwa cold start, inicjalizacja oraz jak długie jest wywołanie naszego kodu. W tym wypadku:

cold-start – ok. 400 ms
inicjalizacja – 173 ms
wywołanie – 1200 ms

Monitorowanie requestów wychodzących z innymi usługami AWS

Monitorowanie zapytań wychodzących z Lambdy również jest stosunkowo proste, jednak wymaga już ingerencji w kod aplikacji i wykorzystania SDK, które dostarcza Amazon.

Mamy dwie możliwości uruchomienia automatycznego śledzenia komunikacji z innymi usługami AWS.

śledzenie komunikacji ze wszystkimi usługami
śledzenie komunikacji z wybranymi usługami

W przypadku C# konfiguracja wygląda następująco.

AWSSDKHandler.RegisterXRayForAllServices();
// lub
AWSSDKHandler.RegisterXRay<IAmazonSQS>();
AWSSDKHandler.RegisterXRay<IAmazonLambda>();

By śledzić komunikację z innymi usługami AWS w Node.js, należy zawsze używać klientów utworzonych w sposób pokazany poniżej.

var AWS = AWSXRay.captureAWS(require('aws-sdk'));
// lub
var AWSXRay = require('aws-xray-sdk');
var ddb = AWSXRay.captureAWSClient(new AWS.DynamoDB());
var s3 = AWSXRay.captureAWSClient(new AWS.S3());

Tym razem mapa przekazuje dużo więcej informacji. Łatwo możemy zobaczyć, że Lambda komunikuje się z S3, SQS i SSM.

Również analizując przebieg zapytań uzyskujemy dużo więcej informacji niż ostatnio. Dzięki wyszczególnieniu poszczególnych zewnętrznych zapytań, możemy znaleźć wąskie gardła.

W powyższym przypadku wygląda to następująco.

cold-start – 300ms
inicjalizacja – 165ms
wywołanie – 1100ms
GetParameters – 352ms
PutObject – 94,3ms
SendMessage – 71,6ms

Łatwo policzyć, że nasz kod wywołuje się około 580ms, a z zewnętrznych wywołań najdłużej trwa pobranie parametrów z Parameter Store.

Monitorowanie requestów wychodzących poza chmurę AWS

By monitorować zapytania wychodzące poza chmurę AWS również możemy skorzystać z AWS SDK. Tym razem musimy udekorować klienta HTTP, którego będziemy używali do komunikacji z zewnętrznymi systemami.

Poniżej widzimy jak skonfigurować klienta http w C#.

var handler = new HttpClientHandler();
var xRayHandler = new HttpClientXRayTracingHandler(clientHandler);
var httpClient = new HttpClient(httpClientXRayTracingHandler);

Oraz jak zrobić to w Node.js.

AWSXRay.captureHTTPsGlobal(require('http'));
AWSXRay.captureHTTPsGlobal(require('https'));
// lub
var tracedHttp = AWSXRay.captureHTTPs(require('http'));
// lub
AWSXRay.capturePromise();

Dzięki zastosowanej konfiguracji jesteśmy w stanie monitorować komunikację z zewnętrznymi serwisami.

W tym przypadku widzimy, że Lambda wywołuje worldclockapi.com i trwa to 299ms.

Również na liście przebiegów pojawia się nowy podsegment, dzięki czemu łatwo możemy analizować które części Lambdy trwają najdłużej.

Problem z SQS

UWAGA!
Problem został zaadresowany przez AWS dnia 21.11.2022r.
Aktualnie połączenie SQS Lambda tworzone jest automatycznie dzięku mechanizmowi trace linking.
Więcej można przeczytać tutaj.

Do tej pory cała konfiguracja była bardzo prosta, zmodyfikowaliśmy CloudFormation, dodaliśmy kilka linijek kodu i działa. Niestety nie zawsze jest tak pięknie. Jednym z przykładów jest śledzenie requestów przechodzących przez kolejkę SQS.

Przyjrzyjmy się standardowemu przykładowi. Lambda AddItem wrzuca zdarzenie na kolejkę, a Lambda UpdateItem subskrybuje się na przychodzące zdarzenia. Dla lepszego zobrazowania sytuacji, Lambda UpdateItem komunikuje się z S3.

Co prawda X-Ray posiada wsparcie dla SQS, ale TraceId przekazuje tylko poprzez nagłówek zawarty we wiadomości i nie aplikuje go automatycznie. Powoduje to, że ścieżka zapytania kończy się na kolejce, co możesz zobaczyć na mapie poniżej.

Również na liście przebiegów możemy zobaczyć jedynie umieszczenie zdarzenia na kolejce, ale nie dowiemy się co dzieje się dalej.

W rzeczywistości Lambda otrzymująca zdarzenie z kolejki otrzymuje nowe TraceId, a co za tym idzie posiada swoją mapę zasobów w X-Ray.

Krok pierwszy

W dokumentacji możemy znaleźć rozwiązanie tej sytuacji proponowane przez AWS. Przyjrzyjmy się mu i zaaplikujmy. W dokumentacji widnieje tylko kod napisany w Javie, ale można go przepisać na dowolny język posiadający X-Ray SDK. Poniżej widnieje kod napisany w C#.

var segment = AWSXRayRecorder.Instance.GetEntity();
segment.TraceId = traceHeader.RootTraceId;
segment.ParentId = traceHeader.ParentId;
segment.Sampled = traceHeader.Sampled;

Rozwiązanie jest proste. Wyciągamy aktualny Segment, następnie podmieniamy TraceId, RootId oraz informacje o próbkowaniu na przekazane w nagłówku wiadomości z kolejki.

Niestety przy subskrypcji Lambdy na kolejkę, to rozwiązanie nie działa. Dzieje się tak, ponieważ nie jesteśmy w stanie nadpisać głównych segmentów Lambdy.

Krok drugi

Co możemy w takim razie zrobić?
Przyjrzyjmy się logom, które zostawia X-Ray, ale najpierw musimy włączyć ich publikowanie.

AWSXRayRecorder.RegisterLogger(LoggingOptions.Console);

Teraz już możemy zobaczyć jak działa X-Ray wewnątrz Lambdy.

Spójrzmy na interesujące nas fragmenty zalogowane w CloudWatch.

AWSXRayRecorder znalazł zmienną odpowiedzialną za tracing w zmiennych środowiskowych.
Zdarzenie zostało wysłane na kolejkę.
UdpSegmentEmitter wysłał nowy Segment do X-Ray.

Jeśli X-Ray korzysta ze zmiennych środowiskowych, to zostało dowiedzieć się jaka to zmienna. Z pomocą przychodzi dokumentacja AWS.

Teraz już wiemy, że jest to zmienna o kluczu _X_AMZN_TRACE_ID, więc możemy ją nadpisać. Nazwa zmiennej środowiskowej dostępna jest również w AWSXRayRecorder.LambdaTraceHeaderKey.

Z tą wiedzą pozostało nam już tylko nadpisanie zmiennej środowiskowej.

Environment.SetEnvironmentVariable(AWSXRayRecorder.LambdaTraceHeaderKey, sqsMessage.Attributes["AWSTraceHeader"]);

Dzięki temu spowodujemy przypisanie wszystkich zewnętrznych wywołań z Lambdy UpdateItem do oryginalnego TraceId oraz rodzica. Nadal pozostanie ślad po tej Lambdzie w X-Ray, ale jest pusty, co można zobaczyć na mapie poniżej.

Niestety do ideału nadal daleko. Spójrzmy jak teraz wygląda mapa zasobów, którą chcemy analizować.

Widzimy dużo więcej, ale nadal są dwa główne problemy.

Całkowicie zniknęła Lambda UpdateItem.
Według mapy Lambda AddItem komunikuje się z S3.

Również analizująć przebiegi, sytuacja jest daleka od ideału, co prawda widzimy, że Lambda AddItem komunikuje się tylko z SQS, ale tym razem komunikacja z S3 przypisana jest do kolejki.

Krok trzeci i ostatni

Co dalej?
By uzyskać zadowalający efekt dodamy własny segment imitujący Lambdę UpdateItem. Więcej na temat segmentów możesz przeczytać w dokumentacji.

Zerknijmy na to jak wygląda segment opisujący Lambdę AddItem, by dowiedzieć się czego potrzebujemy, by dodać własny segment.

Widzimy, że do utworzenia segmentu imitującego Lambdę potrzebujemy:

id – musimy je wygenerować
name – pełna nazwa Lambdy UpdateItem, można ją pozyskać z kontekstu lambdy
trace_id – rootTraceId otrzymane z kolejki
parent_id – id kolejki SQS
start_time – początek wywołania Lambdy
end_time – koniec wywołania Lambdy
account_id – można je pozyskać z kontekstu lambdy
function_arn – również można go pozyskać z kontekstu lambdy
resource_names – to samo co w ‘name’

Dodatkowo będziemy chcieli ustawić takie samo próbkowanie jak oryginalnie, czyli użyć przekazanego przez kolejkę.

Po pierwsze musimy wyciągnąć nagłówek z wiadomości dostarczonej przez kolejkę. Do sparsowania tego nagłówka przydatna będzie klasa TraceHeader z X-Ray SDK.

var traceHeader = TraceHeader.FromString(sqsMessage.Attributes["AWSTraceHeader"]);
var lambdaSegmentParentId = traceHeader.ParentId;
var lambdaSegmentId = Entity.GenerateId();
traceHeader.ParentId = lambdaSegmentId;

Environment.SetEnvironmentVariable(AWSXRayRecorder.LambdaTraceHeaderKey, traceHeader.ToString());

Następnie podmieniamy ParentId na nowe id, którym będzie się identyfikował customowy segment, a na koniec ustawiamy zmienną środowiskową.

Pamiętając czego potrzebujemy do wygenerowania segmentu i jak wygląda segment opisujący Lambdę AddItem, utwórzmy własny segment.

_lambdaSegment = new Segment(lambdaContext.FunctionName, traceHeader.RootTraceId)
{
    Id = lambdaSegmentId,
    ParentId = lambdaSegmentParentId,
    Sampled = traceHeader.Sampled,
    Origin = "AWS::Lambda::Function",
    Aws =
    {
        { "account_id", lambdaContext.InvokedFunctionArn.Split(":")[4] },
        { "function_arn", lambdaContext.InvokedFunctionArn },
        { "resource_names", new List<string> { lambdaContext.FunctionName } }
    }
};

Jeśli chcemy mieć wgląd w całkowity czas wywołania Lambdy, to musimy jeszcze ustawić start_time. Najlepiej go zapisać zaraz po wejściu do Lambdy, a podczas tworzenia segmentu tylko przypisać.

_startTime = DateTime.UtcNow.ToUnixTimeSeconds();

_lambdaSegment.SetStartTime(_startTime);

Została ostatnia część, czyli ustawienie czasu końcowego oraz wyemitowanie segmentu. Zrobimy to na samym końcu wywołania Lambdy w następujący sposób.

_lambdaSegment.SetEndTimeToNow();
AWSXRayRecorder.Instance.Emitter.Send(_lambdaSegment);

Po dodaniu własnego segmentu mapa prezentuje się następująco.

Teraz już możemy przeanalizować cały przebieg naszego zapytania. Oczywiście nie jest to idealne rozwiązanie, ponieważ wciąż brakuje elementów Lambdy, które opisują cold start oraz inicjalizację, ale przebieg jest zachowany i gotowy do analizy.

Spójrzmy również na widok zapytań.

Ten widok też jest gotowy do analizy. Lambda AddItem komunikuje się z kolejką, a Lambda UpdateItem z bucketem S3.

Podsumowanie

W wiekszości sytuacji X-Ray działa automatycznie i pozwala bardzo łatwo analizować przebieg i czas zapytań. Jeżeli chcemy analizować niestandarowe elementy, jak czas wykonania własnego kawałka kodu, to musimy napisać trochę kodu, ale jest to bezproblemowe i łatwe zadanie.