Bu yazıda bu hafta başında başıma gelen, network paketlerinin gecikmesi neticesinde Oracle kullanıcıların işlemlerinde yaşağıdığı ani yavaşlamayı, sebebi ve sonuç analiz metodu ile birlikte açıklayacağım. Aslında olayın hikayesi, bazı kullanıcıların bu Salı günü aniden kullandıkları programın cevap süresinin ani olarak yavaşladığından şikayet etmesiyle başladı. Kullanılan program istemci/veritabanı yapısında bir programdır ve bu programı AR-GE bölümünde sınırlı sayıda kullanıcı kullanmaktadır. Kullanılan Oracle 10g veritabanı ise dedicated yapıda ayrı bir Linux sunucu üzerinde hizmet vermektedir.
İlk iş olarak toolkit’lerimi kullanarak paylaşımlı havuzdan aşırı önbellek kullanan işlem olup olmadığını tespit ettim, ancak gerek proses başına, gerekse SQL ve PL/SQL işlemi başına önbellek kullanımında bir anormallik yoktu. Ayrıca, SGA alanında ve belli başlı hit oranlarındada geçtiğimiz haftaya göre bir farklılık yoktu. Bunun ardından AWR raporunu hem geçen hafta Pazartesi-Salı günlerini kapsayacak şekilde, hemde bu hafta Pazartesi-Salı günlerini kapsayacak şekilde 2 sefer çalıştırdım.
Geçen hafta Pazartesi-Salı günlerini kapsayan AWR raporu;
Top User Events
Event | Event Class | % Activity | Avg Active Sessions |
CPU + Wait for CPU | CPU | 18.16 | 0.19 |
db file sequential read | User I/O | 14.10 | 0.12 |
db file scattered read | User I/O | 11.30 | 0.08 |
log file sync | Commit | 4.03 | 0.03 |
enq: TX - row lock contention | Application | 1.96 | 0.06 |
Event | Event Class | % Activity | Avg Active Sessions |
db file parallel write | System I/O | 2.92 | 0.03 |
CPU + Wait for CPU | CPU | 8.65 | 0.03 |
log file parallel write | System I/O | 3.51 | 0.02 |
reliable message | Other | 1.75 | 0.01 |
Bu hafta Pazartesi-Salı günlerini kapsayan AWR raporu:
Top User Events
Event | Event Class | % Activity | Avg Active Sessions |
CPU + Wait for CPU | CPU | 14.16 | 0.18 |
db file sequential read | User I/O | 12.10 | 0.12 |
db file scattered read | User I/O | 8.30 | 0.07 |
log file sync | Commit | 3.17 | 0.02 |
enq: TX - row lock contention | Application | 1.64 | 0.02 |
Top Background Events
Event | Event Class | % Activity | Avg Active Sessions |
db file parallel write | System I/O | 2.62 | 0.04 |
CPU + Wait for CPU | CPU | 9.54 | 0.04 |
log file parallel write | System I/O | 2.43 | 0.05 |
reliable message | Other | 1.98 | 0.02 |
Yukardada görüldüğü üzere bu haftaki bekleme olayları, geçen hafta aynı periyoda nazaran yaklaşık %10 daha iyi. Peki o zaman sorun nerede???
AWR raporunda SQL*NET ile ilgili zirvede bir bekleme olayı olmamasına rağmen TCP paketlerinde veya network transferinde bir sıkıntı yaşandığından şüphelendim. Aslında aşağıdaki sorguyu çalıştırdıktan sonra sorunun kaynağını net şekilde gördüm.
SQL> select distinct event from stats$system_event
2 where event like 'SQL%';
EVENT
----------------------------------------
SQL*Net message from client
SQL*Net message to client
SQL*Net more data from client
SQL*Net more data to client
2 where event like 'SQL%';
EVENT
----------------------------------------
SQL*Net message from client
SQL*Net message to client
SQL*Net more data from client
SQL*Net more data to client
SQL*Net more data from client
…
Ardından tarih aralıklarındaki istatistik snapshotları kullanarak aldığım raporu inceliyorum. Geçen haftanın snapshotu aşağıdadır, bazı kolonları çıkardım bu yazıda…
SNAPSHOT_START SNAPSHOT_END TYPE STATISTIC WAIT_SECOND
-------------------------------------------------------------------------------------------------------------------------------
20110328 10:00:35, 20110329 16:00:35 WAIT, SQL*Net message to client 1.45ms
20110328 10:00:35, 20110329 16:00:35 WAIT SQL*Net more data to client 1161.58ms
20110328 10:00:35, 20110329 16:00:35 WAIT SQL*Net message from client 848.21ms
Bu hafta aynı tarih dilimini kapsayan snapshotlardaki SQL*Net bekleme olayları ise aşağıdadır.
SNAPSHOT_START SNAPSHOT_END TYPE STATISTIC WAIT_SECOND
--------------------------------------------------------------------------------------------------------------------------------
20110404 10:00:35, 20110405 16:00:35 WAIT SQL*Net message to client 1.55ms
20110404 10:00:35, 20110405 16:00:35 WAIT SQL*Net more data to client 8633.65ms
20110404 10:00:35, 20110405 16:00:35 WAIT SQL*Net message from client 5215.37ms
Dikkat çekici nokta, “SQL*Net message to client” değeri geçen haftaki aynı periyoda göre yaklaşık %5 artmasına rağmen, “SQL*Net more data to client” ve “SQL*Net message from client” bekleme değerleri geçen hafta aynı periyoda göre yaklaşık 8 kat artmış gözükmekte!
Bu bilgi ışığında “SQL*Net more data to client” ve “SQL*Net message from client” bekleme olayları üzerine odaklanıyorum. Pek çok kişi “SQL*Net more data to client” olayındaki cevap süresinin yüksek olmasını, network gecikmeleri olarak bilmektedir. Halbuki, network bant genişliğinde yaşanan gecikmeler veya TCP paketlerinin sunucuyu terketmesi ve istemciye ulaşması esnasındaki gecikmeler, “SQL*Net message to client” paketi ile meydana gelen bekleme olayını işaret etmez. Kısacası, “SQL*Net message to client” ve “SQL*Net more data to client” paketleri network gecikmelerinin ölçülmesinde kullanılmaz.
Peki o zaman yüksek cevap süresine sahip olan “SQL*Net more data to client” ve “SQL*Net more data to client” olayı nedir? Aslında bu olaylar Oracle cevap mesajının, SDU tamponundan sunucu üzerindeki TCP gönderim tamponuna(TCP send buffer) ne kadar süre içerisinde yerleştirildiğini ölçümlemeye yarayan değerlerdir. Oracle cevap mesajı TCP gönderim tamponuna yerleştirildiğinde, Oracle sunucu prosesi işleme devam eder ve bir sonraki “SQL*Net message to client” olayını beklemeye başlar. Bu zaman anından itibaren teslim alınan paketin network ortamına iletilmesinin sorumluluğu bu TCP yığınındadır. Aslında Oracle sunucusunda bu mesaj paketi TCP soket tampondan çıktığı andan itibaren ölçebilecek bir mekanizma yoktur, bu sebeple bu prosesi network gecikme ölçüm metoduyla karşılaştırmak mümkün değildir.
Bununla beraber “SQL*Net message to client” ve “SQL*Net more data to client” olayları birbirinden tamamen farklıdır. Başlangıçta, alım verisini içeren ilk SDU(session data unit) tamponu gönderilmekte ve TCP tampona “SQL*Net message to client” olarak yazılmaktadır. Bazı durumlarda bir çağrı için Oracle daha fazla veriyi yazma ihtiyacı duyar, ardındanda ilk SDU paketi içine kendini yerleştirir. Bu durumlarda, bu çağrı için yapılan ilave çağrılar “SQL*Net more data to client” olarak gönderilmektedir. Bu paketlerin sıklığı ve “SQL*Net message to client” sayısı ile ilişkisi aşağıdaki faktörlere bağlıdır;
- Oracle Net SDU büyüklüğü
- Çağrı başına istemciye dönen veri miktarı
İlk önce geçtiğimiz haftaki periyod ile bu haftaki periyod arasında çağrı başına istemciye dönen veri miktarında artış olup olmadığını kontrol ediyorum. Çağrı başına istemciye dönen veri miktarı kavramı, ardışık paketlerin dizi büyüklüğü(arraysize) yeterli büyüklükte olmadığı durumlarda SDU tamponundan kendilerini daha uzun zaman zarfında TCP soket tamponuna iletmesi demektir, böylece bu işlem esnasında TCP gönderim tamponunda bekleme oluşacaktır. Bunun yanında, her bir “fetch” çağrısında kullanılan “arraysize” değeri arttığı zaman ise, bu artışa paralel olarak SDU tamponundan TCP gönderim tamponuna daha seyrek bir trafik olacak ve haliyle “SQL*Net more data to client” gecikmeleri azalacaktır. Böylece, bütün bir Oracle veri paketinin işlenmesi daha kısa zamanda olacaktır. Kontrol sırasında “arraysize” değerinin veritabanı başladığı andan itibaren değişmediğini tespit ettim, yanı sıkıntının kaynağı çağrı başına istemciye dönen veri miktarı değil.
Aslında bu sunucu sadece sınırlı sayıda kullanıcıya hizmet vermekte(yaklaşık 25 kişi) olduğundan, sadece tek bir Oracle 10g instance çalıştırdığından her zaman performans izlemelerinde es geçmiştim.
Ardından SDU tampon büyüklüğü olayına odaklanıyorum. Network arayüzündeki SDU tampon büyüklüğü yeterli boyutta değilse, “SQL*Net more data to client” cevaplarının bekleme olayında artış olacaktır. Yani yeterli büyüklükte olmayan SDU tamponuna daha küçük paketler daha sık yazma işlemi yapacak ve TCP soket tamponuna doğru artan trafikten dolayı işlem bitiş süresi artarak beklemeler meydana gelecektir. Sonuçtada, TCP gönderim tamponunun bu paketi SDU tampondan alıp işleme esnasındaki toplam süresi uzayacaktır.
Kendi sorunuma odaklandığımda ise; ilk olarak Oracle sunucusunda işletim sistemi network arayüzü MTU büyüklüğünü kontrol ediyorum, network arayüzünde MTU değeri 2048 olarak ayarlı, ardından tnsnames.ora dosyasını kontrol ediyorum ki aşağıda görüldüğü üzere değer 2048(instance adı ve sunucu adını değiştirdim)
xxx =
(DESCRIPTION=
(SDU=2048)
(ADDRESS=(PROTOCOL=tcp)(HOST=linuxsrv)(PORT=1521))
(CONNECT_DATA=
(SERVICE_NAME=xxx))
)
Bu noktada SDU ve MTU arasındaki ilişkiye değinmek istiyorum. SDU’yu kafamıza göre artırma şansına sahip değiliz. Şöyleki;
- Eğer SDU = MTU ,bu ideal olandır. Herhangi bir fragmentasyon oluşmaz
- Eğer SDU > MTU, fragmentasyon oluşur
- Eğer SDU < MTU , performans artmaz
MTU değerini artırmadan önce network arayüzünün, işletim sisteminin ve elbette kullanılan switch’in bu MTU değerini desteklediğinden emin olmanız gerekmektedir. Tabii, bu durum oldukça şüpheli geldiğinden network takımı ile irtibata geçip switch üzerinde MTU büyüklüğünde herhangi bir değişiklik yapılıp yapılmadığını soruyorum ve aldığım cevap “Evet. 3 Nisan Pazar günü networkte yapılan bakım çalışması neticesinde bazı siwtchlerde MTU ayarı 1024’e çekildi. Bahsedilen switch'tede MTU ayarı düşürüldü. Neden bu kadar önemli bu değer sizin için?” cevabını alıyorum. Evet, artık “SQL*Net message to client” paketlerindeki gecikmelerin sebebinin bu MTU ayar değişikliği olduğundan eminim.
Hazır bu sunucuya odaklanmışken, SDU değerini daha iyi seviyelere çıkararak geçen haftada aslında oldukça yüksek değerde olan (ortalama 1162ms) “SQL*Net message to client” cevap süresini optimize etmeye karar veriyorum ve network takımından bu switchin MTU değerini 9000’e çıkarmasını talep ediyorum. Ardından da Oracle sunucusunun çalıştığı Linux sunucusunda MTU değerini 9000’e sabitliyorum.
# vi /etc/sysconfig/network-scripts/ifcfg-eth0
Açılan dosyada MTU değerini "9000" olarak değiştiriyorum. Ardından “service network restart” komutu ile network servislerini yeniden başlatarak MTU değişikliğini kalıcı olarak etkinleştiriyorum. Tabii, daha sonrada tnsnames.ora dosyası içerisinde SDU değerini 9000 olarak değiştiriyorum.
Ardından Çarşamba gününden bugüne kadarki SQL*Net olaylarını izlemek için aşağıdaki raporu alıyorum.
SNAPSHOT START SNAPSHOT_END TYPE STATISTIC WAIT_SECOND
------------------------------------------------------------------------------------------------------------------------------------
20110406 10:00:35, 20110408 10:00:35 WAIT SQL*Net message to client 1.27ms
20110406 10:00:35, 20110408 10:00:35 WAIT SQL*Net more data to client 195.46ms
20110406 10:00:35, 20110408 10:00:35 WAIT SQL*Net message from client 254.37ms
Yukardada görüldüğü üzere “SQL*Net more data to client” ve “SQL*Net message from client “ cevap süreleri bu sorun yaşanmadan önceki ortalama değerlerin bile kat kat altına düştü. Bu arada istemciler işlemlerin çalışması esnasında cevap sürelerinde ortalama %15 iyileşme olduğunu belirtmekteler J
Kayıtlar
Çok bilgilendirici bir yazı benimde benzer sorunum için örnek oldu. Teşekkürler,
YanıtlaSil