Анализ файла трассировки 10046 навел на мысль о том, что в основном код работает с BLOB-данными. Разработчики подтвердили это предположение. Соответствующий фрагмент отчета tkprof приведен ниже:
declare
a blob;
begin
a:=PrintActiveContragent(7720);
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.03 10.50 1521 4766 2600 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.03 10.50 1521 4766 2600 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 5
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
direct path read 1521 0.05 10.38
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 5.86 5.86
********************************************************************************
Остальные рекурсивные вызовы не приводятся ввиду исчезающе малой ресурсоемкости.
Из приведенного видно, что все время потрачено на direct path read, изучение исходного файла трасировки показало, что это были чтения BLOB-поля, причем со слов разработчиков - читалось значение BLOB только из одной строки таблицы. Кроме того, разработчики сообщили, что размер BLOB в той строке примерно 200К.
Очевидно, что происходят множественные чтения BLOB, которые фактически, осущесвтляются непосредственно с диска. Проверив некоторые свойства BLOB этой таблицы, выяснилось среди прочего, что CACHE=NO.
Что ж, напрашивается рекомендация - воспользоваться возможностью кеширования BLOB, используя стейтмент подобный этому: alter table sometable modify lob (blob_field) (cache reads). После такого изменения скорость работы проблемного приложения улучшилась на 3 порядка, в общем можно было бы останоиться, но у некоторых наверняка возникнут сомнения относительно такого включения кеширования, ведь оно фактически может повлиять и на другие приложения, вытесняя из буферного кеша их данные.
Поскольку я достаточно редко имею дело с BLOB-ами, решил их немного поизучать, заодно попытаться сформулировать возможные альтернативные решения вышеприведенной проблемы.
Тестовые данные. Работаю с Oracle 10.2.0.1 (XE), размер блока 8192 байта.
Таблица:
create table t_blob (id number,blob_data blob);
Проверю некоторые ее свойства
SQL> select table_name,column_name,chunk,cache from user_lobs;
TABLE_NAME COLUMN_NAME CHUNK CACHE
------------------------------ -------------------- ---------- ----------
T_BLOB BLOB_DATA 8192 NO
Создаю одну строку со значением в поле BLOB длиной 10000 байт.
SQL> declare
2 l_data blob;
3 l_str raw(1000);
4 begin
5 insert into t_blob values (1,empty_blob());
6 select blob_data into l_data from t_blob where id=1;
7 dbms_lob.open(l_data,dbms_lob.lob_readwrite);
8 for i in 1..10 loop
9 l_str:=utl_raw.CAST_TO_RAW(rpad('z',1000-i,'z')||rpad('x',i,'x'));
10 dbms_lob.writeappend(l_data,1000,l_str);
11 end loop;
12 dbms_lob.close(l_data);
13 commit;
14 end;
15 /
PL/SQL procedure successfully completed.
SQL> select id,dbms_lob.getlength(blob_data) from t_blob;
ID DBMS_LOB.GETLENGTH(BLOB_DATA)
---------- -----------------------------
1 10000
Создаю процедуру, которая читает BLOB поле фрагментами по 1000 байт, в некотором смысле, эмуляция работы кода, который изучался в начале статьи. После каждого чтения проверяется значение статистики с номером 120 для текущей сессии
SQL> select name from v$statname where statistic#=120;
NAME
------------------------------------------------------
physical reads direct (lob)
Процедура:
SQL> create or replace procedure proc2
2 is
3 function GetStat(st# number) return number
4 is
5 l_res number;
6 begin
7 select value into l_res from v$mystat x where x.statistic#=st#;
8 return l_res;
9 end;
10 procedure a1 (p1 in out blob)
11 as
12 l_cnt1 number;
13 l_cnt2 number;
14 ll raw(1000);
15 am binary_integer := 1000;
16 begin
17 dbms_output.put_line('Size: '||dbms_lob.getlength(p1));
18 for i in 1..trunc(dbms_lob.getlength(p1)/1000) loop
19 l_cnt1:=getstat(120);
20 dbms_lob.read(p1,am,1+(i-1)*am,ll);
21 l_cnt2:=getstat(120);
22 dbms_output.put_line('I/O#'||i||' reads: '||(l_cnt2-l_cnt1));
23 end loop;
24 end;
25 begin
26 for i in (select blob_data from t_blob where id=1 order by id) loop
27 a1(i.blob_data);
28 end loop;
29 end;
30 /
Procedure created.
Сравненние работы с полем BLOB, не кешированными (изначально) и кешированным:
SQL> alter session set events '10046 trace name context forever, level 8';
Session altered.
SQL> begin proc2; end;
2 /
Size: 10000
I/O#1 reads: 1
I/O#2 reads: 1
I/O#3 reads: 1
I/O#4 reads: 1
I/O#5 reads: 1
I/O#6 reads: 1
I/O#7 reads: 1
I/O#8 reads: 1
I/O#9 reads: 2
I/O#10 reads: 1
PL/SQL procedure successfully completed.
SQL> alter table t_blob modify lob (blob_data) (cache reads);
Table altered.
SQL> begin PROC2; end;
2 /
Size: 10000
I/O#1 reads: 0
I/O#2 reads: 0
I/O#3 reads: 0
I/O#4 reads: 0
I/O#5 reads: 0
I/O#6 reads: 0
I/O#7 reads: 0
I/O#8 reads: 0
I/O#9 reads: 0
I/O#10 reads: 0
PL/SQL procedure successfully completed.
Исходя из статистик сессии, следуюет, что каждое обращение к некешированному BLOB приводит к запросу на дисковый ввод-вывод. Это же подтверждают данные трассировки сессии. Видно, что значение BLOB хранится в двух блоках, чтение 9-го фрагмента (длиной 1000 байт) фактически затрагивает оба блока.
WAIT #3: nam='direct path read' ela= 23758 file number=1 first dba=55426 block cnt=1 obj#=16099 tim=107520891323
WAIT #3: nam='direct path read' ela= 271 file number=1 first dba=55426 block cnt=1 obj#=16099 tim=107520895284
WAIT #3: nam='direct path read' ela= 249 file number=1 first dba=55426 block cnt=1 obj#=16099 tim=107520897971
WAIT #3: nam='direct path read' ela= 264 file number=1 first dba=55426 block cnt=1 obj#=16099 tim=107520900695
WAIT #3: nam='direct path read' ela= 262 file number=1 first dba=55426 block cnt=1 obj#=16099 tim=107520903592
WAIT #3: nam='direct path read' ela= 235 file number=1 first dba=55426 block cnt=1 obj#=16099 tim=107520906394
WAIT #3: nam='direct path read' ela= 222 file number=1 first dba=55426 block cnt=1 obj#=16099 tim=107520909032
WAIT #3: nam='direct path read' ela= 235 file number=1 first dba=55426 block cnt=1 obj#=16099 tim=107520911710
WAIT #3: nam='direct path read' ela= 205 file number=1 first dba=55426 block cnt=1 obj#=16099 tim=107520914372
WAIT #3: nam='direct path read' ela= 14 file number=1 first dba=55428 block cnt=1 obj#=16099 tim=107520914681
WAIT #3: nam='direct path read' ela= 239 file number=1 first dba=55428 block cnt=1 obj#=16099 tim=107520917641
Некешированный читаестя через "direct path read", кешированный соответственно через "db file sequential read".
Профиль для некешированного BLOB:
begin proc2; end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.04 11 11 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.04 11 11 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 52
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
direct path read 11 0.02 0.02
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
Профиль для кешированного BLOB
begin PROC2; end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 0.06 2 11 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 0.06 2 11 0 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 52
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 2 0.03 0.05
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
Первый итог: любое чтение поля BLOB - приводит к LIO, если поле BLOB не кешируется, то еще и к физическому вводу-выводу. Следовательно, при кодировании алгоритмов, читающих BLOB - поля, более выиграшным будет подход, минимизирующий количество чтений, что есть закономерным. Фактически необходимо преследовать те же цели, что и при оптимизации SQL.
Что же делать если по каким-либо причинам изменение alter table ... modify lob (...) (cache reads) является неприемлемым?
Можно попробовать использовать временный BLOB, причем, кешированный. Сравнивать его, естественно, есть смысл с кешированным BLOB-полем таблицы. В качестве измерительного инструмента - runstats.
SQL> declare
2 l_blob blob;
3 l_blob1 blob;
4 procedure a1 (p1 in out blob)
5 as
6 ll raw(1000);
7 am binary_integer := 1000;
8 begin
9 for i in 1..trunc(dbms_lob.getlength(p1)/1000) loop
10 dbms_lob.read(p1,am,1+(i-1)*am,ll);
11 end loop;
12 end;
13 begin
14 dbms_lob.createtemporary(l_blob1,true);
15 select blob_data into l_blob from t_blob where id=1;
16 DBMS_LOB.COPY (l_blob1,l_blob,dbms_lob.getlength(l_blob));
17 runStats_pkg.rs_start;
18 for j in 1..1000 loop a1(l_blob); end loop;
19 runStats_pkg.rs_middle;
20 for j in 1..1000 loop a1(l_blob1); end loop; --Temporary BLOB
21 runStats_pkg.rs_stop;
22 dbms_lob.freetemporary(l_blob1);
23 end;
24 /
Run1 ran in 31 hsecs
Run2 ran in 10 hsecs
run 1 ran in 310% of the time
Name Run1 Run2 Diff
STAT...active txn count during 1 0 -1
STAT...consistent gets - exami 1 0 -1
LATCH.library cache lock alloc 0 1 1
STAT...redo entries 8 9 1
STAT...cleanout - number of kt 1 0 -1
LATCH.redo allocation 10 9 -1
STAT...calls to kcmgcs 4 5 1
LATCH.library cache lock 6 8 2
LATCH.library cache pin 6 8 2
LATCH.resmgr:resource group CP 4 2 -2
LATCH.redo writing 2 0 -2
LATCH.cache buffers lru chain 8 5 -3
LATCH.object queue header oper 8 5 -3
STAT...recursive cpu usage 5 2 -3
LATCH.messages 4 0 -4
STAT...enqueue releases 5 1 -4
STAT...db block changes 45 40 -5
STAT...consistent changes 36 31 -5
STAT...enqueue requests 6 1 -5
STAT...parse time elapsed 8 1 -7
LATCH.channel operations paren 8 0 -8
LATCH.enqueue hash chains 10 2 -8
LATCH.enqueues 10 2 -8
STAT...db block gets from cach 38 27 -11
STAT...db block gets 38 27 -11
STAT...session logical reads 11,044 11,033 -11
STAT...undo change vector size 2,008 2,024 16
LATCH.checkpoint queue latch 16 0 -16
STAT...redo size 2,688 2,672 -16
STAT...CPU used by this sessio 33 11 -22
STAT...workarea memory allocat 33 11 -22
STAT...Elapsed Time 50 21 -29
LATCH.cache buffers chains 22,186 22,136 -50
LATCH.SQL memory manager worka 73 6 -67
LATCH.simulator hash latch 4 9,002 8,998
LATCH.simulator lru latch 1 9,002 9,001
STAT...calls to get snapshot s 33,002 10,001 -23,001
STAT...session uga memory 65,560 15,072 -50,488
STAT...session uga memory max 261,964 65,560 -196,404
STAT...session pga memory max 262,144 65,536 -196,608
Run1 latches total versus runs -- difference and pct
Run1 Run2 Diff Pct
22,380 40,212 17,832 55.66%
Как говорится, 3:1 в пользу временного! Хотя есть странности: например некоторые типы защелок "simulator hash latch" и "simulator lru latch" достаточно активно себя проявили у "победителя". Кроме того, использование памяти сильно отличается.
Подытоживая, можно сказать следующее: использование временного кешированного BLOB решает с одной стороны проблему вымывания буферного кеша, а с другой стороны является еще и менее ресурсоемким способом обработки.
