APM open source Glowroot Slow traces

Il seguente articolo è la continuazione della serie sull’APM Glowroot, in cui ci focalizzeremo sul concetto di trace e sulla pagina delle Slow Traces.

Ti sei perso le puntate precedenti? Eccole qui:

Request tracing

In un’applicazione web l’instrumentation del codice (vedere articolo 1) viene solitamente effettuata per recuperare informazioni legate alle singole richieste alle url che il sito mette a disposizione (web requests). Questa tecnica prende il nome di request tracing e si basa sul concetto di trace (traccia). Una traccia è il percorso completo di una richiesta, dal momento in cui arriva all’applicazione partendo dal chiamante (client) al momento in cui rilascia la sua risposta al chiamante stesso.

Tutti gli eventi registrati all’interno della stessa request sono associati ad uno stesso trace id (identificativo di traccia) in maniera tale da poter essere organizzati, filtrati e ricercati per tracce specifiche.

Ogni traccia può essere a sua volta suddivisa in segmenti (denominati span). Uno span isola una data attività o operazione. Anche uno span generalmente ha un suo id univoco per identificarlo ed ha associati dei metadata o altre informazioni, come ad esempio la sua durata.

Slow traces

Glowroot ha una sezione ad hoc in cui mostra le tracce più lente. E’ possibile configurare la soglia oltre la quale una traccia è definibile come lenta. Il default è 2 secondi.

Questa è la schermata delle Slow Traces di Glowroot sulla url principale di un Web.UP sollecitato da test automatici di performance (svolti dalle 12.15 alle 12.30 circa).

Dettaglio di una trace

Può essere molto interessante soffermarsi sulle tracce più lente per individuare ed analizzare problemi di performance. Nell’immagine si nota ad esempio una traccia molto distante dalle altre, di durata poco meno di 14 secondi. Glowroot permette di cliccare sulla traccia e visualizzarne diverse informazioni.

Innanzitutto sulla traccia sono riportati i parametri http della web request. Per uno sviluppatore dell’applicazione Web.UP è chiaro come quella richiesta sia collegata alla chiamata della fun F(EXD;*SCO;) 1(;;) 2(MB;SCP_SCH;WETEST_EXU) 4(;;SIMEXU1) inviata tramite la sezione spotlight dello showcase di Web.UP.

Nella traccia si riconoscono diversi span, registrati nella parte BreakDown. Essi sono ottenuti grazie ai marker del codice instrumentato. Si nota che dei 13,6 secondi totali che ha impiegato quella richiesta la quasi totalità sono stati consumati dalla parte del codice che comunica con lo Sme.UP Provider (SmeupProviderCall).

Cliccando sul link Trace Entries si apre una schermata di maggior dettaglio in cui la durata degli span è rappresentata graficamente con una colorazione piena, mostrando ancora più chiaramente come l’alto tempo di esecuzione dipenda quasi totalmente dall’operazione associata alla chiamata dello Sme.UP Provider.

Provando a cliccare su una delle altre tracce più lente la situazione cambia completamente.

In questo caso degli 8 secondi totali la maggioranza è dovuta al rendering delle JSF. Dall’esame dei parametri http si nota come sia stato chiamato il rendering di una matrice di test costruita appositamente con molte righe e colonne. In questo caso è il rendering della parte grafica e non la chiamata ad un server esterno (lo Sme.UP Provider) che dà lentezza.

Per completezza si riporta il dettaglio delle trace entries di questo caso.