Application Tracing Nasıl Yapıyoruz?

Bir uygulamanın canlıda (production) ne yaptığını görebilmek için gözlemleme (monitoring) yöntemleri kullanılır. Bunlardan bazıları:

• Log monitoring: Sistemin genel gidişatını gözetmek ve durum analizi yapabilmek için uygulama logları merkezi bir yerde toplanır ve işlenir.
• Network / Server monitoring: Ağ ve sunucular hakkında metrik olarak isimlendirilen veriler merkezi bir yerde toplanır ve durum sorgulaması için kullanılır.
• Application monitoring: Uygulama hakkında (hafıza, işlemci, hata oranları vs) veriler toplanır ve bunlar hata ve durum analizi için kullanılır.

Canlıya alınmış bir uygulama için bahsi geçen bu yöntemlerin kullanımı zaruri görünmektedir. Sadece bu şekilde kara bir kutu gibi işlev gören bir uygulamaya ışık tutularak, tasarlandığı şekilde çalışıp, çalışmadığı hakkında fikir sahibi olunabilir. Bir startup olarak bizim bu yöntemleri nasıl uyguladığımızı daha sonra kaleme alacağımız yazılarımızdan takip edebilirsiniz.

Bu kısa girişin ardından application tracing işlemini nasıl yaptığımızı yakından inceleyelim. Application tracing terimini, application monitoring başlığı altında, bir uygulamanın kendi içinde yaptıklarını takip etmek ve bunun için harcadığı zaman birimlerini ölçmek için kulanılan yöntemlere verilen isim olarak tercüme edebiliriz. Application tracing en basit hali ile yapılan işlem için log satırları oluşturmak ile başlatılır. Bu yapılan işlemi görselleştirmek için atılan ilk adımdır. Çoklu kullanıcısı olan uygulamalarda bu çok kısa bir zaman sonra içinde çıkılamayacak bir hal alabilir, çünkü kullanıcı istekleri ile log satırlarınının ilişkilendirilmesi gerekmektedir. Aksi taktirde hangi işlemin hangi kullanıcı için hangi zaman biriminde yapıldığını anlamak kolay olmayacaktır. Bu yüzden application tracing bünyesinde bir işlem için oluşturulan log satırlarının mantıksal olarak guruplandırılması gerekmektedir. Bunun için herhangi tekil bir değer kullanılabilir. Bunun nasıl yapıldığını aşağıdaki örnek üzerinden inceleyelim.

Örneğimizde kulllanıcı (user) kampanya apisi (/api/campaings) üzerinden kampanya listesini alabilmektedir. Uygulama bünyesinde kampanya apisi (application programming ınterface) üç katmanlı bir yapıya sahiptir. Kullanıcı isteği (request) apiye ulaştığı andan itibaren her katmanda en az bir log satırı oluşturarak, nerede hangi işlemin yapıldığını görebiliriz.

2024-11-23T09:46:00.10 DEBUG :: [CampaingApi] - Rest request to getCampaings()
2024-11-23T09:46:00.20 DEBUG :: [CampaingAPi] - start processing campaings
2024-11-23T09:46:00.30 DEBUG :: [CampaingService] - getCampaings() enter
2024-11-23T09:46:00.40 DEBUG :: [CampaingRepository] - findAllCampaings() enter
2024-11-23T09:46:00.50 DEBUG :: [CampaingRepository] - found 10 records
2024-11-23T09:46:00.60 DEBUG :: [CampaingRepository] - findAllCampaings() exit
2024-11-23T09:46:00.70 DEBUG :: [CampaingService] - getCampaings() exit
2024-11-23T09:46:00.80 DEBUG :: [CampaingApi] - returning 10 campaings to user
2024-11-23T09:46:00.90 DEBUG :: [CampaingApi] - exit

Log satırlarının zaman hanesine baktığımızda, her işlemin 10 milisaniye sürdüğünü görmekteyiz ve satırlar düzenli olarak işlemin başladığı andan bittiği ana kadar log dosyasına işlenmektedir. Bunu application tracing yönteminin en basit hali olarak düşünebiliriz. Lakin aynı anda birçok kullanıcı aynı isteği gönderdiğinde, log satırlarındaki düzen bozulur çünkü log yazıcısı (lögger) kullanıcı işlem sırası gözetmeksizin kendisine verilen log satırlarını log dosyasına işler. Bu durumda hangi log satırının hangi kullanıcıya ait olduğunu ve işlemin ne kadar sürdüğünü anlamak zorlaşır.

Bu problemi çözmek için her kullanıcı isteğini tekil bir değer ile eşleştirebiliriz. Aşağıdaki örnekte traceİD için böyle tekil bir değer kullanılmıştır.

2024-11-23T09:46:00.10 [traceID=b4d6cf59f6] DEBUG :: [CampaingApi] - Rest request to getCampaings()
2024-11-23T09:46:00.10 [traceID=gerterr78f] DEBUG :: [CampaingApi] - Rest request to getCampaings()
2024-11-23T09:46:00.20 [traceID=b4d6cf59f6] DEBUG :: [CampaingAPi] - start processing campaings
2024-11-23T09:46:00.30 [traceID=b4d6cf59f6] DEBUG :: [CampaingService] - getCampaings() enter
2024-11-23T09:46:00.40 [traceID=b4d6cf59f6] DEBUG :: [CampaingRepository] - findAllCampaings() enter
2024-11-23T09:46:00.50 [traceID=b4d6cf59f6] DEBUG :: [CampaingRepository] - found 10 records
2024-11-23T09:46:00.60 [traceID=b4d6cf59f6] DEBUG :: [CampaingRepository] - findAllCampaings() exit
2024-11-23T09:46:00.70 [traceID=b4d6cf59f6] DEBUG :: [CampaingService] - getCampaings() exit
2024-11-23T09:46:00.80 [traceID=b4d6cf59f6v] DEBUG :: [CampaingApi] - returning 10 campaings to user
2024-11-23T09:46:00.90 [traceID=b4d6cf59f6] DEBUG :: [CampaingApi] - exit

İlk satır b4d6cf59f6 değerini taşırken ikinci satır gerterr78f değerini kullanmaktadır. Bu iki değişik kullanıcı isteğinin o anda log dosyasına işlendiğini göstermektedir. Biz b4d6cf59f6 değerini kullanarak kolayca bu traceİd ile ilişkili tüm log satırlarına ulaşabiliriz.

Application tracing yapılabilmesi için her kullanıcı isteğinin tracing id olarak isimlendirilen tekil bir değer ile işaretlenmesi gerekmektedir. Her kullanıcı isteği (request) için bu başka bir değer olacaktır. Bu şekilde log satırlarını bu değer üzerinden mantıksal guruplayarak, yapılan işlemin detaylarını ve harcanan zamanı görebiliriz.

Application tracing ile elde edilmek istenen asıl bilgi, hangi katmanda hangi zamanın birimin harcandığı bilgisidir. Bu şekilde performans problemlerinin tespiti kolaylaşmaktadır. Aşağıdaki örnekte rest apiye gelen bir isteği ve bunun için backend sisteminin harcadığı zaman birimini görmektesiniz. Uygulama isteği 55,7 milisaniye cevaplamıştır.

Bu trace ne yazık ki hangi katmanda ne kadar harcandığını gösterecek detaya sahip değildir. Örneğin bir kullanıcı için bu istek 25 milisaniye sürerken, bir başka kullanıcı için 250 milisaniye sürebilir. Bu trace’e bakarak bu farklılığın nedenini anlamamız mümkün değildir. Bunun yerine şöyle bir trace çok daha işimize yarar türden olurdu:

Bu trace bünyesinde isteğin toplamda 55,7 milisaniyede cevaplandığını görüyoruz. Trace bünyesinde ayrıca işlem için değişik katmanlarda ne kadar zaman harcandığına dair bilgiler de bulunmaktadır. Örnekte görüldüğü gibi uygulama 55,7 milisaniyelik toplam zamanın 4,9 milisaniyesini kullanıcı bilgilerini kontrol etmeye girmeden önce (security filterchain before), 41,7 milisaniyeyi kullanıcı isteğini cevaplamak için (secured request) gerekenleri yaparken ve 812 mikrosaniyeyi bu işlemleri tamamlamak için (security filterchain after) kullanmıştır.

Buradan kabaca şöyle bir sonuç çıkarabiliriz:

• İstek toplamda sunucu tarafından 55,7 milisaniyede cevaplanmıştır.
• İşlemin kendisi toplamda 41,7 milisaniye sürmüştür.
• Güvenlik kontrolleri ve geriye kalan diğer işlemler için  5,7 milisaniye harcanmıştır.

Bu trace bizim için yine çok faydalı bir trace değildir, çünkü gerçek işlemin 41,7 milisaniye sürdüğünü biliyor olmamıza rağmen, bu zaman biriminin katmanlar bünyesindeki dağılımını görememekteyiz. Şimdi daha geniş kapsamlı bir trace’i inceleyelim.

Şimdi uygulama içinde olup, bitenleri tüm çıplağı ile görebilmekteyiz. Toplam işlem süresi 41,7 milisaniye bu alt işlemlerden oluşmaktadır:

• Rest katmanındaki işlem (app-user-a-p-i#get-qr-code): 5,9 ms
• Servis katmanındaki işlem (app-user-service#get-user-qr-code): 3,7 ms
• Repository katmanındaki arama işlemi (repositöry:getQrÇode): 2,6 ms

Toplam zaman 41,7 milisaniye iken, bizim yazdığımız kod içinde geçen zaman 12 milisaniye civarındadır. Geriye kalan 30 milisaniyelik zaman Spring boot çatısı tarafından isteği yönetmek için kullanılan zamandır.

Eğer bu request 1 saniye sürmüş olsaydı, bunun nedenini bu trace’e bakarak anlamak çok daha kolay olurdu. Büyük bir ihtimalle repository:getQrÇode bu zamanın büyük bir kısmını teşkil ediyor olacaktı yani veritabanında bir ındex eksik olduğu için bu sorgulama uzun bir zaman alacaktı ve bu şekilde bu problemi keşfetmek ve ortadan kalkması için gerekeni yapmak kolay bir hal alacaktı.

Biz uygulamamız bünyesinde Spring boot 3 ile gelen tracing & observability araçlarını kullanıyoruz. Yukarda örneklerini verdiğin traceler uygulama tarafından oluşturuluyor ve trace analizi için zipkin sunucumuza gönderiliyor.

Spring boot 3 bünyesinde tracing su şekilde aktif hale getiriliyor:

#application.properties
management:
  tracing:
    enabled: true

Daha geniş kapsamlı traceler oluşturmak için @Observed anotasyonu kullanılabilmektedir.

@Observed(name="rest:getQrCode")
@GetMapping("/qrcode")
public ResponseEntity<QrCodeResponse> getQrCode() {
   log.debug("REST request to  getQrCode");
   var appUser = service.getUserQrCode();
   return ResponseEntity.ok().body(appUser);
}

Application tracing yöntemi ile kara kutu olan bir uygulamanın içine bakmak kolaylaşmakta ve nasıl işlediğine dair fikir edinmek mümkün hale gelmektedir. Özellikle uygulama için performans testleri yapılırken application tracing kullanılması, oluşacak performans problemlerin nokta atışı ile bulunmasını sağlamaktadır. Bunun yanı sıra kapasite planlaması için de aynı şekilde application tracing kullanılabilmektedir. Bir yük testi (load testing) sonunda hangi sunucuların ne kadar yük kaldırabildiklerini tespit etmek ve canlı için gerekli kaynakları planlamak kolaylaşmaktadır.

EOF (End Of Fun)
Özcan Acar