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.