Exchange Database Transactions, Version Store, ESE 630

Geçen hafta ilgilendiğimiz Microsoft Exchange projesinde, gecikmelere ve e-posta teslim sorunlarına yol açan bir olayla karşılaştık. Exchange Server sistem yöneticilerinin belki de hayatları boyunca karşılaşmayacağı version store sorununu ve çözüme giden yolu bu blog yazısında okuyabilirsiniz.

Olay DAG yapısına üye bir Exchange Server 2016 sunucuda yaşanıyor. Üzerinde database copy (replication) aktif edilmiş mailbox database’ler var ancak pasif kopyaları tutan diğer DAG üyesi sunucu uzun süredir kayıp ve AD ile güven ilişkisi çoktan kaybolmuş olmasına rağmen hala Exchange organizasyonu için AD configuration partition’da kayıtlı durumda. Kayıp sunucu için cleanup yapılmadığı ve database copy özelliği açık durumda bırakıldığı için de çalışmaya devam eden mevcut sunucu 1 yıldan uzun süredir mailbox database transaction log file biriktirmeye devam ediyor. Bu durumun depolama alanı üzerinde oluşturduğu baskıyı (back-pressure dahil) bir an önce ortadan kaldırmak ve asıl işimiz olan migration çalışmasına yer açmak için database copy özelliğinin devre dışı bırakılması ve biriken log dosyalarının sistem tarafından truncate edilmesi gerekiyor.

Exchange Server DAG Yapılarında Database Replication

Exchange Server DAG yapılarında mailbox database replikasyonlarını anlamak için A ve B sunucusundan oluşan basit bir DAG yapısını ele alalım. DB01 isimli mailbox database’in aktif kopyası A sunucusunda, pasif kopyası B sunucusunda yer alıyor olsun. A sunucusu, DB01’de bir değişiklik gerçekleştiğinde (modified) bu değişikliği aynı zamanda E00007618DC.log gibi unique isimlere sahip log dosyalarına da yazar. Eğer yapıda bu mailbox database’in pasif kopyası varsa, log dosyalarının bir kopyasını B sunucusuna da gönderir. B sunucusu bu log dosyalarını DB01’in pasif kopyasına işler. Böylece aktif ve pasif mailbox database kopyaları eşitlenmiş olur. Ardından ilk backup sonrası ilgili log dosyaları sunuculardan silinir. Bu silme işlemine “log file truncation” diyoruz. Eğer A sunucusu herhangi bir sebepten ötürü B sunucusuna bu log dosyalarını gönderemez ise ne olur? Tekrar gönderebileceği zaman gelene kadar biriktirmeye başlar… Bu pozisyondaki bir mailbox database için backup alınması ya da circular logging aktif edilmesi durumu değiştirmez. B sunucusu tekrar erişilebilir olana ya da ilgili DB’lerden database copy özelliği kaldırılana kadar log dosyaları birikmeye devam eder.

Log File Truncation Sonrası Yaşanan Problem, Etkiler ve Belirtiler

Olay öncesi Remove-MailboxDatabaseCopy ile standart prosedürü takip ederek uzun süredir log biriktiren mailbox database’ler için pasif kopya ilişkilerini kaldırdık ve birkaç saat sonra başlayacak backup görevini takiben log file truncation süreci için sunucuyu kendi haline bıraktık. Ardından sabah gelen bildirim ile e-posta akışında gecikmeler ve teslimat sorunları yaşandığını öğrendik.

Durumu kontrol ettiğimizde gece backup görevinin tamamlandığını, log file truncation sürecinin başarılı şekilde gerçekleştiğini, depolama alanı üzerinde dramatik seviyede boş alan açıldığını, görünürde sunucuyu meşgul eden herhangi bir iş ya da uygulama olmadığını, sunucunun yüksek kapasiteli işlemci/bellek/depolama/ağ gibi altyapı kaynaklarının fazlasıyla müsait durumda olduğunu ve Exchange Server üzerinde herhangi bir back-pressure alarm oluşmadığını doğruladık. Ancak e-posta akışı birkaç dakika boyunca normal seyrinde ilerlerken, birkaç dakika boyunca bazı iletilerde gecikme ya da NDR ile birlikte teslimat sorunları yaşanıyordu ve bu durum bir döngü şeklinde devam ediyordu. Sorun anında cached mode çalışan Outlook’lar sunucuya bağlı durumda kalmaya devam ederken, OWA gibi online servislerin login sayfaları açılıyor ancak başarılı giriş yapılamıyordu. Yine sorun anında bazı iletiler Outlook’ların giden kutusunda beklerken, sunucu üzerindeki transport queue’da da birikmeler yaşanıyordu. Sorunun kısa süreliğine düzeldikten sonra yeniden ortaya çıkması ve bu durumun bir döngü şeklinde tekrar etmesi dikkatimi çeken ilk nokta oldu.

Sorun anında running durumdaki process’leri ve bu process’lerin özellikle disk aktivitelerini incelediğimizde, Microsoft.Exchange.Store.Service.exe’lerin diğer process’lerden ayrıştığını, özellikle sorun anında mailbox database dosyaları üzerinde yoğun ve uzun süreli okuma/yazma işlemleri gerçekleştirdiklerini ve ayrıca çok sayıda yeni transaction log file oluşturduklarını gözlemledik. Bu da arka planda hala devam eden bazı database işlemlerinin varlığını fark etmemize yardımcı oldu.

Sorunu incelemeye devam ederken Windows Event Log \ Application altında ESE (Extensible Storage Engine) tarafından oluşturulan Event ID 630 kayıtlarını gördüm ve bu event’lerin döngüsel olarak sorun anında oluşmaya başladığını, sorun geçici olarak ortadan kalktığı anlarda ise yeni event oluşmadığını fark ettim. ESE 630 numaralı bu event’in bir örneğini aşağıda görebilirsiniz.

Information Store - EX2016-1 (1552) EX2016-1: The version store for this instance (0) has a long-running transaction that exceeds the maximum transaction size. 
Current version store size for this instance: 818Mb 
Maximum transaction size for this instance: 818Mb 
Maximum version store size for this instance: 1023Mb 
Long-running transaction: 
   SessionId: 0x000000D89AAA7E20 
   Session-context: 0x00000000 
   Session-context ThreadId: 0x000000000000665C 
   Cleanup: 1 
   Session-trace: 
62245@8:30:33 AM
57573@8:30:33 AM

Tüm bu parçaları birleştirdiğimizde, dün gece gerçekleşen log file truncation sonrası mailbox database’ler üzerinde bir takım artçı işlerin hala çalışmaya devam ettiğiniz anlıyoruz. Peki mailbox database’lerdeki bu işler neden hala bitmemiş? Neden bir döngü şeklinde çalışıyorlar? Bu sırada neden erişim sorunları yaşanıyor? gibi sorulara event id 630 ile yanıt vermek mümkün çünkü bu event özetle şöyle diyor: Exchange Information Store servisinin “version store” alanında maksimum işlem boyutunu aştığı için tamamlanamayan ve uzun süredir devam eden işler var… Long-running transaction olarak adlandırılan bu uzun süredir çalışan işler ve dolayısıyla yaşanan birikme, bu yazıya da konu olan sorunun kaynağını teşkil ediyor. Bu sebeple çözüm arayışında yönümüzü mailbox database transaction’ları gerçekleştiren Information Store servisine, ESE’ye ve özellikle de Version Store’a çeviriyoruz. Öncesinde bu bileşenlerin görevlerine bakalım.

Exchange Information Store Servisi

Microsoft Exchange Server’lar üzerinde mailbox database’leri yöneten servistir ve Windows servisler altında MSExchangeIS ya da Microsoft Exchange Information Store ismiyle yer alır. Database transaction’ların yönetilmesi, ESE entegrasyonu vasıtasıyla database file’lara işlenmesi ve bu sırada oluşan transaction log file’lardan sorumludur. Geçmiş sürümlerde Store.exe isimli tek bir process olarak çalışan Information Store servisi, Exchange Server 2013 ile birlikte controller/worker process modeline geçmiştir. Bu sebeple 2013’ten bu yana Microsoft.Exchange.Store.Service.exe isimde bir controller process ve mailbox database’ler için Microsoft.Exchange.Store.Worker.exe isminde worker process’ler şeklinde çalışır. Ayrıca birkaç dll vasıtasıyla ESE altyapısını da kendine entegre eder. Bu sebeple Exchange mimarisinde Information Store ve ESE kavramları fazlasıyla iç içe geçmiş durumdadır. Microsoft Exchange Information Store servisini, ESE altyapısını da implement ve operate eden kapsayıcı bir servis olarak düşünebilirsiniz.

Extensible Storage Engine (ESE)

Bir zamanlar JET Blue Engine olarak bilinen Extensible Storage Engine (ESE), Microsoft tarafından geliştirilen ve belirli işler için optimize edilmiş bir Non-SQL veritabanı motorudur. Microsoft Exchange Server, Active Directory, Windows Search, Windows Update Client, SCOM Agent, Exchange Online ve bazı diğer Office 365 servisleri gibi çeşitli yerlerde görev alan ESE, neredeyse 30 yıldır hayatta kalmayı başarmış ve bir süredir de hayatına open source olarak devam eden ender tasarımlardan biridir.

Microsoft Exchange mimarisinde ESE ayrı bir servis ya da process olarak yer almaz ve birkaç DLL vasıtasıyla doğrudan Information Store servisine entegre şekilde çalışır. Bu yüzden de fazlasıyla arka planda kalan bir bileşendir. EDB uzantılı database file’lar, dirty shutdown, clean shutdown, database check/repair/recovery işleri için kullanılan ESEUTIL aracı hep ESE ile ilişkili kavramlardır. Exchange mimarisinde mailbox database’ler dışında ip filtering database (IpFiltering.edb), queue databse (mail.que), transaction log file replaying/truncation, backup öncesi database’lerin freeze edilmesi ve sonra tekrar çözülmesi gibi işlerden de aslında hep ESE sorumludur.

Version Store

Exchange Information Store servisine entegre çalışan ESE’nin önemli bir parçası olan Version Store, database transaction’ların disk’e yazılmadan önce geçici olarak memory’de tutulduğu yerdir. Örneğin gelen bir iletinin posta kutusuna teslim edilmesi ya da giden bir iletinin gönderilmiş öğeler klasörüne kayıt edilmesi, mailbox içinde bir klasör oluşturulması/silinmesi/düzenlenmesi, bir postanın taşınması, bir takvim öğesinin oluşturulması ya da değiştirilmesi gibi aklınıza gelebilecek her türlü iş, çeşitli transaction’lar vasıtası ile mailbox database’lere işlenirler. Buna Exchange Server’ın arka planda gerçekleştirdiği online defragmentation görevleri, databse indexing, diğer maintenance task’lar ve log file truncation gibi şeyler de dahildir.

ESE mimarisinde bir mailbox database’de yer alan nesnenin (veri/kayıt/record) örneğin değiştirilmesi gerektiğinde (modified), ilgili transaction gerçekleşmeden önce söz konusu nesnenin henüz değişmemiş halinin bir kopyası geçici olarak Version Store’a alınır ve modified işlemi sonuçlanana kadar gerektiğinde kullanılmak üzere bu alanda muhafaza edilir. Bu sayede ESE, ilgili veri modified sürecinde olsa dahi bir kopyasını okuma amaçlı talep eden diğer transaction’lara servis etmeye devam edebilirken, herhangi bir problem durumunda transaction rollback yaparak veriyi kolayca eski haline döndürme şansına da sahip olur. ESE mimarisinde transaction rollback önemli bir kabiliyet çünkü mailbox database’lerde atomic transaction modelini mümkün kılıyor. Kabaca bir transaction’ın ya tamamının gerçekleştiği ya da hiçbir parçasının gerçekleşmediği işlemlere atomic transaction deniyor. Örneğin bir banka için A hesabından B hesabına para transferi atomic transaction’lara güzel bir örnektir. Parayı A hesabından çekmek ve B hesabına kaydetmek olmak üzere iki işlemden oluşur. Bu işlemleri bir atomic transaction içinde gerçekleştirmek, herhangi bir hata durumunda veritabanının tutarlı kalmasını sağlar çünkü bu iki işlemden biri başarısız olursa A hesabındaki para kaybolmamış ve B hesabına da yatırılmamış olur.

Version Store’un yer aldığı memory alanı, her bir mailbox database için ayrı çalışan Microsoft.Exchange.Store.Worker.exe isimli process’lerin memory alanından ayrılır. Bu sebeple ilgili worker process’in memory kullanım miktarına dahil şekilde çalışır. Ayrıca hem memory’i taşırma ihtimaline karşı hem de bitişik/sıralı memory alanı gerektirdiğinden, çalışma anında dinamik olarak belirlenemeyen bir üst limite tabidir. Microsoft Exchange yapısında Version Store’un memory kullanım limiti, AD configuration partition’da yer alan msExchESEParamMaxVerPages isimli bir attribute ile belirlenir. Ayrıca Version Store’un anlık memory (bucket/page) kullanım durumu aşağıdaki performance counter ile DB bazlı olarak izlenebilir.

MSExchange Database > Version Buckets Allocated > Information Store – DB01

Version store alanının en büyük düşmanı ise event id 630’da da bahsi geçen long-running transaction’lardır; Bitmek bilmeyen ve uzun süredir çalışmaya devam eden database işlemleri… Çeşitli sebeplerden ötürü tamamlanamayan ve çok uzun süre açık kalan bu tip transaction’lar Version Store alanında yer kaplayarak maksimum boyuta ulaşana kadar büyümesine sebep olabilirler. Haliyle de birikmeye yol açan eski transaction’lar bitene ya da bir şekilde rollback yapıp arkadan gelenler durdurulana kadar o database için yeni update/modified işlemleri gerçekleştirmek mümkün olamaz. Bu yazıda ele aldığım sorun da tam olarak böyle bir case.

Çözüm

Çözüm long-running transaction’ların kısa sürede tamamlanabilmesi için ESE Version Store’a daha fazla memory alanı ayırmaktan geçiyor. Bunun için de AD configuration partition’a bağlanıp msExchESEParamMaxVerPages attribute değerini düzenlemek gerekiyor.

Bu attribute, örneğin DB01 isimli bir mailbox database için aşağıdaki konumda yer alır.

Configuration / Services / Microsoft Exchange / <OrganizationName> / Administrative Groups / Exchange Administrative Group (FYDIBOHF23SPDLT) / Databases / DB01

İlgili database için attribute editor listesinde msExchESEParamMaxVerPages değerini düzenlemek ve AD configuration partition’a bağlanmak için ise Adsiedit.msc aracını kullanabilirsiniz.

Bu attribute değerinin mailbox database başına ayarlandığını ve Version Buckets Allocated performance counter’a bakarak tavan seviyesinde kullanım tespit ettiğiniz her bir mailbox database için ayrı ayrı ayarlanması gerektiğini unutmayın.

msExchESEParamMaxVerPages parametresi varsayılan olarak <not set> şeklinde ayarlıdır ve bu, limit değerinin sunucu mimarisi, işlemci sayısı ve toplam bellek miktarına göre sistem tarafından belirlendiği anlamına gelir. Bu sebeple size burada sabit bir değer vermem doğru olmayacaktır ama uygun değere yaklaşık olarak ulaşmak için bir formül söyleyebilirim. Söz konusu bucket’lar yani page’ler 64-bit sistemlerde 32KB’lık memory parçaları şeklinde ayrılırlar ve limiti belirleyen en önemli faktör budur. Diğer tüm faktörler sonuca çok küçük seviyede etki ettiğinden kafa karıştırmaması için bu case’de yok sayılabilir. Eğer yine de öğrenmek isterseniz şurada Active Directory veri tabanı NTDS.dit için çalışan ESE Version Store limitlerini ele alan güzel bir yazı var. Yalnız bunun Exchange Server yapısında çalışan ESE Version Store’a uygun olup olmadığından emin değilim çünkü uymayan bazı noktalar olduğunu düşünüyorum. Ama büyük oranda benzerlik gösteriyor.

Sadeleştirilmiş hesaplama formülü is şu şekilde: 64-bit olarak çalışan bir Exchange Server’da ESE Version Store’u örneğin 5GB bellek kullanacak şekilde ayarlamak için aşağıdaki gibi önce 5GB’ı KB’a çevirin ve sonra 32’ye bölün. Çıkan sonuç sizi yaklaşık olarak uygun bir msExchESEParamMaxVerPages değerine ulaştıracaktır.

(5 * 1024 * 1024) / 32 = 163840

Daha sonra ilgili DB ya da DB’ler için msExchESEParamMaxVerPages attribute değerini uygun şekilde ayarlayıp Exchange Server’ı ya da sadece Information Store servisini yeniden başlatarak yeni limitlerin aktif olmasını sağlayın. Ardından Version Buckets Allocated performance counter ile anlık kullanımı izlemeye devam edin. Hala yeterli gelmediğini gözlemliyorsanız bu değeri kademeli olarak yükseltmeyi deneyebilirsiniz. Ancak bu sırada şuna dikkat edin: Eğer ESE yeni limitleri de dolduracak seviyede kullanım sergilerse ve bu sırada sunucuda yeterli fiziksel bellek alanı yoksa, bu sefer de bir başka koruma mekanizması olan back-pressure devreye girerek bazı servisleri baskılamaya ve farklı erişim sorunları yaşanmasına sebebiyet verebilir. Limitleri artırırken bu noktaya dikkat edin ve emin değilseniz 12.000’den itibaren küçük artışlar tercih ederek ilerleyin.

ESE işlerini bitirdikten ve Version Buckets Allocated performance counter kalıcı şekilde düştükten sonra msExchESEParamMaxVerPages attribute değerini tekrar <not set> yapmayı unutmayın. Normal işleyişte bu değerin yüksek olması hiçbir işinize yaramaz.

Sonuç

Bugüne kadar sayısız Microsoft Exchange projesi yapmış biri olarak normal işleyişte bile doğası gereği aşırı transaction log üreten ya da çeşitli sorunlardan ötürü log biriktiren birçok sunucuyla çalıştım. Ama bu seferki gerçekten ziyadesiyle nevi şahsına münhasır bir case oldu. Özellikle ESE’nin günümüzde fazlasıyla arka planda kalmış olması, en önemli göstergelerden biri olan Event Id 630’un üretici belgeleri dahil hiçbir kaynakta açıkça yer almaması, sorunun benzer belirtiler ile ortaya çıktığı diğer örneklerde tavsiye edilen mailbox’ları yeni database’lere taşıma fonksiyonlarının da çalışmıyor oluşu gibi faktörler bizim case’de işleri bir miktar zorlaştırdı. Diğer taraftan bu transaction’lar görünür ve geri alınabilecek işler değildi. Bu sebeple ertelemek ya da yarıda kesmek gibi seçeneklerimiz olmadı.

Yaşanan sorunun sebebini anlamak ve doğru müdahaleye karar vermek zaman alsa da gün sonunda çözüm basitti. Yaptığımız tek şey Version Store limitlerini artırarak ESE’ye biriken transaction’ları tamamlayabilmesi için daha fazla memory alanı açmak oldu. Ayrıca her ne kadar event id numaraları örtüşmese de sorunu anlamamıza yardımcı olan eski bir troubleshooting version store issues belgesini buraya bırakıyorum. Version store sorunlarıyla ilgili işinize yarayabilir.

Başlarda ~11.000 seviyesini geçemeyen Version Buckets Allocated performance counter’ın, msExchESEParamMaxVerPages düzenlemesinden sonra ~250.000 gibi bir tavan değerine ulaştığını ve ilgili worker process’in ~30GB memory kullandığını gördük. Bu haliyle ESE birkaç saat içerisinde tüm işleri tamamladı ve bu transaction’lar sonrasında 200.000 yeni log dosyası oluştu. Oluşan bu yeni log dosyalarının sayısı, arka planda biriken işin büyüklüğünü anlamak adına güzel bir nokta… Diğer taraftan aynı Exchange Server gün içerisinde tüm kullanıcılara hizmet verirken Version Buckets Allocated performance counter 0-10 arası seyrediyor ve günlük ~2.000 log dosyası oluşturuyordu. Eğer msExchESEParamMaxVerPages düzenlemesi yapılmasaydı ne olurdu? Aslında bu işler yine tamamlanırdı ancak muhtemelen günler sürerdi ve tabii bu sırada servis kesintileri de devam ederdi.

Sonuç olarak özellikle çok sayıda transaction log birikmiş sistemlerde bu dosyaların silinmesiyle ilgili bir çalışma başlatmadan önce ESE Version Store memory limitine dikkat etmenizi, gerekli görüyorsanız msExchESEParamMaxVerPages parametresini düzenlemenizi, işlem sırasında ve sonrasında Version Buckets Allocated performance counter ve Event ID 630’u takip etmenizi tavsiye ederim.