Category Archives: troubleshooting

How to speed up slow unicode migration of a table with xmltype columns

Posted on by Posted in oracle, parallel, query optimizing, troubleshooting Leave a comment

Recently I have had an issue with slow unicode migration of the database upgraded from 10g to 12.1.0.2. The main problem was a table with xmltype: we spent about 4 hours for this table(~17GB) during test migration, though all other tables (~190GB) migrated just for about 20 minutes.
We used DMU(Database Migration Assistant for Unicode), and the root cause of the problem was update statement generated by DMU for this table:

update  /*+ PARALLEL(A,16)*/ "RRR"."T_XMLDATA" A  set A."SYS_NC00011$" = SYS_OP_CSCONV(A."SYS_NC00011$", 'AL16UTF16')

“SYS_NC00011$” was internal hidden CLOB column used to store XMLTYPE. As you can see DMU added PARALLEL hint, but though oracle can use parallel dml for xmltype since 12.1.0.1, we can’t use it because of its’ limitations:

Changes in Oracle Database 12c Release 1 (12.1.0.1) for Oracle XML DB

Parallel DML Support for XMLType
Support for parallel DML has been improved for XMLType storage model binary XML using SecureFiles LOBs. The performance and scalability have been improved for both CREATE TABLE AS SELECT and INSERT AS SELECT.

Restrictions on Parallel DML

Parallel DML can be done on tables with LOB columns provided the table is partitioned. However, intra-partition parallelism is not supported.

For non-partitioned tables with LOB columns, parallel INSERT operations are supported provided that the LOB columns are declared as SecureFiles LOBs. Parallel UPDATE, DELETE, and MERGE operations on such tables are not supported.

Btw, Oracle didn’t support parallel dml for xmltype on previous releases:

No Parallel DML for XMLType – DML operations on XMLType data are always performed in serial. Parallel DML is not supported for XMLType. (Parallel query and DDL are supported for XMLType.)

So I had to use manual parallelization:
1. Monitor “Convert application tables” step through “View Table Conversion progress” and press “Stop” button during conversion of this table.
2. Create table with ROWIDs of this table and split them into 16 groups:

create table tmp_rids as 
select rowid rid, ntile(16)over(order by rowid) grp 
from t_xmldata;

3. Execute 

ALTER SYSTEM SET EVENTS '22838 TRACE NAME CONTEXT LEVEL 1,FOREVER';

to avoid “ORA-22839: Direct updates on SYS_NC columns are disallowed”
4. Start 16 sessions and each of them have to update own part:

update t_xmldata A 
set A."SYS_NC00011$" = SYS_OP_CSCONV(A."SYS_NC00011$", 'AL16UTF16') 
where rowid in (select rid from tmp_rids where grp=&grp);
commit;

5. Disable event 22838:

ALTER SYSTEM SET EVENTS '22838 TRACE NAME CONTEXT OFF';

6. Open “View Table Conversion progress” window, click on this table and change “Retry” to “Skip” option for the update step.

This simple method allowed to make unicode migration about 16 times faster.

select * from table where rownum=1

Posted on by Posted in adaptive serial direct path reads, CBO, oracle, troubleshooting 1 Comment

I never thought I would have to optimize so simple query as 

select col1, col2, col4, col7 from table where rownum=1

(even though I read recently “SELECT * FROM TABLE” Runs Out Of TEMP Space)
But a few days ago frequent executions of this query caused big problems on the one of our databases(11.2.0.3) because of adaptive serial direct path reads.

I don’t know why, but I felt intuitively that full table scan with “First K rows” optimization (“_optimizer_rownum_pred_based_fkr“=true) should turn off adaptive serial direct path reads. It seems quite logical to me.

PS. Unfortunately I had a little time, so I didn’t investigate what process and why it was doing that, I just created profile with “index full scan” access, and it completely solved the problem.

When v$sesstat statistics are updated

Posted on by Posted in oracle, PL/SQL, runstats, statistics, troubleshooting, undocumented Leave a comment

Craig Shallahamer wrote excellent article “When is v$sesstat really updated?”.
And my today post just a little addition and correction about the difference of updating ‘Db time’ and ‘CPU used by this session’ statistics.

Test #1

In this test I want to show that the statistics will be updated after every fetch call.
I have set arraysize=2, so sql*plus will fetch by 2 rows:
(full script)

-- Result will be fetched by 2 rows:
set arraysize 2;
-- this query generates CPU consumption 
-- in the scalar subquery on fetch phase,
-- so CPU consumption will be separated 
-- into several periods between fetch calls:
with gen as (
            select/*+ materialize */
               level n, lpad(level,400) padding
            from dual
            connect by level<=200
            )
    ,stat as (
            select/*+ inline */
               sid,name,value 
            from v$mystat st, v$statname sn
            where st.statistic#=sn.statistic#
              and sn.name in ('DB time'
                             ,'CPU used by this session'
                             ,'user calls'
                             ,'recursive calls')
            )
--first rows just for avoiding SQL*Plus effect with fetching 1 row at start,
-- others will be fetched by "arraysize" rows:
select null rn,null cnt,null dbtime,null cpu,null user_calls, null recursive_calls from dual
union all -- main query:
select
   rownum rn
  ,(select count(*) from gen g1, gen g2, gen g3 where g1.n>g2.n and g1.n*0=main.n*0) cnt
  ,(select value from stat where sid*0=n*0 and name = 'DB time'                    ) dbtime
  ,(select value from stat where sid*0=n*0 and name = 'CPU used by this session'   ) cpu
  ,(select value from stat where sid*0=n*0 and name = 'user calls'                 ) user_calls
  ,(select value from stat where sid*0=n*0 and name = 'recursive calls'            ) recursive_calls
from gen main
where rownum<=10;
set arraysize 15;

Test results:

SQL> @tests/dbtime

        RN        CNT     DBTIME        CPU USER_CALLS RECURSIVE_CALLS
---------- ---------- ---------- ---------- ---------- ---------------

         1    3980000      12021      11989        200             472
         2    3980000      12021      11989        200             472
         3    3980000      12121      12089        201             472
         4    3980000      12121      12089        201             472
         5    3980000      12220      12186        202             472
         6    3980000      12220      12186        202             472
         7    3980000      12317      12283        203             472
         8    3980000      12317      12283        203             472
         9    3980000      12417      12383        204             472
        10    3980000      12417      12383        204             472

As you can see the statistics are updated after every fetch call.

Test #2

Now since we already tested simple sql query, I want to do a little bit more complicated test with PL/SQL:
I’m going to write single PL/SQL block with next algorithm:
1. Saving stats
2. Executing some pl/sql code with CPU consumption
3. Getting statistics difference
4. Starting query from first test
5. Fetch 10 rows
6. Getting statistics difference
7. Fetch next 10 rows
8. Getting statistics difference
9. Fetch next 10 rows
10. Getting statistics difference
And after executing this block, i want to check statistics.

Full script:

set feed off;

-- saving previous values
column st_dbtime      new_value prev_dbtime      noprint;
column st_cpu_time    new_value prev_cputime     noprint;
column st_user_calls  new_value prev_user_calls  noprint;
column st_recur_calls new_value prev_recur_calls noprint;

select   max(decode(sn.NAME,'DB time'                  ,st.value))*10 st_dbtime
        ,max(decode(sn.NAME,'CPU used by this session' ,st.value))*10 st_cpu_time
        ,max(decode(sn.NAME,'user calls'               ,st.value))    st_user_calls
        ,max(decode(sn.NAME,'recursive calls'          ,st.value))    st_recur_calls
from v$mystat st, v$statname sn
where st.statistic#=sn.statistic# 
  and sn.name in ('DB time','CPU used by this session'
                 ,'user calls','recursive calls'
                 )
/
-- variable for output from pl/sql block: 
var output varchar2(4000);

prompt Executing test...;
----- main test:
declare
   cnt int;
   st_dbtime      number; 
   st_cpu_time    number; 
   st_user_calls  number; 
   st_recur_calls number; 
   cursor c is 
      with gen as (select/*+ materialize */
                     level n, lpad(level,400) padding
                   from dual
                   connect by level<=200)
      select
          rownum rn
        , (select count(*) from gen g1, gen g2, gen g3 where g1.n>g2.n and g1.n*0=main.n*0) cnt
      from gen main
      where rownum<=60;
   
   type ctype is table of c%rowtype;
   c_array ctype;
   
   procedure SnapStats(descr varchar2:=null)
   is
      st_new_dbtime      number;
      st_new_cpu_time    number;
      st_new_user_calls  number;
      st_new_recur_calls number;
   begin
      select   max(decode(sn.NAME,'DB time'                 ,st.value))*10 st_dbtime
              ,max(decode(sn.NAME,'CPU used by this session',st.value))*10 st_cpu_time
              ,max(decode(sn.NAME,'user calls'              ,st.value))    st_user_calls
              ,max(decode(sn.NAME,'recursive calls'         ,st.value))    st_recur_calls
          into st_new_dbtime,st_new_cpu_time,st_new_user_calls,st_new_recur_calls
      from v$mystat st, v$statname sn
      where st.statistic#=sn.statistic#
        and sn.name in ('DB time','CPU used by this session'
                       ,'user calls','recursive calls'
                       );
      if descr is not null then
         :output:= :output || descr ||':'||chr(10)
                || 'sesstat dbtime:     ' || (st_new_dbtime      - st_dbtime      )||chr(10)
                || 'sesstat cputime:    ' || (st_new_cpu_time    - st_cpu_time    )||chr(10)
                || 'sesstat user calls: ' || (st_new_user_calls  - st_user_calls  )||chr(10)
                || 'sesstat recur calls:' || (st_new_recur_calls - st_recur_calls )||chr(10)
                || '======================================'||chr(10);
      end if;
      st_dbtime      := st_new_dbtime     ;
      st_cpu_time    := st_new_cpu_time   ;
      st_user_calls  := st_new_user_calls ;
      st_recur_calls := st_new_recur_calls;
   end;
   
begin
   -- saving previous stats:
   SnapStats;

   -- generating cpu load:
   for i in 1..1e7 loop
      cnt:=cnt**2+cnt**1.3-cnt**1.2;
   end loop;
   -- getting new stats:
   SnapStats('After pl/sql loop');
   
   open c;
   SnapStats('After "open c"');
   fetch c bulk collect into c_array limit 10;
   SnapStats('After fetch 10 rows');
   fetch c bulk collect into c_array limit 10;
   SnapStats('After fetch 20 rows');
   fetch c bulk collect into c_array limit 10;
   SnapStats('After fetch 30 rows');
   close c;
   SnapStats('After close c');
end;
/ 

prompt 'Delta stats after statement(ms):';
select   max(decode(sn.NAME,'DB time'                 ,st.value))*10
          - &&prev_dbtime      as delta_dbtime
        ,max(decode(sn.NAME,'CPU used by this session',st.value))*10
          - &&prev_cputime     as delta_cpu_time
        ,max(decode(sn.NAME,'user calls'              ,st.value))  
          - &&prev_user_calls  as delta_user_calls
        ,max(decode(sn.NAME,'recursive calls'         ,st.value))  
          - &&prev_recur_calls as delta_recur_calls
from v$mystat st, v$statname sn
where st.statistic#=sn.statistic# 
  and sn.name in ('DB time','CPU used by this session'
                 ,'user calls','recursive calls'
                 )
/
prompt 'Test results:';
col output format a40;
print output;
set feed off;

Output:

SQL> @tests/dbtime2

Executing test...
'Delta stats after statement(ms):'

DELTA_DBTIME DELTA_CPU_TIME DELTA_USER_CALLS DELTA_RECUR_CALLS
------------ -------------- ---------------- -----------------
       18530          18460                5                33

Test results:
OUTPUT
----------------------------------------
After pl/sql loop:
sesstat dbtime:     0
sesstat cputime:    4350
sesstat user calls: 0
sesstat recur calls:2
======================================
After "open c":
sesstat dbtime:     0
sesstat cputime:    20
sesstat user calls: 0
sesstat recur calls:4
======================================
After fetch 10 rows:
sesstat dbtime:     0
sesstat cputime:    4680
sesstat user calls: 0
sesstat recur calls:2
======================================
After fetch 20 rows:
sesstat dbtime:     0
sesstat cputime:    4680
sesstat user calls: 0
sesstat recur calls:2
======================================
After fetch 30 rows:
sesstat dbtime:     0
sesstat cputime:    4690
sesstat user calls: 0
sesstat recur calls:2
======================================
After close c:
sesstat dbtime:     0
sesstat cputime:    0
sesstat user calls: 0
sesstat recur calls:3
======================================

We can notice that “CPU time” is updated at the same time as recursive calls, but “DB time” is updated only with “User calls”. Although this difference is not so important(because in most cases we can use other statistics in sum), but i think, if you want to instrument some code, it gives reason to check out desirable statistics for update time.

A couple of well-known but often forgotten things for PL/SQL developers

Posted on by Posted in oracle, PL/SQL, troubleshooting 2 Comments

1. Don’t forget always add NO_DATA_FOUND exception handling, when you doing “select into” in code which can be called as from PL/SQL, as from SQL.

A little example:
Suppose we need to create a function, which would call some procedure:

create or replace procedure p_nested as
  a int;
begin
  select 1 into a from dual where 1=0;
end;
/
create or replace function f_no_data_found return varchar2 as
begin
  p_nested;
  return 'ok';
end;
/

When we call this function in PL/SQL, it will raise NO_DATA_FOUND and we will see it:

SQL> exec dbms_output.put_line(f_no_data_found);
BEGIN dbms_output.put_line(f_no_data_found); END;

*
ERROR at line 1:
ORA-01403: no data found
ORA-06512: at "XTENDER.P_NESTED", line 4
ORA-06512: at "XTENDER.F_NO_DATA_FOUND", line 3
ORA-06512: at line 1

But it doesn’t when we call it in SQL, because it’s normal for SQL: it’s just like a result of scalar subquery that returns nothing – NULL:

SQL> set null "NUL"
SQL> col ndf format a10
SQL> select f_no_data_found ndf from dual;

NDF
----------
NUL

1 row selected.

So if you want the function to behave the same way in PL/SQL and SQL, just add exception handling with reraising another exception or just return null.
It must be at the level of reflexes – “select into” → “exception when no_data_found”
Otherwise, later, when code become a big and difficult, you can get unstable hidden error.

2. Exceptions raised in a declaration section or in default parameters assigning will never be handled in exception section of the same level

Let’s take a look at a very simple example:

An example of exception in default parameter assigning 

SQL> create or replace function f_value_error return int is
  2  begin
  3    raise value_error;
  4    return 1;
  5  end;
  6  /

Function created.

SQL> create or replace function f(i int:=f_value_error) return varchar2 is
  2  begin
  3    return 'ok';
  4  exception when others then
  5    return dbms_utility.format_error_backtrace;
  6  end;
  7  /

Function created.

SQL> set serverout on;
SQL> begin
  2    dbms_output.put_line('From f: '||chr(10)||f);
  3    dbms_output.put_line('****************************');
  4  exception when others then
  5    dbms_output.put_line('****************************');
  6    dbms_output.put_line('From higher level:'||chr(10)||dbms_utility.format_error_backtrace);
  7    dbms_output.put_line('****************************');
  8  end;
  9  /
****************************
From higher level:
ORA-06512: at "XTENDER.F_VALUE_ERROR", line 3
ORA-06512: at line 2

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

PL/SQL procedure successfully completed.

[collapse]

As you can see, there are two problems:
1. an exception was handled at higher level
2. the error backtrace does not show the call of the function “F”.

If the exception was caused in the declaration, we would see the “correct” backtrace, but exception would be still handled at higher level only:

In the declaration 

SQL> create or replace function f(i int:=null) return varchar2 is
  2    l_i int:=nvl(i,f_value_error);
  3  begin
  4    return 'ok';
  5  exception when others then
  6    return dbms_utility.format_error_backtrace;
  7  end;
  8  /

Function created.

SQL> set serverout on;
SQL> begin
  2    dbms_output.put_line('From f: '||chr(10)||f);
  3    dbms_output.put_line('****************************');
  4  exception when others then
  5    dbms_output.put_line('****************************');
  6    dbms_output.put_line('From higher level:'||chr(10)||dbms_utility.format_error_backtrace);
  7    dbms_output.put_line('****************************');
  8  end;
  9  /
****************************
From higher level:
ORA-06512: at "XTENDER.F_VALUE_ERROR", line 3
ORA-06512: at "XTENDER.F", line 2
ORA-06512: at line 2

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

PL/SQL procedure successfully completed.

[collapse]

Sometimes it’s not so dangerous, but last week I was investigating a complex case for this reason: one function when called in SQL throws strange exception, but in PL/SQL it works fine.
The exception was:

SQL> select PKG1.F(1,0,0,1275) from dual; 
select PKG1.F(1,0,0,1275) from dual 
       * 
ERROR at line 1: 
ORA-06553: PLS-801: internal error [1401]

And the function has many functions calls in default parameters initialization, so I couldn’t even find out which one contains a root problem.