OpenTelemetry w OpenEdge – część I
OpenTelemetry pojawiło się w OpenEdge 12.8. Wraz z tą wersją Progress wprowadził tracing zarówno dla ABL Client, jak i PASOE.
Jest to technologia coraz częściej pojawiająca się w środowiskach, w których chcemy wiedzieć nie tylko czy aplikacja działa, ale również co dokładnie robi i gdzie “spędza” najwięcej czasu.
W przypadku aplikacji napisanych w ABL jest to szczególnie interesujące. Przez lata do diagnozowania problemów z aplikacją OpenEdge wykorzystywaliśmy między innymi logi, czy narzędzia diagnostyczne jak Profiler. OpenTelemetry otwiera jednak trochę inną możliwość – możemy spojrzeć na wykonanie aplikacji z perspektywy trace’ów i spanów. I tak, trace opisuje wykonanie całej operacji użytkownika, a spany pokazują poszczególne elementy tego wykonania – np. ABL Client, PASOE, poszczególne procedury itp.
W OpenEdge Progress udostępnia natywne wsparcie dla OpenTelemetry w ABL Client. Nie trzeba więc od razu przebudowywać aplikacji ani dodawać własnego mechanizmu logowania. Tracing można włączyć na poziomie sesji ABL za pomocą parametru -otelconfig. Architektura śledzenia jest dość prosta.
ABL Client → OTLP → OpenTelemetry Collector → APM
ABL Client generuje dane telemetryczne i przekazuje je do OpenTelemetry Collector za pomocą protokołu OTLP. Collector może następnie przekazać je do wybranego narzędzia APM (Application Performance Monitor) np. Elastic APM, Dynatrace czy New Relic.
Na potrzeby pierwszego testu możemy jednak pominąć cały backend APM i instalację Collectora.
W OpenEdge mamy bowiem ostream, który Progress opisuje jako rozwiązanie przydatne właśnie do testowania i debugowania. Zamiast wysyłać trace do Collectora, możemy zapisać je bezpośrednio do pliku.
ABL Client → ostream → plik
Do testowania potrzebna będzie nam aplikacja ABL. Weźmy poniższy przykład składający się z czterech procedur, każda w osobnym pliku. Tylko procedura UpBalance.p generuje transakcję.
// CustomerOrders.p
VAR INTEGER iCustomer = 1, iOrders.
VAR CHARACTER cName.
RUN GetCustomer.p (iCustomer, OUTPUT cName).
RUN GetOrdersNum.p (iCustomer, OUTPUT iOrders).
RUN UpBalance.p (iCustomer).
MESSAGE
cName iOrders
VIEW-AS ALERT-BOX INFO.
// GetCustomer.p
DEFINE INPUT PARAMETER piCustNum AS INTEGER NO-UNDO.
DEFINE OUTPUT PARAMETER cName AS CHAR NO-UNDO.
FIND FIRST Customer
WHERE Customer.CustNum = piCustNum NO-LOCK NO-ERROR.
IF AVAILABLE Customer THEN
cName = NAME.
ELSE
cName = "".
// GetOrdersNum.p
DEFINE INPUT PARAMETER piCustNum AS INTEGER NO-UNDO.
DEFINE OUTPUT PARAMETER piOrders AS INTEGER NO-UNDO.
piOrders = 0.
FOR EACH Order WHERE Order.CustNum = piCustNum NO-LOCK:
piOrders = piOrders + 1.
END.
// UpBalance.p
DEFINE INPUT PARAMETER piCustNum AS INTEGER NO-UNDO.
FIND FIRST Customer
WHERE Customer.CustNum = piCustNum NO-ERROR.
IF AVAILABLE Customer THEN
Balance = Balance * 1.1.
Konfiguracja OpenTelemetry jest przechowywana w pliku JSON. Zawiera ona m.in. informacje o exporterze (element OpenTelemetry odpowiedzialny za wysłanie (eksport) zebranych danych telemetrycznych) oraz zakresie śledzenia procedur ABL.
Plik konfiguracyjny przekazujemy do sesji ABL podczas jej uruchamiania za pomocą parametru -otelconfig, wskazując ścieżkę do pliku JSON.
Poniżej widać przykładowy plik konfiguracyjny myOtelConfig.json.
{
"OpenTelemetryConfiguration": {
"resource_attributes": "service.name=Sports2000",
"exporters": {
"ostream": [
{
"filename": "C:\\WrkOpenEdge128\\otel\\traces.out",
"span_processor": "simple"
}
]
}
},
"OpenEdgeTelemetryConfiguration": {
"trace_procedures": "*",
"trace_classes": "*",
"trace_abl_transactions": true,
"trace_requires_parent": false,
"trace_request_start": true
}
}
Uwaga! dla trace_procedures i trace_classes po znaku dziekiej karty * nie może występować żaden ciąg znaków, czyli “Customer*” jest OK, ale “Customer*.p” już jest błędem.
“trace_requires_parent”: false – oznacza: jeżeli nie ma jeszcze nadrzędnego spanu (parent), i tak utwórz span. W przeciwnym razie, dla wartości true oznaczałoby: twórz spany tylko wtedy, gdy istnieje odpowiedni trace/span nadrzędny.
Sesję startuję poleceniem:
prowin ../db/sports2000 -otelconfig myOtelConfig.json
Gdyby pojawiły się błędy lub np. plik wynikowy był pusty, warto dodać parametry generujące log klienta:
prowin ../db/sports2000 -otelconfig myOtelConfig.json -clientlog otel.log -logentrytypes TELEMETRY -logginglevel 3
Plik wynikowy traces.out zawiera informacje o utworzonych spanach. Każdy span posiada między innymi trace_id, który identyfikuje cały ślad wykonania, oraz span_id i parent_span_id, pozwalające określić zależności pomiędzy poszczególnymi operacjami.
Pole name zawiera nazwę śledzonej procedury lub operacji. start określa moment rozpoczęcia spanu, natomiast duration informuje o czasie jego wykonania. W naszym przykładzie wartości czasu podawane są w nanosekundach.
W danych znajdziemy również informacje o rodzaju spanu (span kind), jego statusie oraz atrybutach. W przypadku transakcji OpenEdge możemy zobaczyć dodatkowe informacje, takie jak numer linii czy nazwa bazy danych.
Sekcja resources zawiera informacje opisujące źródło telemetryki. W naszym przypadku jest to między innymi service.name, ustawione w pliku konfiguracyjnym JSON, oraz informacje o wykorzystanej implementacji OpenTelemetry.
Dzięki tym informacjom pojedynczy plik wynikowy zawiera nie tylko listę wykonanych operacji, ale również dane pozwalające odtworzyć ich wzajemne zależności i zmierzyć czas wykonania poszczególnych elementów aplikacji.
W pliku wynikowym znajdziemy również informacje dotyczące transakcji ABL. W naszym przykładzie wykonanie procedury UpBalance.p powoduje utworzenie dodatkowego spanu BeginTransaction_UpBalance.p. Dzięki temu możemy zobaczyć nie tylko czas wykonania samej procedury, ale również czas związany z rozpoczęciem i obsługą transakcji.
Span transakcji może zawierać dodatkowe atrybuty, takie jak numer linii, w której rozpoczęła się transakcja (Line), oraz lista baz danych uczestniczących w operacji (dblist). Pozwala to powiązać dane telemetryczne z konkretnym fragmentem kodu ABL i używaną bazą danych.
Poniżej znajduje się rzeczywisty plik wyniowy traces.out wygenerowany podczas wykonania naszego przykładu. Dodam, że testy przeprowadziłem w środowisku OE 12.8 i 13.0 z podobnym rezultatem.
{
name : GetCustomer.p
trace_id : b391af61034180280d0c8ac7f847c547
span_id : 46814552c7b7f49d
tracestate :
parent_span_id: dba1567c11e6fce7
start : 1787993179723773800
duration : 31300
description :
span kind : Internal
status : Unset
attributes :
events :
links :
resources :
service.name: Sports2000
telemetry.sdk.language: cpp
telemetry.sdk.name: opentelemetry
telemetry.sdk.version: 1.9.1
instr-lib : 54208-1.9.1
}
{
name : GetOrdersNum.p
trace_id : b391af61034180280d0c8ac7f847c547
span_id : d143669da300cb61
tracestate :
parent_span_id: dba1567c11e6fce7
start : 1787993179724423100
duration : 74600
description :
span kind : Internal
status : Unset
attributes :
events :
links :
resources :
service.name: Sports2000
telemetry.sdk.language: cpp
telemetry.sdk.name: opentelemetry
telemetry.sdk.version: 1.9.1
instr-lib : 54208-1.9.1
}
{
name : BeginTransaction_UpBalance.p
trace_id : b391af61034180280d0c8ac7f847c547
span_id : 47fbd8c581af2e2c
tracestate :
parent_span_id: f2489adf6e462ba0
start : 1787993179724894000
duration : 887200
description :
span kind : Internal
status : Unset
attributes :
Line: 1
dblist: sports2000
events :
links :
resources :
service.name: Sports2000
telemetry.sdk.language: cpp
telemetry.sdk.name: opentelemetry
telemetry.sdk.version: 1.9.1
instr-lib : 54208-1.9.1
}
{
name : UpBalance.p
trace_id : b391af61034180280d0c8ac7f847c547
span_id : f2489adf6e462ba0
tracestate :
parent_span_id: dba1567c11e6fce7
start : 1787993179724885700
duration : 930800
description :
span kind : Internal
status : Unset
attributes :
events :
links :
resources :
service.name: Sports2000
telemetry.sdk.language: cpp
telemetry.sdk.name: opentelemetry
telemetry.sdk.version: 1.9.1
instr-lib : 54208-1.9.1
}
{
name : C:\WrkOpenEdge128\otel\p78729_CustomerOrders.ped
trace_id : b391af61034180280d0c8ac7f847c547
span_id : dba1567c11e6fce7
tracestate :
parent_span_id: 0000000000000000
start : 1787993179722973700
duration : 3154827200
description :
span kind : Internal
status : Unset
attributes :
events :
links :
resources :
service.name: Sports2000
telemetry.sdk.language: cpp
telemetry.sdk.name: opentelemetry
telemetry.sdk.version: 1.9.1
instr-lib : 54208-1.9.1
}
W powyższym pliku widać, że wszystkie spany należące do jednego wykonania aplikacji mają ten sam trace_id (b391af61034180280d0c8ac7f847c547). Jest to identyfikator całego śladu (trace), dzięki któremu można powiązać ze sobą poszczególne operacje składające się na jedno wykonanie programu. W naszym przykładzie pozwala on powiązać CustomerOrders.ped z wywołanymi przez nią procedurami GetCustomer.p, GetOrdersNum.p oraz UpBalance.p.
W następnym odcinku, napiszę jak włączyć w ten proces Otel Collector.