Добро пожаловать в форум, Guest  >>   Войти | Регистрация | Поиск | Правила | В избранное | Подписаться
Все форумы / Oracle Новый топик    Ответить
 Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Shurikas
Member

Откуда: Москва
Сообщений: 182
Здравствуйте!

Проблема в следующем - есть секционированная таблица на текущем (не удаленном) сервере. Есть некий простейший UPDATE,
обновляющий все строки в одной из её секций. Если этот UPDATE выполнить в локальной транзакции, то время выполнения одно, а если в распределенной, то время сильно увеличивается (в разы), и кол-во обработанных блоков тоже увеличивается (примерно в два раза независимо от кол-ва существующих других секций).

См. спойлер "Запуск UPDATE со снятием trace", разница по времени между первым и вторым PL/SQL блоками, которые
отличаются только обращением к локальному/удаленному DUAL. Приплюсовка 1,2 и 3 к значениям в запросах сделана только для того, чтобы отличать запросы в trace мне и утилите TKPROF.

+ Версия Oracle

Connected to Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 
Connected as taxi
 
SQL> select banner from v$version;
 
BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production
PL/SQL Release 11.2.0.2.0 - Production
CORE	11.2.0.2.0	Production
TNS for Linux: Version 11.2.0.2.0 - Production
NLSRTL Version 11.2.0.2.0 - Production

Версия Oracle удаленного сервера - 10.2.0.5


Замедляющийся UPDATE всех строк одной секции (по полю num_field4):
update tx_tmp
    set
        num_field1 = num_field2 + num_field3
where
    num_field4 = 2;
Открытие распределенной транзакции происходит через обращение к удаленному DUAL:
select count(*) into x from dual@my_dblink

+ Скрипты, использованные в теме

/* Секционированная таблица */
set timing on;
drop table tx_tmp cascade constraints;
create table tx_tmp
    (
        code          number(9),
        chr_field     char(100),
        num_field1    number(9),
        num_field2    number(9),
        num_field3    number(9),
        num_field4    number(9),
        constraint tx_tmp_pk primary key(code)
    )
    partition by range (num_field4)
        interval (1)
        (partition tx_tmp_p0 values less than (1));
insert into
    tx_tmp(code, chr_field, num_field1, num_field2, num_field3, num_field4)
select
    rownum,
    substr(a.object_name || b.object_type || a.owner || b.status || to_char(rownum), 1, 100),
    rownum + 1,
    rownum + 2,
    rownum + 3,
    case when rownum <= 3000000 then 1 else 2 end
from
    all_objects a,
    all_objects b
where
    rownum <= 6000000;
commit;
select * from user_tab_partitions where table_name = 'TX_TMP';
exec dbms_stats.gather_table_stats('TAXI', 'TX_TMP');
    
/*************************** UPDATE *****************************/
-- Без использования DBLink
set timing on;
rollback;
declare
    x number;
begin
    select count(*)+1 into x from dual;
    update tx_tmp
       set
           num_field1 = num_field2 + num_field3 + 1
    where
        num_field4 = 2;
end;
/
commit;

-- Использование DBLink до основного UPDATE
rollback;
declare
    x number;
begin
    select count(*)+2 into x from dual@my_dblink;
    update tx_tmp
       set
           num_field1 = num_field2 + num_field3 + 2
    where
        num_field4 = 2;
end;
/
commit;

-- Использование DBLink после основного UPDATE
rollback;
declare
    x number;
begin
    update tx_tmp
       set
           num_field1 = num_field2 + num_field3 + 3
    where
        num_field4 = 2;
    select count(*)+3 into x from dual@my_dblink;
end;
/
commit;

+ Создание и заполнение тестовой таблицы, сбор статистики

Connected to Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 
Connected as taxi
 
SQL> 
SQL> set timing on;
SQL> drop table tx_tmp cascade constraints;
 
drop table tx_tmp cascade constraints
 
ORA-00942: table or view does not exist
SQL> create table tx_tmp
  2      (
  3          code          number(9),
  4          chr_field     char(100),
  5          num_field1    number(9),
  6          num_field2    number(9),
  7          num_field3    number(9),
  8          num_field4    number(9),
  9          constraint tx_tmp_pk primary key(code)
 10      )
 11      partition by range (num_field4)
 12          interval (1)
 13          (partition tx_tmp_p0 values less than (1));
 
Table created
 
Executed in 0.031 seconds
SQL> insert into
  2      tx_tmp(code, chr_field, num_field1, num_field2, num_field3, num_field4)
  3  select
  4      rownum,
  5      substr(a.object_name || b.object_type || a.owner || b.status || to_char(rownum), 1, 100),
  6      rownum + 1,
  7      rownum + 2,
  8      rownum + 3,
  9      case when rownum <= 3000000 then 1 else 2 end
 10  from
 11      all_objects a,
 12      all_objects b
 13  where
 14      rownum <= 6000000;
 
6000000 rows inserted
 
Executed in 87.969 seconds
SQL> commit;
 
Commit complete
 
Executed in 0 seconds
SQL> select * from user_tab_partitions where table_name = 'TX_TMP';
 
TABLE_NAME                     COMPOSITE PARTITION_NAME                 SUBPARTITION_COUNT HIGH_VALUE                                                                       HIGH_VALUE_LENGTH PARTITION_POSITION TABLESPACE_NAME                  PCT_FREE   PCT_USED  INI_TRANS  MAX_TRANS INITIAL_EXTENT NEXT_EXTENT MIN_EXTENT MAX_EXTENT   MAX_SIZE PCT_INCREASE  FREELISTS FREELIST_GROUPS LOGGING COMPRESSION COMPRESS_FOR   NUM_ROWS     BLOCKS EMPTY_BLOCKS  AVG_SPACE  CHAIN_CNT AVG_ROW_LEN SAMPLE_SIZE LAST_ANALYZED BUFFER_POOL FLASH_CACHE CELL_FLASH_CACHE GLOBAL_STATS USER_STATS IS_NESTED PARENT_TABLE_PARTITION         INTERVAL SEGMENT_CREATED
------------------------------ --------- ------------------------------ ------------------ -------------------------------------------------------------------------------- ----------------- ------------------ ------------------------------ ---------- ---------- ---------- ---------- -------------- ----------- ---------- ---------- ---------- ------------ ---------- --------------- ------- ----------- ------------ ---------- ---------- ------------ ---------- ---------- ----------- ----------- ------------- ----------- ----------- ---------------- ------------ ---------- --------- ------------------------------ -------- ---------------
TX_TMP                         NO        TX_TMP_P0                                       0 1                                                                                                1                  1 TAXI                                   10                     1        255                                                                                                     YES     DISABLED                                                                                                                DEFAULT     DEFAULT     DEFAULT          NO           NO         NO                                       NO       NO
TX_TMP                         NO        SYS_P872                                        0 2                                                                                                1                  2 TAXI                                   10                     1        255        8388608     1048576          1 2147483645 2147483645                                         YES     DISABLED                                                                                                                DEFAULT     DEFAULT     DEFAULT          NO           NO         NO                                       YES      YES
TX_TMP                         NO        SYS_P873                                        0 3                                                                                                1                  3 TAXI                                   10                     1        255        8388608     1048576          1 2147483645 2147483645                                         YES     DISABLED                                                                                                                DEFAULT     DEFAULT     DEFAULT          NO           NO         NO                                       YES      YES
 
Executed in 0.094 seconds
SQL> exec dbms_stats.gather_table_stats('TAXI', 'TX_TMP');
 
PL/SQL procedure successfully completed
 
Executed in 47.25 seconds

+ Запуск UPDATE со снятием trace

Connected to Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 
Connected as taxi
 
SQL> alter session set timed_statistics = true;
Session altered
SQL> select
  2      d.instance_name || '_ora_' || ltrim(to_char(a.spid)) || '.trc' filename
  3  from
  4      v$process a,
  5      v$session b,
  6      v$instance d
  7  where
  8      a.addr = b.paddr
  9      and b.audsid = sys_context('userenv','sessionid');
FILENAME
-------------------------------------------------
MYDB_ora_25810.trc
SQL> alter session set events '10046 trace name context forever, level 12';
Session altered
SQL> set timing on;


-- Без использования DBLink
SQL> rollback;
Rollback complete
Executed in 0.015 seconds
SQL> declare
  2      x number;
  3  begin
  4      select count(*)+1 into x from dual;
  5      update tx_tmp
  6         set
  7             num_field1 = num_field2 + num_field3 + 1
  8      where
  9          num_field4 = 2;
 10  end;
 11  /
PL/SQL procedure successfully completed
Executed in 30.11 seconds

SQL> commit; 
Commit complete
Executed in 0.031 seconds


-- Использование DBLink до основного UPDATE
SQL> rollback;
Rollback complete
Executed in 0 seconds
SQL> declare
  2      x number;
  3  begin
  4      select count(*)+2 into x from dual@my_dblink;
  5      update tx_tmp
  6         set
  7             num_field1 = num_field2 + num_field3 + 2
  8      where
  9          num_field4 = 2;
 10  end;
 11  /
PL/SQL procedure successfully completed
Executed in 123.828 seconds

SQL> commit;
Commit complete
Executed in 0.031 seconds


-- Использование DBLink после основного UPDATE
SQL> rollback;
Rollback complete
Executed in 0.016 seconds
SQL> declare
  2      x number;
  3  begin
  4      update tx_tmp
  5         set
  6             num_field1 = num_field2 + num_field3 + 3
  7      where
  8          num_field4 = 2;
  9      select count(*)+3 into x from dual@my_dblink;
 10  end;
 11  /
PL/SQL procedure successfully completed
Executed in 28.828 seconds

SQL> commit;
Commit complete
Executed in 0.047 seconds

SQL> alter session set events '10046 trace name context off';
Session altered
Executed in 0 seconds
 
SQL> 

+ Trace-файл после TKPROF



TKPROF: Release 10.2.0.1.0 - Production on Fri Aug 26 15:17:39 2011

Copyright (c) 1982, 2005, Oracle. All rights reserved.

Trace file: d:\trace_file.txt
Sort options: default

********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

select 'x'
from
dual


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10 0.00 0.00 0 0 0 0
Execute 10 0.00 0.00 0 0 0 0
Fetch 10 0.00 0.00 0 0 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 30 0.00 0.00 0 0 0 10

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80

Rows Row Source Operation
------- ---------------------------------------------------
1 FAST DUAL (cr=0 pr=0 pw=0 time=4 us cost=2 size=0 card=1)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 20 0.00 0.00
SQL*Net message from client 20 0.00 0.06
********************************************************************************

begin :id := sys.dbms_transaction.local_transaction_id; end;


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10 0.00 0.00 0 0 0 0
Execute 10 0.00 0.00 0 0 0 10
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 20 0.00 0.00 0 0 0 10

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 10 0.00 0.00
SQL*Net message from client 10 0.00 0.01
********************************************************************************

rollback


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0
Parsing user id: 80

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.04 0.09
********************************************************************************

declare
x number;
begin
select count(*)+1 into x from dual;
update tx_tmp
set
num_field1 = num_field2 + num_field3 + 1
where
num_field4 = 2;
end;

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 29.95 30.10 0 92339 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 29.95 30.10 0 92339 0 1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.04 0.04
********************************************************************************

SELECT COUNT(*)+1
FROM
DUAL


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 0 0 1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80 (recursive depth: 1)

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=0 pr=0 pw=0 time=30 us)
1 FAST DUAL (cr=0 pr=0 pw=0 time=2 us cost=2 size=0 card=1)

********************************************************************************

UPDATE TX_TMP SET NUM_FIELD1 = NUM_FIELD2 + NUM_FIELD3 + 1
WHERE
NUM_FIELD4 = 2


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 29.95 30.10 218 92339 3070178 3000000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 29.95 30.10 218 92339 3070178 3000000

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80 (recursive depth: 1)

Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE TX_TMP (cr=92339 pr=218 pw=0 time=30105208 us)
3000000 PARTITION RANGE SINGLE PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=5064945 us cost=15239 size=63000000 card=3000000)
3000000 TABLE ACCESS FULL TX_TMP PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=4245355 us cost=15239 size=63000000 card=3000000)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 2 0.00 0.00
log buffer space 2 0.01 0.03
log file switch completion 1 0.01 0.01
db file scattered read 19 0.00 0.00
********************************************************************************

select file#
from
file$ where ts#=:1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 86 0.00 0.00 0 0 0 0
Execute 86 0.01 0.00 0 0 0 0
Fetch 172 0.01 0.00 0 258 0 86
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 344 0.03 0.01 0 258 0 86

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 2)

Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS FULL FILE$ (cr=3 pr=0 pw=0 time=39 us cost=2 size=6 card=1)

********************************************************************************

commit


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 3 0.09 0.09 0 0 19 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.09 0.09 0 0 19 0

Misses in library cache during parse: 0
Parsing user id: 80

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 3 0.00 0.00
SQL*Net message from client 3 0.03 0.05
log file sync 2 0.00 0.00
SQL*Net message to dblink 2 0.00 0.00
SQL*Net message from dblink 2 0.00 0.00
********************************************************************************

declare
x number;
begin
select count(*)+2 into x from dual@my_dblink;
update tx_tmp
set
num_field1 = num_field2 + num_field3 + 2
where
num_field4 = 2;
end;

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 123.47 123.82 0 92339 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 123.47 123.83 0 92339 0 1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************

SELECT COUNT(*)+2
FROM
DUAL@my_dblink


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.14 0 0 1 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.01 0.14 0 0 1 1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
single-task message 1 0.10 0.10
SQL*Net message from dblink 11 0.00 0.03
SQL*Net message to dblink 10 0.00 0.00
SQL*Net more data to dblink 1 0.00 0.00
SQL*Net more data from dblink 1 0.00 0.00
********************************************************************************

UPDATE TX_TMP SET NUM_FIELD1 = NUM_FIELD2 + NUM_FIELD3 + 2
WHERE
NUM_FIELD4 = 2


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 123.46 123.68 218 92339 6070211 3000000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 123.46 123.68 218 92339 6070211 3000000

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80 (recursive depth: 1)

Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE TX_TMP (cr=92339 pr=218 pw=0 time=123680690 us)
3000000 PARTITION RANGE SINGLE PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=7092924 us cost=15239 size=63000000 card=3000000)
3000000 TABLE ACCESS FULL TX_TMP PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=5817039 us cost=15239 size=63000000 card=3000000)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
log file switch (private strand flush incomplete)
3 0.00 0.01
log buffer space 4 0.02 0.07
db file scattered read 19 0.00 0.00
********************************************************************************

declare
x number;
begin
update tx_tmp
set
num_field1 = num_field2 + num_field3 + 3
where
num_field4 = 2;
select count(*)+3 into x from dual@my_dblink;
end;

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 28.55 28.82 0 92275 0 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 28.55 28.82 0 92275 0 1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.03 0.03
********************************************************************************

UPDATE TX_TMP SET NUM_FIELD1 = NUM_FIELD2 + NUM_FIELD3 + 3
WHERE
NUM_FIELD4 = 2


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 28.55 28.79 218 92275 3069986 3000000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 28.55 28.79 218 92275 3069986 3000000

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80 (recursive depth: 1)

Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE TX_TMP (cr=92275 pr=218 pw=0 time=28794821 us)
3000000 PARTITION RANGE SINGLE PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=4523241 us cost=15239 size=63000000 card=3000000)
3000000 TABLE ACCESS FULL TX_TMP PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=3701352 us cost=15239 size=63000000 card=3000000)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
log file switch completion 4 0.08 0.16
log buffer space 2 0.01 0.03
db file scattered read 19 0.00 0.00
********************************************************************************

SELECT COUNT(*)+3
FROM
DUAL@my_dblink


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.02 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 0 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.02 0 0 0 1

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 80 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to dblink 5 0.00 0.00
SQL*Net message from dblink 5 0.01 0.02
********************************************************************************

alter session set events '10046 trace name context off'


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 0 0

Misses in library cache during parse: 0
Parsing user id: 80



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 30 0.00 0.00 0 0 0 0
Execute 30 182.08 182.85 0 276953 19 13
Fetch 10 0.00 0.00 0 0 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 70 182.08 182.85 0 276953 19 23

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 40 0.00 0.00
SQL*Net message from client 40 0.04 0.32
single-task message 1 0.10 0.10
SQL*Net message from dblink 14 0.01 0.05
SQL*Net message to dblink 13 0.00 0.00
SQL*Net more data to dblink 1 0.00 0.00
SQL*Net more data from dblink 1 0.00 0.00
log file sync 2 0.00 0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 92 0.02 0.17 0 0 1 0
Execute 92 181.98 182.59 654 276953 12210375 9000000
Fetch 175 0.01 0.00 0 258 0 89
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 359 182.02 182.76 654 277211 12210376 9000089

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
Disk file operations I/O 2 0.00 0.00
log buffer space 8 0.02 0.14
log file switch completion 5 0.08 0.17
db file scattered read 57 0.00 0.02
SQL*Net message from dblink 4 0.00 0.00
SQL*Net message to dblink 4 0.00 0.00
log file switch (private strand flush incomplete)
3 0.00 0.01

14 user SQL statements in session.
1 internal SQL statements in session.
15 SQL statements in session.
********************************************************************************
Trace file: d:\trace_file.txt
Trace file compatibility: 10.01.00
Sort options: default

1 session in tracefile.
14 user SQL statements in trace file.
1 internal SQL statements in trace file.
15 SQL statements in trace file.
15 unique SQL statements in trace file.
1524 lines in trace file.
1314357421 elapsed seconds in trace file.

+ Различия в TRACE


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 29.95 30.10 218 92339 3070178 3000000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 29.95 30.10 218 92339 3070178 3000000

Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE TX_TMP (cr=92339 pr=218 pw=0 time=30105208 us)
3000000 PARTITION RANGE SINGLE PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=5064945 us cost=15239 size=63000000 card=3000000)
3000000 TABLE ACCESS FULL TX_TMP PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=4245355 us cost=15239 size=63000000 card=3000000)



call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 123.46 123.68 218 92339 6070211 3000000
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 123.46 123.68 218 92339 6070211 3000000

Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE TX_TMP (cr=92339 pr=218 pw=0 time=123680690 us)
3000000 PARTITION RANGE SINGLE PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=7092924 us cost=15239 size=63000000 card=3000000)
3000000 TABLE ACCESS FULL TX_TMP PARTITION: 3 3 (cr=92203 pr=218 pw=0 time=5817039 us cost=15239 size=63000000 card=3000000)



Указанное замедление повторяется на всех типах секционированных таблиц и не повторяется на обычных таблицах. Проверялось на Oracle 11.2.0.2 и 10.2.0.5.

Подскажите, пожалуйста, из-за чего такая проблема возникает и как от нее избавиться?

P.S. Полный trace-файл во вложении.

К сообщению приложен файл (trace_file.txt - 103Kb) cкачать
26 авг 11, 16:49    [11186962]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
wildwind
Member

Откуда: Москва
Сообщений: 1298
Shurikas,

А полную статистику выполнения можно? Или хотя бы '%commit%'

Может быть во втором случае происходит полный commit cleanout? Хотя, с другой стороны, Льюис писал, что это не учитывается в current...
27 авг 11, 01:59    [11188602]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
wildwind
Member

Откуда: Москва
Сообщений: 1298
wildwind,

Не, гоню.

Если блоков в секции всего 92203, менялась половина из них, значит на каждый блок приходится current чтений в среднем 66 раз в первом случае, и 131 раз во втором. В блоке у нас по 32 строки. Допустим 2 чтения приходятся на блок таблицы, тогда остальные вероятно на индекс, по 2 на строку (зачем 2, вроде одного достаточно?). А во втором случае получается чтений индекса вдвое больше.

Жесть какая-то... Видимо снова гоню :)
27 авг 11, 04:31    [11188648]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
wildwind
Member

Откуда: Москва
Сообщений: 1298
wildwind,

Снова гоню. В блоке 65 строк, на каждую 1 чтение индекса, в нормальном случае. Уже легче.
Статистику интересно бы.
27 авг 11, 04:36    [11188649]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
wildwind
Member

Откуда: Москва
Сообщений: 1298
wildwind,

Чтений больше в два раза, а CPU скушано в четыре. Конкуренции нет, спинлоков значит тоже. Чем же он там занимается?

Гнать прекращаю, всем доброго утра.
27 авг 11, 04:41    [11188651]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Shurikas
Member

Откуда: Москва
Сообщений: 182
У кого-нибудь проблема повторилась? Или это только у меня?
Могу выложить скрипт для создания и заполнения секционированной таблицы под 10g с меньшим кол-вом записей, если исходный кажется слишком громоздким и ресурсоемким.
30 авг 11, 09:30    [11198916]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Shurikas
Member

Откуда: Москва
Сообщений: 182
wildwind,
Какую диагностику еще нужно выложить?
30 авг 11, 09:32    [11198920]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
wurdu
Member

Откуда: Владивосток
Сообщений: 4440
Shurikas
У кого-нибудь проблема повторилась? Или это только у меня?
Могу выложить скрипт для создания и заполнения секционированной таблицы под 10g с меньшим кол-вом записей, если исходный кажется слишком громоздким и ресурсоемким.
У меня на linux на 11.2.0.2 с PSU 3 воспроизводится. По статистикам разница только в current, но замедление, на мой взгляд, только этим не объясняется. Я бы обратился в саппорт, благо тесткейс есть. Можно конечно сэмплировать pstack и сравнивать, но не уверен что это приведет к решению проблемы :)
30 авг 11, 09:39    [11198943]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Shurikas
Member

Откуда: Москва
Сообщений: 182
wurdu
Shurikas
У кого-нибудь проблема повторилась? Или это только у меня?
Могу выложить скрипт для создания и заполнения секционированной таблицы под 10g с меньшим кол-вом записей, если исходный кажется слишком громоздким и ресурсоемким.
У меня на linux на 11.2.0.2 с PSU 3 воспроизводится. По статистикам разница только в current, но замедление, на мой взгляд, только этим не объясняется. Я бы обратился в саппорт, благо тесткейс есть. Можно конечно сэмплировать pstack и сравнивать, но не уверен что это приведет к решению проблемы :)

Да, видимо, буду писать на металинк, который myoracle.
30 авг 11, 09:47    [11198968]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Мубык
Guest
ерунда какая-то
1 сен 11, 10:31    [11210387]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Alexander Anokhin
Member

Откуда: Хабаровск
Сообщений: 425
Ну что, спрашивал поддержку?


Я тут порыл немного (подробности здесь, заодно там же альтернативная трассировка consistent & current reads).

Опуская детали - действительно в распределенной транзакции примерно в 2 раза больше current reads. И не только на партиционированной таблице, а на любой.
Все эти current reads читается один и тот же блок - undo header, вызов из ktuGetExtTxnInfo (11.2.0.2) или ktugusc (10.2.0.5), еще выше ktugti и там и там.
В распределенной транзакции каждый вызов ktuchg2 начинается примерно вот так:
(примерно, потому что это только k* пробы [kernel], должно быть достаточно)

0 | ktuchg2:entry ktuchg2
0 -> ktugti ktugti
0 -> ktuGetExtTxnInfo ktuGetExtTxnInfo
0 -> ktuGetUsegHdr ktuGetUsegHdr
0 -> ktuGetUsegDba ktuGetUsegDba
0 -> kslgetl kslgetl --<< хватает латч undo global data.
0 <- kslgetl kslgetl
0 -> kslfre kslfre
0 <- kslfre kslfre
0 <- ktuGetUsegDba ktuGetUsegDba
0 -> kcbgcur kcbgcur
0 -> kcbzgs kcbzgs
0 -> kssadf_numa_intl kssadf_numa_intl
0 <- kssadf_numa_intl kssadf_numa_intl
0 <- kcbzgs kcbzgs
0 <- kcbgcur kcbgcur
0 <- ktuGetUsegHdr ktuGetUsegHdr
0 -> kturus kturus
0 -> kcbrls kcbrls
0 -> kcbzar kcbzar
0 <- kcbzar kcbzar
0 -> kcbzfs kcbzfs
0 -> kjbilms kjbilms
0 <- kjbilms kjbilms
0 -> kssrmf_numa_intl kssrmf_numa_intl
0 <- kssrmf_numa_intl kssrmf_numa_intl
0 <- kcbzfs kcbzfs
0 <- kcbrls kcbrls
0 <- kturus kturus
0 <- ktuGetExtTxnInfo ktuGetExtTxnInfo
0 <- ktugti ktugti
В обычной этого куска нет. Это не единственное отличие, но именно в нем эти current reads (kcbgcur) происходят.
Возможно что это необходимо чтобы поддерживать v$global_transaction, точно пока не знаю.

Еще пара занятных моментов на эту тему.
1) Вызов
select count(*) from dual@dblink;
не открывает распределенную транзакцию,
а вызов
declare 
  i integer;
begin
  select count(*) into i from dual@dblink;
end;
открывает (транзакция прописывается в undo header, появляется в v$transaction, v$global_transaction)

2) Транзакция в примере выше открывается во время hard парсинга! Если же hard парсинга не происходит, то во время вызова стейтмента через dblink.
Из этого следует, что если выполняется следующий стейтмент
declare
    i integer;
begin
    DML;
    DML;
    DML;
    if 1=0 then
        select count(*) into i from dual@dblink;
    end if;
end;
то будет ли он (и все DMLи, а следовательно и экстра current reads, латчи и т.д.) выполняться в распределенной транзакции или нет зависит от того, будет ли произведен hard parsing или нет.



ну и напоследок:
(проверено в версиях 10.2.0.4, 10.2.0.5, 11.2.0.2)
SQL> @10046

session altered

SQL> declare
  2    i integer;
  3  begin
  4
  5    select count(*) into i from dual@dblink;
  6
  7  end;
  8  /


trace
PARSE ERROR #18446741324891357672:len=36 dep=1 uid=91 oct=3 lid=91 tim=236879676964 err=942
SELECT * FROM "TEST"."DUAL"@"DBLINK"
CLOSE #18446741324891357672:c=0,e=7,dep=1,type=0,tim=236879677111
WAIT #18446741324891357672: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879677330
WAIT #18446741324891357672: nam='SQL*Net message from dblink' ela= 221 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879677574
WAIT #18446741324891357672: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879677971
WAIT #18446741324891357672: nam='SQL*Net message from dblink' ela= 303 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879678292
WAIT #18446741324891357672: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879678432
WAIT #18446741324891357672: nam='SQL*Net message from dblink' ela= 824 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879679282
WAIT #18446741324891357672: nam='SQL*Net break/reset to dblink' ela= 8 driver id=1413697536 break?=0 p3=0 obj#=-1 tim=236879679307
WAIT #18446741324891357672: nam='SQL*Net message from dblink' ela= 70 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879679384
=====================
PARSE ERROR #18446741324891357672:len=75 dep=1 uid=91 oct=3 lid=91 tim=236879679436 err=2289
SELECT                    "TEST"."DUAL".CURRVAL@"DBLINK" FROM DUAL@"DBLINK"
CLOSE #18446741324891357672:c=0,e=6,dep=1,type=0,tim=236879679536
WAIT #0: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879679579
WAIT #0: nam='SQL*Net message from dblink' ela= 206 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879679801
WAIT #0: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879679898
WAIT #0: nam='SQL*Net message from dblink' ela= 106 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879680028
WAIT #0: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879680077
WAIT #0: nam='SQL*Net message from dblink' ela= 50 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879680140
WAIT #0: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879680205
WAIT #0: nam='SQL*Net message from dblink' ela= 86 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879680306
WAIT #0: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879680354
WAIT #0: nam='SQL*Net message from dblink' ela= 50 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=236879680417
=====================
PARSING IN CURSOR #18446741324892973984 len=76 dep=0 uid=91 oct=47 lid=91 tim=236879682228 hv=1972333099 ad='88ec8d80' sqlid='ad8yk95usyujb'
declare
  i integer;
begin
  select count(*) into i from dual@dblink;
end;
END OF STMT
PARSE #18446741324892973984:c=10000,e=99759,p=0,cr=1,cu=5,mis=1,r=0,dep=0,og=1,plh=0,tim=236879682227
WAIT #18446741324891346480: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=13753 tim=236879682806
WAIT #18446741324891346480: nam='SQL*Net message from dblink' ela= 112 driver id=1413697536 #bytes=1 p3=0 obj#=13753 tim=236879682939
WAIT #18446741324891346480: nam='SQL*Net message to dblink' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=13753 tim=236879682989
WAIT #18446741324891346480: nam='SQL*Net message from dblink' ela= 63 driver id=1413697536 #bytes=1 p3=0 obj#=13753 tim=236879683064
=====================
PARSING IN CURSOR #18446741324891346480 len=32 dep=1 uid=91 oct=3 lid=91 tim=236879683123 hv=2816557745 ad='8c046928' sqlid='ckyxrukmy2hpj'
SELECT COUNT(*) FROM DUAL@DBLINK
END OF STMT
PARSE #18446741324891346480:c=0,e=726,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=236879683122
...
WTF?
13 ноя 11, 07:12    [11588377]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Shurikas
Member

Откуда: Москва
Сообщений: 182
После двухмесячной переписки с поддержкой проблема решилась. Помогает решить проблему патч из "bug 11682061". Правда патчи пока есть только для 11.2.0.2 for Linux и AIX.
8 дек 11, 16:13    [11730587]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Shurikas
Member

Откуда: Москва
Сообщений: 182
Alexander Anokhin,

Да, точно, я замечал разные странности, которые вы раскрыли, и которые теперь понятны, но как-то не придавал им значения.
В процессе тестирования тестовый пример упростился до неприличного.
У меня только благодаря этому патчу расчет по бизнес-процессу вместо 480 секунд стал работать 280 секунд.

К сообщению приложен файл (simple_reproduce.sql - 1Kb) cкачать
8 дек 11, 16:23    [11730654]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Alexander Anokhin
Member

Откуда: Хабаровск
Сообщений: 425
Можешь показать трейс следующего кода после патча?
create table t as select * from all_objects;

declare
    i integer;
begin
    select count(*) into i from dual@dblink;
    update t set owner = 'SYS';
    commit;
end;
/

declare
    i integer;
begin
    update t set owner = 'SYS';
    commit;
end;
/


Интересует количество current gets.
8 дек 11, 17:13    [11731131]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Shurikas
Member

Откуда: Москва
Сообщений: 182
Вот, пожалуйста.

Только, что интересно, у меня была проблема исключительно на партицированных таблицах.

К сообщению приложен файл (trc.zip - 5Kb) cкачать
9 дек 11, 10:20    [11734372]     Ответить | Цитировать Сообщить модератору
 Re: Update секционированной таблицы в распределенной транзакции - непонятное замедление.  [new]
Alexander Anokhin
Member

Откуда: Хабаровск
Сообщений: 425
ok, просто хотел убедиться, что двойное количество current gets и настолько повышенное потребление CPU - разные проблемы.
PARSING IN CURSOR #140266332364944 len=26 dep=1 uid=86 oct=6 lid=86 tim=1323411341998750 hv=3336072213 ad='418b137e0' sqlid='8huuq2z3dhv0p'
UPDATE T SET OWNER = 'SYS'
END OF STMT
...
EXEC #140266332364944:c=772049,e=773271,p=0,cr=1839,cu=117121,mis=0,r=54072,dep=1,og=1,plh=931696821,tim=1323411342772065
...
EXEC #140266332364944:c=628039,e=640789,p=0,cr=1839,cu=58967,mis=0,r=54072,dep=1,og=1,plh=931696821,tim=1323411343451626
9 дек 11, 21:19    [11739764]     Ответить | Цитировать Сообщить модератору
Все форумы / Oracle Ответить