Yüksek “DB Time” değeri hakkında bir inceleme

Yüksek CPU kullanımı ile kendini göstermeyen ve bekleme sebebiyle oluşan performans problemi ile karşılaşılırsa ne yapılır? Bekleme belki mandallar(latches), kilitler veya mesela yavaş disk gibi farklı kaynaklar yüzünden olabilmektedir. Oracle 10g sürümünden itibaren CPU zaman tüketimi ve beklemesini gözönünde bulunduran sözde zaman modeli istatistiklerini sunmaktadır. Bu istatistikler (V$SYS_TIME_MODEL) ve oturum seviyesi için (V$SESS_TIME_MODEL) sistem görünümlerinden elde edilebilir. İşin özünde, veritabanı instance içinde harcanan zaman değerlendirmeye alınmaktadır.

“DB Time”  veritabanı kullanıcı seviyesi çağrılarını yerine getirirken geçen zaman miktarının mikrosaniye bazında toplamıdır. PMON gibi instance arkaplan proseslerinde geçen süre bu hesaplamaya dahil edilmez.

“DB Time” metriğine dahil olan durumlar aşağıda yer almaktadır;

·         DB CPU

·         Bağlantı yönetimi çağrısı esnasında geçen süre

·         Sekuans yüklemesi esnasında geçen süre

·         SQL yürütmesi esnasında geçen süre

·         Ayrıştırma esnasında geçen süre

·         PL/SQL yürütmesi esnasında geçen süre

·         Gelen PL/SQL rpc çağrıları esnasında geçen süre

·         PL/SQL derlemesi esnasında geçen süre

·         Java yürütmesi esnasında geçen süre

Burada bekleme olayı hakkında tek bir cümle yeterli gelmez. Ancak  bekleme süresinin, SQL izleme dosyaları içinde yer alan veritabanı çağrıları tamamlanma süresi içerisine yerleştirildiği gözönünde bulundurulmalıdır; bu noktada zaman modelli istatistiklerin farklı bir yaklaşım izlemiş olacağı şaşırtıcı olmamalıdır.

“DB Time”  değerini temel ölçüt olarak kullanarak ASH ve AWR verisinin kombinasyonuyla, ADDM en önemli tepki süresi düşüşlerini sunacak olan hareketlere odaklanabilir ve bu tepki süresi düşüşlerinin daha fazla CPU veya disk kaynağındanmı, bireysel SQL komutlarındanmı veya kilit sorunlarının bertaraf edilmesindenmi olduğunu işaret edebilmektedir. Çünkü “DB Time”  pek çok seviyede toplanabilir(oturum, servis, instance gibi) ve hangi verinin uygun olduğu ve optimizasyon alıştırmasının ne amaçla olduğuna bağlı olarak pek çok farklı yönden kullanılabilir. Bu durumu aşağıda bir örnek ile açıklayalım.

DBMS_SYSTEM.wait_for_events paketi, ilgili bekleme olayı için tanımlanan oranda yapay bekleme süresi üretir.  Yeni bir veritabanı oturumunun başlangıcında, V$SESS_TIME_MODEL görünümündeki tüm değerler neredeyse sıfırdır.

SQL> SELECT stat_name, value/1000000 time_secs FROM v$sess_time_model

WHERE (stat_name IN ('sql execute elapsed time','PL/SQL execution elapsed time')

OR stat_name like 'DB%')

AND sid = userenv('sid');

STAT_NAME                      TIME_SECS

----------------------------   ----------

DB time                        .018276

DB CPU                         .038276

sql execute elapsed time       .030184

PL/SQL execution elapsed time  .007097

Ardından, “db file scattered read” olayı için bir saniye yapay bekleme yapacak birtakım “fake” bekleme süreleri oluşturuyorum(SELECT komutu full tablo taramasına sebebiyet verdiği durumda bu bekleme tipi meydana gelecektir, aslında bu olayı yapay olarak oluşturduk bu test senaryosunda).

SQL> EXECUTE dbms_system.wait_for_event('db file scattered read', 1, 1);

PL/SQL procedure successfully completed.

“sql execute elapsed time” ve “PL/SQL execution elapsed time” değerlerinin her ikisininde yaklaşık olarak 1 saniye artmış olduğunu belirtmek isterim. Açık olarak, bu testin yapay doğası nedeniyle, geçen süre(elapsed time) iki sefer hesaba katıldı. “DB CPU” metriği sadece biraz daha artış gösterdi  ve SQL ile PL/SQL geçen süresinide topladığından itibaren “DB time” değeri ayrıca 1 saniye artmış oldu. Aşağıdaki sonuca bir bakalım.

SQL> SELECT stat_name, value/1000000 time_secs FROM v$sess_time_model

WHERE (stat_name IN ('sql execute elapsed time','PL/SQL execution elapsed time')

OR stat_name like 'DB%')

AND sid=userenv('sid');

STAT_NAME                      TIME_SECS

----------------------------- ---------

DB time                        1.030818

DB CPU                          .045174

sql execute elapsed time       1.017276

PL/SQL execution elapsed time   .987208

Olaylar üzerinde, SQL yürütmesinin bir parçası olarak oluşan bekleme, “sql execute elapsed time” metriği içine dahil edilmektedir. Idle sınıfı bekleme sınıfı dışındaki diğer bekleme süreleride “DB time” içine dahil edilir.

Sadece CPU kullanımı gibi  durumlarda, bir şekilde “DB Time” değerinin normalleştirilmesi gerekmektedir. Sistem üzerinde ne kadar çok işlemci çalışırsa ve her bir işlemci aynı kaynak için ne kadar çok rekabet ederse, sistem seviyesinde o kadar çok bekleme süresi birikecektir.

Mesela; on işlemcinin her biri aynı TX ön kuyruğu için bir saniye beklerse, sonuç olarak her bir işlemci için toplam bekleme süreside on kat artacaktır. “DB time”, snapshot aralığı yoluyla normalleştirilebilir. Bu metrik aslında kimi kişilerce “relative(ilişkili) db time” olarak adlandırılır. Bu noktada yeniden manuel hesaplamaya geçilir. Örneğimde kullandığım Oracle 10g platformu için, ilgili olan bir Statspack alıntı raporu aşağıdadır.  “İlişkili DB Time” hesaplamasında kullanılan kısımlar aşağıda koyu font ile belirtilmiştir.

Snapshot Snap Id Snap Time Sessions Curs/Sess Comment

---------- ------------------ -------- --------- -------------------

Begin Snap: 73 06-Nov-11 17:04:06 24 3.3

End Snap:   74 06-Nov-11 17:09:54 24 3.3

Elapsed: 5.80 (mins)

Time Model System Stats DB/Inst: ORCL/ORCL Snaps: 73-74

-> Ordered by % of DB time desc,

Statistic name                Statistic Time (s)   % of DB time

----------------------------- -------------------- ------------

sql execute elapsed time       319.3                100.0

PL/SQL execution elapsed time  316.7                 99.2

DB CPU                         301.4                 94.4

…

DB time                        319.3

Formulasyon olarak “ilişkili DB time” hesaplaması aşağıdaki gibidir:

İlişkili DB Time (s) = DB Time (s) / snapshot aralığı(s)

Yukardaki formül neticesinde;

ilişkili DB Time(s) => 319.3 / (5.80 * 60) = 0.92

İki ardışık snapshot arasında “Relative DB Time” metrik değerini ölçmek için tek bir sorgu da kullanılabilmektedir. Bu, ardışık iki snapshot arası amaca uygun farklı bekleme değerlerinin ölçümü içinde oldukça basit, kısa ve faydalı bir yaklaşım olacaktır.

Bu amaçla, ilk olarak snapshot tanımlayıcılarını açığa vuran ve oluşturulan aralığın geçerli olduğunu doğrulayacak bir görünüm, analizlerde temel yapıtaşı olarak kullanılmak amacıyla oluşturulabilir. Aralık doğrulaması, STATS$SNAPSHOT.STARTUP_TIME  kolonu değerlerinin birbiriyle karşılaştırması yapılarak kontrol edilmektedir. Aşağıda bu doğrultuda sp_gecerli_araliklar adında bir görünüm oluşturulmaktadır. Bu görünümü bir sefer oluşturmak ve ardından bu görünüm üzerinden farklı bekleme olaylarının delta değişimlerini elde etmek üzere çeşitli performans sorgulamaları yapmakta mümkün olmaktadır. Unutmadan belirtmek isterim, kullandığım sürüm Oracle 10.2.0.5’dir.

CREATE OR REPLACE VIEW sp_gecerli_araliklar AS

SELECT *

FROM (

SELECT lag(dbid) over (order by dbid, instance_number, snap_id) AS start_dbid,

dbid AS end_dbid, lag(snap_id) over (order by dbid, instance_number, snap_id) AS start_snap_id,

snap_id AS end_snap_id,

lag(instance_number) over (order by dbid, instance_number, snap_id)

AS start_inst_nr, instance_number AS end_inst_nr,

lag(snap_time) over (order by dbid, instance_number, snap_id)

AS start_snap_time, snap_time AS end_snap_time,

lag(startup_time) over (order by dbid, instance_number, snap_id)

AS start_startup_time, startup_time AS end_startup_time

FROM perfstat.stats$snapshot

) ta

WHERE ta.start_snap_id IS NOT NULL

AND ta.start_dbid=ta.end_dbid

AND ta.start_inst_nr=ta.end_inst_nr

AND ta.start_startup_time=ta.end_startup_time;

“İlişkili db time” metriğini tüm snapshot aralıklarında otomatik olarak hesaplayıp listeleyen ve temel olarak yukardaki sp_gecerli_araliklar adlı görünümü kullanan sorgu aşağıda yer almaktadır.

SQL> SELECT i.start_snap_id, i.end_snap_id,

i.start_snap_time, i.end_snap_time,

(i.end_snap_time - i.start_snap_time) * 86400 AS “Interval(s)”,

round((s2.value - s1.value) / 1000000 /* mikrosaniye değeri saniyeye dönüşmekte */

/ ((i.end_snap_time - i.start_snap_time) * 86400 ), 2)

/* snapshot aralığı ile standartlaştırılır */

AS “R.DB Time/s”

FROM sp_valid_intervals i, stats$sys_time_model s1,

stats$sys_time_model s2, stats$time_model_statname n

WHERE i.start_snap_id=s1.snap_id

AND i.end_snap_id=s2.snap_id

AND n.stat_name='DB time'

AND s1.stat_id=n.stat_id

AND s2.stat_id=n.stat_id

ORDER BY db_time_per_sec DESC;

SnapID SnapID Start Time   End Time       Interval(s)  R.DB time/s

------ ------ -------------- -------------- ------------ ---------

73        74 06.11.11 17:04 06.11.11 17:09  348          .92

51        52 05.11.11 07:45 05.11.11 08:00  850          .02

34        35 27.10.11 19:53 27.10.11 20:00  401          .01

...

Yukardaki sonuç çıktısında da 73 ve 74 numaralı snapshotlar arasındaki geçen sürede en yüksek “ilişkili DB time” olayı gerçekleşmiştir.