CODEWITHSUNDEEP
sqloracle-database
mikcutu
mikcutu

Reputation: 1082

same execution time for same DML

I want to make some tests for transaction execution time, for a DML, on a table with and without a trigger.

For this, I run same DML 5 times and collect the execution time. I keep into 2 variables the start and stop time but starting with 2nd execution, the start and stop time is the same with 1st stop time.

Here is the code:

declare
    l_start number;
    l_stop  number;
begin
        for i in 1 .. 5 loop
        l_start := dbms_utility.get_time;
        update table_1 set field_1 = 5 where rowid = 'ABFpFhAC2AAAAkNAAB';
        l_stop := dbms_utility.get_time;
        dbms_output.put_line('l_start: ' || l_start);
        dbms_output.put_line('l_stop: ' || l_stop);
        dbms_output.put_line('execution time: ' || to_char((l_stop - l_start) / 100) || ' miliseconds');
        rollback;
    end loop;
end;

... and here is the output:

l_start: -1012926990
l_stop: -1012926988
execution time: .02 miliseconds
l_start: -1012926988
l_stop: -1012926988
execution time: 0 miliseconds
l_start: -1012926988
l_stop: -1012926988
execution time: 0 miliseconds
l_start: -1012926988
l_stop: -1012926988
execution time: 0 miliseconds
l_start: -1012926988
l_stop: -1012926988
execution time: 0 miliseconds

Can anyone explain why the l_start and l_stop are not re-initialized every time a loop is passing?

Upvotes: 0

Views: 33

Answers (1)

Thomas Strub
Thomas Strub

Reputation: 1285

You are measuring seconds and not fractions. Use timestamp instead: 

declare
    l_start number;
    l_stop  number;
    t_start timestamp;
    t_stop  timestamp;
begin
    for i in 1 .. 5 loop
        t_start := systimestamp;
        l_start := dbms_utility.get_time;   
        dbms_session.sleep(i/1000);
        l_stop := dbms_utility.get_time;
        t_stop := systimestamp;
        dbms_output.put_line(i || ' n start/stop: ' || l_start || ' / ' || l_stop || '     execution time: ' || to_char((l_stop - l_start) / 100) || ' seconds'  );
        dbms_output.put_line(i || ' t start/stop: ' || to_char(t_start,'SSXFF') || ' / ' || to_char(t_stop,'SSXFF') || '     execution time: ' || to_char(t_stop - t_start) || ' seconds'  );
    end loop;
end;


1 n start/stop: 43402125 / 43402125     execution time: 0 seconds
1 t start/stop: 02,404420000 / 02,404459000     execution time: +000000000 00:00:00.000039000 seconds
2 n start/stop: 43402125 / 43402125     execution time: 0 seconds
2 t start/stop: 02,404506000 / 02,404514000     execution time: +000000000 00:00:00.000008000 seconds
3 n start/stop: 43402125 / 43402125     execution time: 0 seconds
3 t start/stop: 02,404525000 / 02,404530000     execution time: +000000000 00:00:00.000005000 seconds
4 n start/stop: 43402125 / 43402125     execution time: 0 seconds
4 t start/stop: 02,404538000 / 02,404542000     execution time: +000000000 00:00:00.000004000 seconds
5 n start/stop: 43402125 / 43402126     execution time: ,01 seconds
5 t start/stop: 02,404550000 / 02,414774000     execution time: +000000000 00:00:00.010224000 seconds

Which is also not granular enough for very small fractions of time. Then you have to do the process more often to get a good timing.

Upvotes: 1

Related Questions