Профайлер выдает странные результаты

Имеется Oracle 8.1.7 + Developer 6i.
Запускаю форму в Формсах, в одной из процедур формы включаю профайлер, выполняю в цикле процедуру серверного пакета, выключаю профайлер.
В отчете профайлера получаю странный результат, как будто некоторые строки в серверной процедуре выполнены 100 раз (=число вызовов процедуры из формы в цикле), хотя по идее эти строки в тесте не должен выполняться ни одного раза, а некоторые другие строки - 200 раз, хотя должны выполниться только 100 раз.

Усомнившись в правильности работы процедуры, пишу отладочную процедурку:

procedure write_log(v_log in varchar2) is
  pragma autonomous_transaction;
begin
  insert into log_table(id, log)
    select log_seq.nextval, v_log from dual;
  commit;
end;

и вставляю ее вызовы в сомнительные места кода:

if .... then
  write_log('point 1'); -- должен выполниться 0 раз
  strange_statement_1; 
  ...
end if;
...
write_log('point 2'); -- должен выполниться 100 раз
strange_statement_2; 

Получаю в таблице log_table как и ожидалось 0 строк 'point 1' и 100 строк 'point 2'.
Смотрю новый отчет профайлера - строка, записывающая 'point 2', выполнена 200 раз! Строка, записывающая 'point 1', выполнена 0 раз, но вслед за ней идущая строка strange_statement_1 выполнена 100 раз!

Как такое объяснить?

^{В связи с окончанием праздников позволю себе поднять тему еще раз. Да простят меня модераторы.}

Еще раз вопрос: Сталкивался ли кто-то с тем, что профайлер утверждает в выполнении строк, которые на самом деле не выполняются (или в выполнении их кратно больше число раз, чем на самом деле)? Как это объяснить, и как вылечить?

Можно объяснить багом, например этим: Bug 2335456 DBMS_PROFILER GIVES WRONG RESULTS Fixed in 10g,
а можно и некорректным тестом.

Timm

Можно объяснить багом, например этим: Bug 2335456 DBMS_PROFILER GIVES WRONG RESULTS Fixed in 10g, а можно и некорректным тестом.

Суть теста я привел. Контрольная строка представляет собой вызов процедуры write_log, записывающей одну строку в специально созданную таблицу, причем процедура выполняется в автономной транзакции. Если этот тест некорректен, то поясните, в чем именно?

PS: Все-таки похоже на баг. Вот только апдейты на 8.1.7 в свое время по глупости не скачивали, хотя и была лицензия на сервер. А теперь финита-ля комедия .. в смысле давно уже end of life cycle. Если кто может поделиться обновлением на 8.1.7 - напишите. Мыло есть в профиле.

A.K.

Timm Можно объяснить багом, например этим: Bug 2335456 DBMS_PROFILER GIVES WRONG RESULTS Fixed in 10g, а можно и некорректным тестом. Суть теста я привел. Контрольная строка представляет собой вызов процедуры write_log, записывающей одну строку в специально созданную таблицу, причем процедура выполняется в автономной транзакции. Если этот тест некорректен, то поясните, в чем именно?

А его просто нет. "Некорректный тест" - это предположение.

drop table t_log;
create table t_log (tim timestamp, msg varchar2(4000));

set serveroutput on

create or replace procedure write_log(p_string varchar2) is
    pragma autonomous_transaction;
begin
    insert into t_log (tim, msg) values (systimestamp, p_string);
    commit;
end;
/

show err

create or replace procedure test_proc is
begin
    for i in 1..100 loop
        if 1 = 2 then
            write_log('Hmmm');
        end if;
        write_log('Iteration ' || i);
    end loop;
end;
/

show err

variable l_run_id number;

begin
    dbms_profiler.start_profiler(to_char(sysdate, 'YYYY.MM.DD HH24:MI:SS'), '', :l_run_id);
    test_proc;
    dbms_profiler.flush_data;
    dbms_profiler.stop_profiler;
end;
/

select count(*) from t_log;

select total_occur
from plsql_profiler_units u, plsql_profiler_data d
where
    u.unit_name = 'WRITE_LOG' and
    u.runid = :l_run_id and
    d.runid = :l_run_id and
    d.unit_number = u.unit_number and
    d.line# = 4
/

TIM@test>select count(*) from t_log;

  COUNT(*)
----------
       100

1 row selected.

TIM@test>
TIM@test>select total_occur
  2  from plsql_profiler_units u, plsql_profiler_data d
  3  where
  4      u.unit_name = 'WRITE_LOG' and
  5      u.runid = :l_run_id and
  6      d.runid = :l_run_id and
  7      d.unit_number = u.unit_number and
  8      d.line# = 4
  9  /

TOTAL_OCCUR
-----------
        100

1 row selected.

Обнаружил условия, при которых ситуация воспроизводится. А именно - выполнение действий внутри цикла for по курсору, возвращающему 0 строк:

drop table t_log;
create table t_log (tim timestamp, msg varchar2(4000));

create or replace procedure test1 is
  cursor c1 is select 'Hello' from dual where 1=0;
begin
  for r1 in c1 loop
    update t_log t
      set t.msg='Hello, profiler!';
  end loop;
end test1;
/

variable l_run_id number;
begin
    dbms_profiler.start_profiler(to_char(sysdate, 'YYYY.MM.DD HH24:MI:SS'), '', :l_run_id);
    test1;
    dbms_profiler.flush_data;
    dbms_profiler.stop_profiler;
end;
/

select d.line#, d.total_occur
from plsql_profiler_units u, plsql_profiler_data d
where
    u.unit_name = 'TEST1' and
    u.runid = :l_run_id and
    d.runid = u.runid and
    d.unit_number = u.unit_number
/

     LINE# TOTAL_OCCUR
---------- -----------
         2           1
         4           2
         5           1
        11           2

есть объяснение?

A.K.

А теперь финита-ля комедия .. в смысле давно уже end of life cycle. Если кто может поделиться обновлением на 8.1.7 - напишите..

Перестань дурачиться, все на Металинке есть.

Скорее всего баг.
10.2.0.1

     LINE# TOTAL_OCCUR
---------- -----------
         1           1
         2           1
         4           2
         5           0
         8           1

9.2.0.8

     LINE# TOTAL_OCCUR
---------- -----------
         2           1
         4           2
         5           2