Remember everything is connected when troubleshooting database issue

Yesterday (Monday) users of a reporting database experienced slowness in extracting data from the database. They indicated that at the speed of current extracting, they would miss the business requirement to deliver the data to executives. I was called to check the database. I noticed their sessions were waiting for "buffer busy wait" event frequently, other than that nothing seemed abnormal in the database. Later, several sessions finished. "Buffer busy wait" become not outstanding. However, one of their major job was still running. Another job errored out with ORA-1555 snapshot too old eventually. They noticed the volume of data that they extracted was larger than usual.

Discussing for a while among users and DBAs, finally we realized that this was due to a large scrub that was carried out against the online production database by me per development team's request last Sunday night. Our online production database is replicated to the reporting database. In that scrub, one DATE type column of a table was updated to SYSDATE', whereas the reporting database users extract their data based on the value of that column. This caused the increased volume of data because more records now fall into the range of time that needs to be extracted.

I felt lucky secretly that I was able to provide the log file of that scrub with starting time and ending time information. This is of course not something I should be proud of. We should always have logs as detail as possible of whatever changes we make against a database, right?. The truth is in my current working environment, DBA is always handed over scripts without taking this into consideration. So if DBA does not take extra step to modify the script to generate useful log information , he could be in trouble if something goes wrong. The scrub took more than 8 hours from about 9:30 PM Saturday to 5:40 AM Sunday. So we knew what was the range of values that the DATE column has when it was updated to 'SYSDATE'. The users decided to exclude that range of data as a temporary fix for their Monday's report. Development team was requested to review their scrubs (i.e. Why updating the DATE column? Initial discussion gave me impression that this was not necessary), since we have even larger scrubs yet to complete of this kind.

Why you need to know a job's LOG_USER when using DBMS_JOB?

Log in as SYS, I executed the following command to change a job's attributes, however, I recieved ORA-23421 error.

sys@MYDB> begin
dbms_job.change(
1001,
what=>'BEGIN DBMS_STATS.gather_database_stats(ESTIMATE_PERCENT => 30, CASCADE=>TRUE, OPTIONS=> ''GATHER STALE'', DEGREE=> 7,METHOD_OPT=>''FOR ALL COLUMNS SIZE 1''); END;',
next_date=> sysdate+1,
interval=> 'trunc(sysdate+1)+1/48'
);
end;
/ 2 3 4 5 6 7 8 9
begin
*
ERROR at line 1:
ORA-23421: job number 1001 is not a job in the job queue
ORA-06512: at "SYS.DBMS_SYS_ERROR", line 86
ORA-06512: at "SYS.DBMS_IJOB", line 529
ORA-06512: at "SYS.DBMS_JOB", line 207
ORA-06512: at "SYS.DBMS_JOB", line 188
ORA-06512: at line 2


Later, I learned that every job has a LOG_USER attribute, which is the login user when the job is submitted. Even SYS can not change other user's job:


sys@MYDB> ho oerr ora 23421
23421, 00000, "job number %s is not a job in the job queue"
// *Cause: There is no job visible to the caller with the given job number.
// *Action: Choose the number of a job visible to the caller.
//

sys@MYDB> select job, log_user from dba_jobs;

JOB LOG_USER
---------- ------------------------------
... ...
1001 OPS$ORACLE


After log in as OPS$ORACLE, the above statement got executed successfully.

ALTER SESSION SET CURRENT_SCHEMA

Recently I have learned how to use ALTER SESSION SET CURRENT_SCHEMA=schmea. This setting makes subsequent unqualified references to schema objects during the session resolve to objects in the specified schema.

Sometimes, developers give us scripts without qualifying the objects with the schema name, and We DBA usually execute the scripts in our own database user account. So this setting provides a convenient way to resolve this issue, otherwise we may have to modify the script to add schema names. Before I tend to complain about it and emphasize developers should have used qualified name. Actaully, I learned this trick from a developer.

A concern is thus how can I know what is my CURRENT_SCHMEA setting? If I am not careful, I may end up drop a table t that belongs to another schema. It is not difficult to find the answer by google.

The following is the query:

z98xxx4@DBT920> ho cat sess_user_sch.sql
col current_user format a15
col current_schema format a15

select sys_context('USERENV','SESSION_USER') current_user,
sys_context('USERENV','SESSION_SCHEMA') current_schema
from dual
/


z98xxx4@DBT920> create table denis.t as select 'denis' name from dual;

Table created.

z98xxx4@DBT920> create table z98xxx4.t as select 'z98xxx4' name from dual;

Table created.
z98xxx4@DBT920> @sess_user_sch.sql
CURRENT_USER CURRENT_SCHEMA
--------------- ---------------
Z98xxx4 Z98xxx4

z98xxx4@DBT920> select * from t;

NAME
------------------------------
z98xxx4

z98xxx4@DBT920> alter session set current_schema=denis;

Session altered.

z98xxx4@DBT920> @sess_user_sch.sql
CURRENT_USER CURRENT_SCHEMA
--------------- ---------------
Z98xxx4 DENIS

z98xxx4@DBT920> select * from t;

NAME
------------------------------
denis

A case of wrong cardinality estimation by CBO

A developer handed over us a query, asking us to run in the report database. There is a predicate in the query for the table 'om', which looks like:

AND om.order_id = SUBSTR (om.order_id,1, 13)

The problem is that CBO can not correctly estimate the cardinality from such a predicate. (It showed cardinality equals 1, CBO choose this table as the build table in the hash join )

Below is a simple test to demonstrate this point:

1. Create and analyze a test table

DB10G> create table t(a varchar2(10));

Table created.

DB10G>
DB10G>
DB10G> begin
  2  for i in 1..1000
  3  loop
  4    insert into t values(dbms_random.string('x', mod(i,10) + 1 ));
  5
  6  end loop;
  7  commit;
  8  end;
  9  /

PL/SQL procedure successfully completed.

DB10G>
DB10G>
DB10G> exec dbms_stats.gather_table_stats(user, 'T');

PL/SQL procedure successfully completed.

2. Case 1 - Predicate: a=substr(a, 1, 5)

In this case, we can see CBO estimates cardinality to be 1, however, the actual number of row is 500

DB10G> select count(* ) from t where a=substr(a, 1, 5);

  COUNT(*)
----------
       500


Execution Plan
----------------------------------------------------------
Plan hash value: 1842905362

---------------------------------------------------------------------------
 Id   Operation           Name  Rows   Bytes  Cost (%CPU) Time
---------------------------------------------------------------------------
   0  SELECT STATEMENT              1      6      3   (0) 00:00:01
   1   SORT AGGREGATE               1      6                
*  2    TABLE ACCESS FULL T         1      6      3   (0) 00:00:01
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("A"=SUBSTRA",1,5))

3. Case 2 - length(a) <=5 I have suggested use length function, but it still can not result in good estimation of the cadinality in the problem query. In my test, the carnality and the actual are different by one order of magnitude.

DB10G> select count(*) from t where length(a) <=5 ; 
COUNT(*)
----------     
500
Execution Plan
----------------------------------------------------------
Plan hash value: 1842905362
---------------------------------------------------------------------------
Id   Operation           Name  Rows   Bytes  Cost (%CPU) Time 
---------------------------------------------------------------------------
 0  SELECT STATEMENT              1      6      3   (0) 00:00:01 
 1   SORT AGGREGATE               1      6                  
*2    TABLE ACCESS FULL T        50    300      3   (0) 00:00:01
---------------------------------------------------------------------------  Predicate Information (identified by operation id):
--------------------------------------------------- 
 2 - filter(LENGTH("A")<=5)

Finally, I suggested to use /*+ ordered */ hint to force Oracle choose the table 'om' as the probe table in the hash join, instead of as a build table by default. The table 'om' is relatively big with approximately 37M rows. I also suggested to add parallel hint. The query was able to be finished in about 3.5 hours.

Different explain-time and run-time execution plans due to parallel degree setting of a table

I have recently faced a query that has different explain-time and run-time execution plans due to parallel degree setting of a table.

The query involvs joining three tables, SEED, SSD and SOD. The execution plan shown by AUTOTRACE is as follows:

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE (Cost=21 Card=1 Bytes=124)
   1    0   SORT (UNIQUE) (Cost=21 Card=1 Bytes=124)
   2    1     TABLE ACCESS (BY INDEX ROWID) OF 'SEED' (Cost=12 Card=1 Bytes=38)
   3    2       NESTED LOOPS (Cost=20 Card=1 Bytes=124)
   4    3         NESTED LOOPS (Cost=9 Card=1 Bytes=86)
   5    4           TABLE ACCESS (BY INDEX ROWID) OF 'SOD' (Cost=6 Card=1 Bytes=54)
   6    5             INDEX (RANGE SCAN) OF 'RECV_DATE' (NON-UNIQUE) (Cost=4 Card=3)
   7    4           TABLE ACCESS (BY INDEX ROWID) OF 'SSD' (Cost=4 Card=1 Bytes=32)
   8    7             INDEX (RANGE SCAN) OF 'SSD_UQ1' (UNIQUE) (Cost=3 Card=1)
   9    3         INDEX (RANGE SCAN) OF 'SEED_IDX11' (NON-UNIQUE) (Cost=4 Card=3)

It looks like a simple plan and the optimzer statistics is up-to-date. However, when run in a 9i database, it runs 2 hours without return before being killed.

When I checked the run-time execution plan, I found it used parallel execution (truncated some middle columns):

--------------------------------------------------------------~~~------------------------------
 Id   Operation                          Name     Rows   ~~~  TQ    IN-OUT PQ Distrib
--------------------------------------------------------------~~~-----------------------------
   0  SELECT STATEMENT                                   ~~~                       
   1   SORT UNIQUE                                33174  ~~~                       
   2    FILTER                                           ~~~                       
   3     HASH JOIN                                33174  ~~~ 72,02   P->S  QC (RAND)
   4      TABLE ACCESS BY INDEX ROWID   SSD           1  ~~~ 72,02   PCWP          
   5       NESTED LOOPS                           31793  ~~~ 72,02   PCWP          
   6        TABLE ACCESS BY INDEX ROWID SOD       33786  ~~~ 72,02   PCWP          
   7         INDEX RANGE SCAN           RECV_DATE   266K ~~~ 72,02   PCWP          
   8        INDEX RANGE SCAN            SSD_UQ1       1  ~~~ 72,02   PCWP          
   9      TABLE ACCESS FULL             SEED       2566K ~~~ 72,01   P->P  HASH    
--------------------------------------------------------------~~~------------------------------

From the dba_tables, I can see the "DEGREE" of the table SEED is 'DEFAULT'. This setting is questionable.

Oracle will use the instance-level defaults whenever the keyword DEFAULT is used in a hint or in a table or index definition.Oracle also will use the instance-level defaults when there are no hints and when no degree of parallelism has been specified at the table or index level. Check this to know hwo Oracle determines the default degree of a table.

I tested with hint: no_parallel(SEED), not helpful, Oracle still uses parallel execution plan. When using parallel(SEED, 1), the query returns in less than a second.