Wednesday, December 21, 2011

Implicit conversion of a character string to Oracle DATE type is dangerous

Typically TO_DATE function is used by taking a char as the first argument and 'fmt' as the second argument. According to Oracle doc:

TO_DATE converts char of CHAR, VARCHAR2, NCHAR, or NVARCHAR2 datatype to a value of DATE datatype. The fmt is a datetime model format specifying the format of char. If you omit fmt, then char must be in the default date format. If fmt is J, for Julian, then char must be an integer.

It should be pointed out that omitting the fmt could be a very bad practise. If the character string does not match the default format, Oracle does not necessarily throw error in some cases. For example, I have executed the following commands in the SQL* Plus:
SQL>alter session set nls_date_format='yyyy-mm-dd HH24:mi:ss';

Session altered.


SQL>select count(*) from  dba_objects where created between '1-Nov-2011' and '14-Nov-2011';

  COUNT(*)
----------
         0

1 row selected.

SQL>select to_date('1-Nov-2011') from dual;

TO_DATE('1-NOV-2011
-------------------
0001-11-20 11:00:00

1 row selected.



While the correct results should be as follows:



SQL>alter session set nls_date_format='dd-Mon-yyyy HH24:mi:ss';

Session altered.

SQL>select count(*) from  dba_objects where created between '1-Nov-2011' and '14-Nov-2011';

  COUNT(*)
----------
       171

1 row selected.

SQL>select to_date('1-Nov-2011') from dual;

TO_DATE('1-NOV-2011'
--------------------
01-Nov-2011 00:00:00

1 row selected.



I have learned this in a pretty hard way during a sql tuning effort. Many hours have been spent before I realized that the weired results were due to this implicit conversion "bug". ( See http://www.freelists.org/post/oracle-l/Huge-difference-between-sqlplus-and-sqldeveloper-sorting-in-memory-vs-disk,7)

Sunday, November 27, 2011

Reorganize Table and Index

I manage a database for the retail ordering application. The orders that were completed 90 days ago are subject to archiving. Due to various reasons there were about 80 million archiving backlog about two months ago. Since the backlog is caught up now, reorganization of the schema objects is desirable in order to reclaim space.

First of all, I need to estimate how much space can be saved potentially after the reorganization. For table segment, I use DBMS_SPACE.create_table_cost to estimate the size after reorganization. Given the number of row and average row size and the target tablespace, the following script can be used to estimate the size if the table is moved to the target tablespace.

--  script: tabsize_est.sql 
--  get the avg row size and row cnt from analyze job
--  dba_tables
-- @tabsize_est 'table_size' 100   10000000

set verify off feedback off
set SERVEROUTPUT ON
DECLARE
  l_ddl          VARCHAR2(500);
  l_used_bytes   NUMBER;
  l_alloc_bytes  NUMBER;
  l_message      varchar2(100);
BEGIN
  -- Estimate the size of a new table on the USERS tablespace.
  l_message := '&1';
  DBMS_SPACE.create_table_cost (
            tablespace_name => 'TTQ_ORD_DATA_4',
            avg_row_size    => &2,
            row_count       => &3 ,
            pct_free        => 10 ,
            used_bytes      => l_used_bytes,
            alloc_bytes     => l_alloc_bytes);

  DBMS_OUTPUT.put_line (  l_message  || ' Mbytes_allocated= ' || l_alloc_bytes/1024/1024 || ' Mbytes');
END;
/


I use the following script to generate command for each table:

--  script: tabsize_est_gen.sql
--  purpose: generate 
select '@@tabsize_est ' ||''' ' || t.owner || ' ' || t.table_name || ' ' || t.tablespace_name || ' ' 
     || trunc(s.bytes/1024/1024)  || ''' '||  t.avg_row_len || ' ' || t.num_rows
from
dba_segments s,
dba_tables t
where s.owner=t.owner
and  s.segment_name=t.table_name
and t.owner in  ('TTQ_ORD')
and  s.bytes > 1000000000
/



The output from above script looks like:

@@tabsize_est ' TTQ_ORD CUST_ORDER_ACTIVITY TTQ_ORD_DATA_2 2611' 139 15874503
@@tabsize_est ' TTQ_ORD CUST_HIGH_RISK_20110425 TTQ_ORD_DATA_2 1349' 82 14246227
@@tabsize_est ' TTQ_ORD ENCDEC_MIGRATION TTQ_ORD_DATA_4 1400' 29 2257790
@@tabsize_est ' TTQ_ORD ACCOUNT_COMMENTS TTQ_ORD_DATA_4 13600' 146 82486887
@@tabsize_est ' TTQ_ORD BUNDLE_RECON_TRACKING TTQ_ORD_DATA_3 7060' 957 6294040
@@tabsize_est ' TTQ_ORD ISP_MESSAGE_TRACKING TTQ_ORD_DATA_3 30480' 815 31089530
...

Then, executing above commands, I can obtain current and estimated table segment size as shown below:

TTQ_ORD CUST_ORDER_ACTIVITY TTQ_ORD_DATA_2 2611 Mbytes_allocated= 2600 Mbytes
TTQ_ORD CUST_HIGH_RISK_20110425 TTQ_ORD_DATA_2 1349 Mbytes_allocated= 1400 Mbytes
TTQ_ORD ENCDEC_MIGRATION TTQ_ORD_DATA_4 1400 Mbytes_allocated= 200 Mbytes
TTQ_ORD ACCOUNT_COMMENTS TTQ_ORD_DATA_4 13600 Mbytes_allocated= 13600 Mbytes
TTQ_ORD BUNDLE_RECON_TRACKING TTQ_ORD_DATA_3 7060 Mbytes_allocated= 7200 Mbytes
TTQ_ORD ISP_MESSAGE_TRACKING TTQ_ORD_DATA_3 30480 Mbytes_allocated= 30400 Mbytes
...

To estimate the size of index segment after rebuild, I use a script called index_est_proc_2.sql by Joanathan Lewis (http://jonathanlewis.wordpress.com/index-sizing/).

I use EXCEL to calcuate the size difference between the estimated size and current size for each index and table. As a result I can estimate the total space gain. Of course when I plan to do reoraganization, I can start with the segment which would give the most space gain.

The space gain estimated is at tabespace level. To actually release the space at OS level, the datafile needs to be shrinked. For this it is very useful to know which segments reside at the end of datafile. Those segments should be moved first to allow the datafile shrikable.

The following script is used to list the segment in each data file ordered by its max(block_id). The segments that reside at the end of datafile should have large max(block_id).


-- find segment at the end of the data files
-- so if this segment is removed, the data file could be resized down

spool shrinkdf_&tbs..log

col sum_mbytes format 999,999
col  diff format 999,999,999

select name from v$database;

break on file_id skip 1
select file_id, segment_name, sum_mbytes, count_blocks, max_block_id, 
max_block_id -  lead(max_block_id,1) over (partition by file_id order by max_block_id desc )  diff
from
(
select /*+ RULE */ 
file_id
, segment_name
, sum(bytes/1014/1024)  sum_mbytes
, count(block_id) count_blocks
, max(block_id) max_block_id
from dba_extents
where tablespace_name = upper('&&tbs') 
group by file_id, segment_name
order by 1, 5 desc,4
)
/

spool off

undef tbs


Sample outout from the above script looks like:

FILE_ID SEGMENT_NAME                   SUM_MBYTES COUNT_BLOCKS MAX_BLOCK_ID         DIFF
---------- ------------------------------ ---------- ------------ ------------ ------------
       227 ORDER_TRANS                         1,818            9      1868809      128,000
           AUDIT_TRAIL                         1,010            5      1740809       25,600
           ORD_ADDRESS                           808            4      1715209       51,200
           MASTER_ACCOUNT                        202            1      1664009      179,200
           ORD_TRANS_DETAILED_STATUS             202            1      1484809       51,200
           ORDER_MASTER                          202            1      1433609      153,600
           MASTER_SERVICE                        202            1      1280009       25,600
           ACCOUNT_HISTORY                       202            1      1254409       25,600
           ACCOUNT_COMMENTS                      202            1      1228809       51,200
           ORD_ACCOUNT                           202            1      1177609       51,200
           SUPP_HISTORY                          202            1      1126409      102,400
           CREDIT_CHECK                          202            1      1024009      153,600
           ORD_CONTACT                           404            2       870409       25,600
           ORD_TRANS_NOTES_HISTORY               404            2       844809      102,400
           ORD_DSL                               404            2       742409



It is clear that for the datafile with file_id=227, ORDER_TRANS is at the end, followed by AUDIT_TRAIL.

Finally, the following script can be used to generate the resize statement:


rem  script: red_df.sql 
rem 
rem  Purpose: This gives the Total size of datafiles in a tablespace
rem         and also the size to which it can be reduced.
rem     It generated rdf.log spool file with commands to resize datafiles
rem  Usage: @red_df.sql <TABLESPACE>
rem 
rem  Note: I got this script from a colleague but I once saw this script in AskTom website 

set verify off

col tsname  format         a24    justify c heading 'Tablespace'
col nfrags  format     9,999,990  justify c heading 'Free|Frags'
col mxfrag  format   999,990.999  justify c heading 'Largest|Free Frag'
col totsiz  format 9,999,990.999  justify c heading 'Total|Mbytes'
col avasiz  format 9,999,990.999  justify c heading 'Available|Mbytes'
col pctusd  format       990.99   justify c heading 'Percent|Used'

set pagesize 200
set linesize 120

select
total.tablespace_name                       tsname,
count(free.bytes)                           nfrags,
round(nvl(max(free.bytes)/1048576,0),2)              mxfrag,
total.bytes/1048576                         totsiz,
round(nvl(sum(free.bytes)/1048576,0),2)              avasiz,
round((1-nvl(sum(free.bytes),0)/total.bytes)*100,2)  pctusd
from
(select tablespace_name, sum(bytes) bytes
from dba_data_files
where tablespace_name = upper('&1')
group by tablespace_name)  total,
dba_free_space  free
where
total.tablespace_name = free.tablespace_name(+)
and total.tablespace_name = upper('&1')
group by
total.tablespace_name,
total.bytes;


set verify off
set linesize 150
set echo off

column file_name format a60 word_wrapped
column smallest format 999,990 heading "Smallest|Size|Poss."
column currsize format 999,990 heading "Current|Size"
column savings format 999,990 heading "Poss.|Savings" 
break on report
compute sum of savings on report

column value new_val blksize
select value from v$parameter where name = 'db_block_size'
/

select file_name,
ceil( (nvl(hwm,1)*&&blksize)/1024/1024 ) smallest, 
ceil( blocks*&&blksize/1024/1024) currsize,
ceil( blocks*&&blksize/1024/1024) -
ceil( (nvl(hwm,1)*&&blksize)/1024/1024 ) savings
from dba_data_files a,
( select file_id, max(block_id+blocks-1) hwm 
from dba_extents
group by file_id ) b
where a.file_id = b.file_id(+)
and a.tablespace_name = upper('&1')
/

spool rdf.log
column cmd format a75 word_wrapped
set pagesize 4000

select 'alter database datafile '''||file_name||''' resize ' ||
ceil( (nvl(hwm,1)*&&blksize)/1024/1024 ) || 'm;' cmd 
from dba_data_files a,
( select file_id, max(block_id+blocks-1) hwm
from dba_extents
group by file_id ) b
where a.file_id = b.file_id(+)
and ceil( blocks*&&blksize/1024/1024) - 
ceil( (nvl(hwm,1)*&&blksize)/1024/1024 ) > 0
and a.tablespace_name = upper('&1')
/
spool off

Monday, November 07, 2011

Cloud Computing and DBA career

Recently, in reply to a question in the MITBBS database forum( in Chinese) –“Will the DBA career become down-hill and the future dimmed with the growth of Cloud Computing and NoSQL movement ?”, I made the following comments:


My understanding till today: NOSQL is just a special purpose database (or data model), it cannot replace traditional general purpose RDBMS. (The market of NoSQL is small). It has little impact on DBA’s career.


Cloud computing provides more choices for a company for its IT infrastructure. Basically three choices: traditional in-house IT; outsource IT totally ( i.e. to public cloud provider, pay-per-use ); consolidating in house IT infrastructure on private cloud; or maybe the fourth choice, some kind of mixing of all above. I think the demanding for DBA role (or system admin, network, storage admin in this regard) will be reduced when a company move part (or all) of its IT to cloud (either public or private).


Demanding for traditional DBA role is not only being affected by emerging of cloud computing. It has been affected by more and more self-managing and automation of RDBMS anyway ( In USA that role is being outsourced to India and China etc)


Obviously if there is a trend to move to cloud with significance, there will be a demanding for “cloud system/support administrator” It should not so difficult for a true DBA ( means he is always willing to learn new things) to transition his role to a cloud administrator.


After making the comments, I googled more and found the following article interesting: “The tech jobs that the cloud will eliminate” ( http://www.infoworld.com/d/adventures-in-it/tech-jobs-cloud-will-eliminate-008 ). There is also a two-part article describing Cloud IT roles here: http://open.eucalyptus.com/learn/cloud-it-roles. It indicated a DBA’s skill-set is extendable to assume Cloud Data Architect role.

I wrote a Perl script to non-interactively search dice.com to get the count of job listing with respect to some keywords. I scheduled to do this count every day. Hope this will give me some kind of insights into the trend about the DBA job market and the impact by Cloud Computing.

For example, the output of the script of yesterday looked like:

2011-11-06 07:59 System+Administrator 5688
2011-11-06 07:59 DBA 2799
2011-11-06 07:59 Oracle+DBA 1570
2011-11-06 07:59 Cloud+Administrator 277
2011-11-06 07:59 Cloud+DBA 74

Wednesday, October 12, 2011

SQL Server - Find out Transactions per second etc from DM_OS_PERFORMANCE_COUNTERS

In a whitepaper named "Diagnosing and Resolving Latch Contention on SQL Server",  a script is provided to snap DM_OS_WAITE_STATS view to calculate wait over a period of time. In this post, based on the same idea,  I developed a script to snap the DM_OS_PERFORMANCE_COUNTERS view in order to find out transactions/sec for each database. It is also easy to be modified to get other performance counters.


-- script: snap_perf_conuter.sql

/* Snapshot the performance counters (such as transaction/sec) on sys.dm_os_performance_counters
   and store in a table so that they can be used to compute a per second value.
      This script is only applicable to Cntr_Type = 272696576. Different Cntr_type is explained
      in this blog:
        http://rtpsqlguy.wordpress.com/2009/08/11/sys-dm_os_performance_counters-explained/
** Data is maintained in tempdb so the connection must persist between each execution** 
**alternatively this could be modified to use a persisted table in tempdb. if that is changed code should be included to clean up the table at some point.**
 */


use tempdb
go
declare @current_snap_time datetime
declare @previous_snap_time datetime
-- declare @l_counter_name  nchar(128)
declare @sqlcmd nvarchar(4000)
declare @l_counter_name  nvarchar(2000)

-- modify the counter_name as needed, some examples provided 
set @l_counter_name  = '''transactions/sec'''
-- set @l_counter_name = '''Batch Requests/sec'''                                                                                                              
-- set @l_counter_name= '''Page Splits/sec'',''Page lookups/sec'''
-- set @l_counter_name = '''transactions/sec'',''Batch Requests/sec'''                                                                                                              
-- set @l_counter_name='''Page compression attempts/sec'',''Page Deallocations/sec'',''Page lookups/sec'',''Page reads/sec'',''Page Splits/sec'',''Page writes/sec'',''Pages Allocated/sec'',''Pages compressed/sec'''
-- set @l_counter_name = '''Logins/sec'',''Logouts/sec'''                                                                                              



if not exists(select name from tempdb.sys.sysobjects where name like '#_perf_counter%') 
create table #_perf_counter ( "object_name" nchar(128) ,counter_name nchar(128) ,instance_name nchar(128) ,cntr_value bigint ,cntr_type int ,snap_time datetime
)

set @sqlcmd ='
insert into #_perf_counter (
object_name
,counter_name
,instance_name
,cntr_value
,cntr_type
,snap_time
)
select
OBJECT_NAME
,counter_name
,instance_name
,cntr_value
,cntr_type
,getdate()
from sys.dm_os_performance_counters
where counter_name in (' +  @l_counter_name +  ')'

exec sp_executesql @sqlcmd

--get the previous and current collection point
select top 1 @previous_snap_time = snap_time from #_perf_counter where snap_time < (select max(snap_time) from #_perf_counter) order by snap_time desc

select @current_snap_time = max(snap_time) from #_perf_counter

-- debug
select @current_snap_time end_time, @previous_snap_time start_time

set @sqlcmd='
select
e.object_name
,e.counter_name
,e.instance_name
,(e.cntr_value -s.cntr_value) / DATEDIFF(ss, s.snap_time, e.snap_time)  Per_Sec_Value 
--, s.snap_time as [start_time] 
--, e.snap_time as [end_time] , DATEDIFF(ss, s.snap_time, e.snap_time) as [seconds_in_sample] from #_perf_counter e inner join  
( select * from #_perf_counter   
where snap_time ='''+ convert(varchar(100), @previous_snap_time, 21) + ''' ) s on ( e.instance_name=s.instance_name and e.object_name = s.object_name and e.instance_name=s.instance_name 
   and e.counter_name=s.counter_name)
where e.snap_time= '''+  convert(varchar(100), @current_snap_time, 21) + ''' and e.counter_name in (' +  @l_counter_name + ')order by Per_Sec_value desc'


exec sp_executesql @sqlcmd

--clean up table
 delete from #_perf_counter
 where snap_time = @previous_snap_time

-----------------  end of script  ----

Sample output (edited) :
end_time                start_time
----------------------- -----------------------
2011-10-12 18:47:25.173 2011-10-12 18:46:23.190

(1 row(s) affected)

object_name                         counter_name     instance_name               Per_Sec_Value        seconds_in_sample
----------------------------------- ---------------- --------------------------- -------------------- -----------------
MSSQL$FPSEFSDB_OP2:Databases        Transactions     _Total                      296                  62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     tempdb                      126                  62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     Orderplacement              100                  62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     master                      60                   62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     Distributor                 2                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     NOCVDB                      1                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     DBADB                       1                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     msdb                        1                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     tempdbx                     0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     spot_admin                  0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     ASPState                    0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     APPCACHELOG                 0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     VGISessions                 0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     SSNSDB                      0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     SSNS4DB                     0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     copper                      0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     VZWPCAT                     0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     model                       0                    62
MSSQL$FPSEFSDB_OP2:Databases        Transactions     mssqlsystemresource         0                    62

Saturday, October 08, 2011

SQL Server - Troubleshooting Deadlock

There is a thread  in the SQLTeam forum that describes a deadlock scenario:
The application inserts a row into a status table. A trigger on the table fires so that when the status id inserted is a certain value it will call a stored procedure, which inserts a row into an accounting table. This whole thing is wrapped in a transaction so it should all be getting rolled back when there are errors. On occasion two threads of the application insert into the status table at nearly the same millisecond, and when both end up calling the stored procedure to insert into the accounting table a deadlock occurs and one is killed.

Two important details were unveiled during the discussion:
(1) the whole transaction took place with isolation level set to be serializable
(2) in the stored procedure, there is an existence check query doing full table scan  on the status table before inserting the row into it.

I try to simulate the deadlock situation for my own better understanding, especially this is the first time I know how to use DBCC trace to troubleshooting deadlock. It is a good practise.

First of all, I created the following test table:


-- create a test table

USE testdata
go

IF OBJECT_ID ( 'mytable', 'U' ) IS NOT NULL
DROP TABLE mytable;
GO


CREATE TABLE mytable
 (
  id  INT,
  val INT,
  padding VARCHAR(4000),
  );

create unique clustered index index01
on mytable(id);

INSERT INTO mytable
SELECT 1, 1, REPLICATE('a', 4000);

INSERT INTO mytable
SELECT 2, 2, REPLICATE('a', 4000);

INSERT INTO mytable
SELECT 3, 3, REPLICATE('a', 4000);

INSERT INTO mytable
SELECT 4, 4, REPLICATE('a', 4000);

go

delete from mytable where id in (2,4);

-- show the location of rows
select
       a.%%physloc%%                          AS Address,
       sys.fn_PhysLocFormatter(a.%%physloc%%) AS AddressText,
       a.id
FROM   mytable a
ORDER BY 2;
go


The remaining two rows in the mytable are located in different page as shown below:

Address    AddressText            id
---------- ---------------------- -----------
0x99000000 (1:153:0)                        1
0xFF420000 (1:17151:0)                      3

Secondly I turn on the deadlock trace:

1> DBCC traceon(1222, -1)
2> go
DBCC execution completed. If DBCC printed error messages, contact your system administrator.


Then I run the following two scripts in two different SSMS windows:


-- script: ins_1.sql 
use testdata
go

set transaction isolation level serializable
begin tran
go
if not exists (select id from mytable where val = 2)
begin
  waitfor delay '00:01:00'
  insert into mytable values (2,2, replicate('a','4000'))
end
go
commit tran
go

-- script: ins_2.sql
use testdata
go

set transaction isolation level serializable
begin tran
go
if not exists (select id from mytable where val = 4)
begin
  waitfor delay '00:01:00'
  insert into mytable values (4,4, replicate('a','4000'))
end
go
commit tran
go







Withing the 1 min delay, run sp_lock procedure, I can see the key-range locks are requested by the two sessions:

spid   dbid   ObjId       IndId  Type Resource                         Mode     Status
------ ------ ----------- ------ ---- -------------------------------- -------- ------
53     8      0           0      DB                                    S        GRANT
52     8      0           0      DB                                    S        GRANT
52     8      0           0      MD   49(90c8bd04:fb81833:777569)      Sch-S    GRANT
53     8      0           0      MD   49(ead7fb30:916efee:7da7e5)      Sch-S    GRANT
53     8      66099276    1      PAG  1:153                            IS       GRANT
52     8      66099276    1      PAG  1:153                            IS       GRANT
53     8      66099276    1      PAG  1:17151                          IS       GRANT
52     8      66099276    1      PAG  1:17151                          IS       GRANT
53     8      66099276    0      TAB                                   IS       GRANT
52     8      66099276    0      TAB                                   IS       GRANT
53     8      66099276    1      KEY  (ffffffffffff)                   RangeS-S GRANT
52     8      66099276    1      KEY  (ffffffffffff)                   RangeS-S GRANT
53     8      66099276    1      KEY  (03000d8f0ecc)                   RangeS-S GRANT
52     8      66099276    1      KEY  (03000d8f0ecc)                   RangeS-S GRANT
53     8      66099276    1      KEY  (010086470766)                   RangeS-S GRANT
52     8      66099276    1      KEY  (010086470766)                   RangeS-S GRANT



Key-range locks protect a range of rows implicitly included in a record set being read by a Transact-SQL statement while using the serializable transaction isolation level. The serializable isolation level requires that any query executed during a transaction must obtain the same set of rows every time it is executed during the transaction. A key range lock protects this requirement by preventing other transactions from inserting new rows whose keys would fall in the range of keys read by the serializable transaction.


After about 1 min, one of the sessions received the following message:

Msg 1205, Level 13, State 48, Line 4
Transaction (Process ID 52) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction.
Msg 3902, Level 16, State 1, Line 1
The COMMIT TRANSACTION request has no corresponding BEGIN TRANSACTION.


In the error log, I can find the following:
--------------------- start of error log  ------------------

2011-10-08 11:01:06.38 spid55      DBCC TRACEON 1222, server process ID (SPID) 55. This is an informational message only; no user action is required.
2011-10-08 11:14:42.43 spid16s     deadlock-list
2011-10-08 11:14:42.43 spid16s      deadlock victim=process3313558
2011-10-08 11:14:42.43 spid16s       process-list
2011-10-08 11:14:42.43 spid16s        process id=process3313558 taskpriority=0 logused=132 waitresource=KEY: 8:72057594047889408 (03000d8f0ecc) waittime=3935 ownerId=623111 transactionname=user_transaction lasttranstarted=2011-10-08T11:13:38.497 XDES=0x574bb30 lockMode=RangeI-N schedulerid=4 kpid=8728 status=suspended spid=52 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2011-10-08T11:13:38.497 lastbatchcompleted=2011-10-08T11:13:38.497 clientapp=Microsoft SQL Server Management Studio - Query hostname=TUSNC012LKVT006 hostpid=4412 loginname=US1\v983294 isolationlevel=serializable (4) xactid=623111 currentdb=8 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2011-10-08 11:14:42.43 spid16s         executionStack
2011-10-08 11:14:42.43 spid16s          frame procname=adhoc line=4 stmtstart=182 stmtend=296 sqlhandle=0x02000000d2ef471c04bdc8903318b80f6975779f09b41ba8
2011-10-08 11:14:42.43 spid16s     insert into mytable values (2,2, replicate('a','4000'))     
2011-10-08 11:14:42.43 spid16s         inputbuf
2011-10-08 11:14:42.43 spid16s     if not exists (select id from mytable where val = 2)
2011-10-08 11:14:42.43 spid16s     begin
2011-10-08 11:14:42.43 spid16s       waitfor delay '00:01:00'
2011-10-08 11:14:42.43 spid16s       insert into mytable values (2,2, replicate('a','4000')) 
2011-10-08 11:14:42.43 spid16s     end
2011-10-08 11:14:42.43 spid16s        process id=process69eaa8 taskpriority=0 logused=132 waitresource=KEY: 8:72057594047889408 (ffffffffffff) waittime=9293 ownerId=623056 transactionname=user_transaction lasttranstarted=2011-10-08T11:13:32.760 XDES=0xff48c10 lockMode=RangeI-N schedulerid=2 kpid=11340 status=suspended spid=53 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2011-10-08T11:13:32.760 lastbatchcompleted=2011-10-08T11:13:32.760 clientapp=Microsoft SQL Server Management Studio - Query hostname=TUSNC012LKVT006 hostpid=4412 loginname=US1\v983294 isolationlevel=serializable (4) xactid=623056 currentdb=8 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
2011-10-08 11:14:42.43 spid16s         executionStack
2011-10-08 11:14:42.43 spid16s          frame procname=adhoc line=4 stmtstart=182 stmtend=296 sqlhandle=0x02000000eec4b91030fbd7eaeeef1609e5a77d124395f09a
2011-10-08 11:14:42.43 spid16s     insert into mytable values (4,4, replicate('a','4000'))     
2011-10-08 11:14:42.43 spid16s         inputbuf
2011-10-08 11:14:42.43 spid16s     if not exists (select id from mytable where val = 4)
2011-10-08 11:14:42.43 spid16s     begin
2011-10-08 11:14:42.43 spid16s       waitfor delay '00:01:00'
2011-10-08 11:14:42.43 spid16s       insert into mytable values (4,4, replicate('a','4000')) 
2011-10-08 11:14:42.43 spid16s     end
2011-10-08 11:14:42.43 spid16s       resource-list
2011-10-08 11:14:42.43 spid16s        keylock hobtid=72057594047889408 dbid=8 objectname=testdata.dbo.mytable indexname=index01 id=lock55da680 mode=RangeS-S associatedObjectId=72057594047889408
2011-10-08 11:14:42.43 spid16s         owner-list
2011-10-08 11:14:42.43 spid16s          owner id=process69eaa8 mode=RangeS-S
2011-10-08 11:14:42.43 spid16s         waiter-list
2011-10-08 11:14:42.43 spid16s          waiter id=process3313558 mode=RangeI-N requestType=convert
2011-10-08 11:14:42.43 spid16s        keylock hobtid=72057594047889408 dbid=8 objectname=testdata.dbo.mytable indexname=index01 id=lock627aa80 mode=RangeS-S associatedObjectId=72057594047889408
2011-10-08 11:14:42.43 spid16s         owner-list
2011-10-08 11:14:42.43 spid16s          owner id=process3313558 mode=RangeS-S
2011-10-08 11:14:42.43 spid16s         waiter-list
2011-10-08 11:14:42.43 spid16s          waiter id=process69eaa8 mode=RangeI-N requestType=convert


--------------------- end of error log  ------------------

The solution to this deadlock situation could be (1) using repeated read isolation level  and/or (2) create an index on the 'val' column. Bottom line, we have to fully understand the requirement to code properly: why we need to insert into a table then using trigger to insert into another table? But this is out of my reach.  Here I am just satisfied with being familiar with SQL Server lock types and DBCC trace command a little bit.

The deadlock shown in this test case belong to a type of deadlock named conversion deadlock. Looking closely at the "resource-list" section of the error log. We can see that both sessions hold the same resource in shared mode (RangeS-S) at the begining. This is no problem. But both sessions then request to convert the lock type to RangeI-N, this reqires the other session give up the RangeS-S lock first. Thus a deadlock happens.

Wednesday, October 05, 2011

SQL Server - Are there any queries using any Plan Guides now?

Plan Guide in SQL Server is equivalent to SQL Profile in Oracle functionally. In Oracle, v$sqlarea has a column called SQL_PROFILE, based on which  I can query this view to check if any queries are using any SQL Profiles. Here is the an example:

select sql_profile, max(sql_text) sample_sql_text, sum(executions) total_executions, 
sum(buffer_gets)/ sum(executions)   gets_per_execs 
from v$sqlarea where sql_profile is not null group by sql_profile;


SQL_PROFILE                      SAMPLE_SQL_TEXT                     TOTAL_EXECUTIONS GETS_PER_EXECS
-------------------------------- ----------------------------------- ---------------- --------------
profile_sfh_user_1               SELECT U.SFH_USER_ID,B.SFH_BTN_ID,U             2254     10.3189885
                                 B.PMT_INDICATOR,U.EMAIL FROM SFH_US
                                 ER U,SFH_BTN B,SFH_USER_BTN UB WHER
                                 E U.SFH_USER_ID = UB.SFH_USER_ID AN
                                 D UB.SFH_BTN_ID = B.SFH_BTN_ID AND
                                 B.CUST_BTN = :B2 AND U.USER_ID = :B
                                 1 AND U.USER_STATUS_CD = 'A' AND UB
                                 .SVC_STATUS ='A' AND B.BTN_STATUS_C
                                 D = 'A'
 
COE_gg3zpxx6j5c8c_4057913317      SELECT COUNT(SESSION_KEY) FROM SFH           638642     7.52062032
                                 _MYACC_SUMMARY WHERE cust_btn=:cust
                                 _btn AND SESSION_KEY like :session_
                                 key_value AND LAST_ACCESS_DATE >= S
                                 YSDATE-1
 
profile_sfh_summary_1            SELECT * FROM SFH_SUMMARY_JOBS WHER             6088     3.84395532
                                 E TTQ_ACCOUNT_ID='999802381'AND CR_
                                 DATE > TRUNC(SYSDATE)
 
COE_1x13vygbj9k9t_142312094      DELETE FROM SFH_MYACC_SUMMARY WHERE             5047     11.3929067
                                  CUST_BTN = :CUST_BTN AND  SESSION_
                                 KEY LIKE :SESSION_KEY

It can been seen that  there are four SQL Profiles being used in this Oracle database (This is one of our production databases. I modified some table names to protect the innocent).


How can I obtain the same information in SQL Server regarding the usage of Plan Guide ? This is what I try to find out in the past few days. Below is what I got so far.


First of all, the output of the following query shows there are three Plan Guids in my AdventureWorks sample database

--  Show Plan Guides I created in AdventureWorks sample database

use AdventureWorks
go
-- usp_p is my own print-rows-as-column procedure
exec usp_p'   
select name,create_date,query_text,scope_type_desc from sys.plan_guides
'
go



OUTPUT ROWS AS COLUMN    
    
----------------------------------------------
name                          : Guide1
create_date                   : Oct  4 2011  4:19PM
query_text                    : SELECT * FROM Sales.SalesOrderHeader AS h,
        Sales.Customer AS c, Sales.SalesTerritory AS t
        WHERE h.CustomerID = c.CustomerID AND c.TerritoryID = t.TerritoryID
            AND t.CountryRegionCode = @Country_region
scope_type_desc               : OBJECT
----------------------------------------------
name                          : MyPlan_Guide_1
create_date                   : Oct  4 2011  6:41PM
query_text                    : SELECT COUNT(*) FROM [HumanResources].[Employee] e INNER JOIN [Person].[Contact] c ON c.[ContactID] = e.[ContactID]
scope_type_desc               : SQL
----------------------------------------------
name                          : Template_Plan_1
create_date                   : Oct  5 2011 11:05AM
query_text                    : select SUM ( LineTotal ) as LineTotal from Sales . SalesOrderHeader H join Sales . SalesOrderDetail D on D . SalesOrderID = H . SalesOrderID where H . SalesOrderID = @0
scope_type_desc               : TEMPLATE
----------------------------------------------


As shown above in the "scope_type_desc" column, in SQL Server, there are three types of Plan Guide: Object, SQL and Template. In summary,
  • An OBJECT plan guide matches queries that execute in the context of Transact-SQL stored procedures, user-defined scalar functions, multi-statement user-defined table-valued functions, and DML triggers.
  • An SQL plan guide matches queries that execute in the context of stand-alone Transact-SQL statements and batches that are not part of a database object. SQL-based plan guides can also be used to match queries that parameterize to a specified form.
  • A TEMPLATE plan guide matches stand-alone queries that parameterize to a specified form. These plan guides are used to override the current PARAMETERIZATION database SET option of a database for a class of queries.


Now, I use the following query in SSMS to check whether any Plan Guides are being used

-- Show if any plan guides are in use now:

SELECT 
   SUBSTRING(st.TEXT, (qs.statement_start_offset/2)+1 , ((CASE qs.statement_end_offset WHEN -1 THEN datalength(st.TEXT) 
   ELSE qs.statement_end_offset END - qs.statement_start_offset)/2) + 1) AS sql_txt 
, qp.query_plan.value('declare default element namespace "http://schemas.microsoft.com/sqlserver/2004/07/showplan"; 
 (/ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple/@PlanGuideDB)[1]' , 'varchar(100)')  AS [PlanGuideDB]
, qp.query_plan.value('declare default element namespace "http://schemas.microsoft.com/sqlserver/2004/07/showplan"; 
 (/ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple/@PlanGuideName)[1]' , 'varchar(100)')  AS [PlanGuideName]
 ,qp.query_plan
, total_worker_time/execution_count AS AvgCPU 
, total_elapsed_time/execution_count AS AvgDuration 
, (total_logical_reads+total_physical_reads)/execution_count AS AvgReads 
, execution_count 
FROM sys.dm_exec_query_stats qs
cross apply sys.dm_exec_sql_text(sql_handle) st
cross apply sys.dm_exec_query_plan(plan_handle) qp
WHERE qp.query_plan.exist('declare default element namespace "http://schemas.microsoft.com/sqlserver/2004/07/showplan";
 /ShowPlanXML/BatchSequence/Batch/Statements/StmtSimple[(@PlanGuideName)]') = 1
ORDER BY [PlanGuideDB], [PlanGuideName] DESC



The idea of this query is from this post: http://www.scarydba.com/2009/02/12/missing-index-information-and-query-stats/ ,  which tries to associate missing index info with the query causing it. Basically I used xquery exist funtion to search if there is a keyword 'PlanGuideName' in the XML text.


Here is the sample output screenshot.


As shown in the screenshot,  the query works for the Object and SQL type Plan Guide. When comes to the template Plan Guide, I encountered difficulties.

The template Plan Guide was created by the following script, which is used to force replacing literals with parameters for a specific type query. By default, database PARAMEDTERIZATION is set to Simple, which will not be applicable to this type of query that has a two-table join.

USE AdventureWorks;
DECLARE @stmt nvarchar(max);
DECLARE @params nvarchar(max);
EXEC sp_get_query_template
    N' SELECT  SUM(LineTotal) AS LineTotal
       FROM    Sales.SalesOrderHeader H
       JOIN    Sales.SalesOrderDetail D ON D.SalesOrderID = H.SalesOrderID
      WHERE   H.SalesOrderID = 56000',
    @stmt OUTPUT,
    @params OUTPUT

EXEC sp_create_plan_guide
    N'Template_Plan_1',
    @stmt,
    N'TEMPLATE',
    NULL,
    @params,
    N'OPTION(PARAMETERIZATION FORCED)';
GO



Then I run the following test to see if the template Plan Guide works:


use AdventureWorks
go

SELECT  SUM(LineTotal) AS LineTotal
FROM    Sales.SalesOrderHeader H
JOIN    Sales.SalesOrderDetail D ON D.SalesOrderID = H.SalesOrderID
WHERE   H.SalesOrderID = 56001
GO



When checking the estimated plan, in the Show Plan XML window, I can find the following text for the "StmtSimple" node:

StmtSimple StatementCompId="1" StatementEstRows="1" StatementId="1" StatementOptmLevel="FULL" StatementOptmEarlyAbortReason="GoodEnoughPlanFound" StatementSubTreeCost="0.00658091"
StatementText="SELECT SUM(LineTotal) AS LineTotal FROM Sales.SalesOrderHeader H
JOIN Sales.SalesOrderDetail D ON D.SalesOrderID = H.SalesOrderID
WHERE H.SalesOrderID = 56001" StatementType="SELECT"
TemplatePlanGuideDB="AdventureWorks" TemplatePlanGuideName="Template_Plan_1" ParameterizedText="(@0 int)
select SUM ( LineTotal ) as LineTotal from Sales . SalesOrderHeader H join Sales . SalesOrderDetail D on D . SalesOrderID = H . SalesOrderID
where H . SalesOrderID = @0"
QueryHash="0x1170510D7B65D486" QueryPlanHash="0x1B1C9CA6A989FB7C"


 
It can be noticed that there are "TemplatePlanGuideDB" and "TemplatePlanGuideName" attributes presented, which indicates the template Plan Guide will be used. When checking the acutual plan, in the Show Plan XML window, I see different text than above:

StmtSimple StatementCompId="1" StatementEstRows="1" StatementId="1" StatementOptmLevel="FULL"

StatementOptmEarlyAbortReason="GoodEnoughPlanFound" StatementSubTreeCost="0.00658091"
StatementText="select SUM ( LineTotal ) as LineTotal from Sales . SalesOrderHeader H
join Sales . SalesOrderDetail D on D . SalesOrderID = H . SalesOrderID
where H . SalesOrderID = @0" StatementType="SELECT"
QueryHash="0x1170510D7B65D486" QueryPlanHash="0x1B1C9CA6A989FB7C"



Basically in the actual execution plan XML text, there is no such keywords as 'PlanGuideDBName' or 'TemplatePlanGuideDBName'. Due to the lacking of such marks,  the query described previously cannot
be used to answer such a question " Are there any queries using any template Plan Guides now?"

Friday, September 23, 2011

SQL Server - A Procedure to Display Columns as Rows

updated: Oct 12, 2012

As an Oracle DBA, I am used to using command line interface (CLI) for my many DBA tasks. When some long rows are output from a query, it is often very unconvenient to view in CLI windows due to text wrapping at certain lengh. Tom Kyte has developed a procedure in Oracle to display columns as rows. Here I try to accomolish the same thing in SQL Server.

My procedure is called usp_p, the source code can be downloaded here.

Below is an example of using this procedure.

First of all, here is the script (top10_ela.sql ) that displays top 10 sqls ordered by average execution time:

declare @sqltext varchar(4000)

set @sqltext = '
SELECT   top 10
sql_handle
, (SELECT TOP 1 SUBSTRING(s2.text,statement_start_offset / 2+1 ,
     ( (CASE WHEN statement_end_offset = -1
            THEN (LEN(CONVERT(nvarchar(max),s2.text)) * 2)
      ELSE statement_end_offset END)  - statement_start_offset) / 2+1))  AS sql_statement
 , (total_elapsed_time/execution_count)/1000 AS [Avg Exec Time in ms]
 , max_elapsed_time/1000 AS [MaxExecTime in ms]
 , min_elapsed_time/1000 AS [MinExecTime in ms]
 , (total_worker_time/execution_count)/1000 AS [Avg CPU Time in ms]
, qs.execution_count AS NumberOfExecs
, (total_logical_writes+total_logical_Reads)/execution_count AS [Avg Logical IOs]
, max_logical_reads AS MaxLogicalReads
, min_logical_reads AS MinLogicalReads
, max_logical_writes AS MaxLogicalWrites
, min_logical_writes AS MinLogicalWrites
, creation_time
, last_execution_time
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(sql_handle)  s2
WHERE s2.objectid is null
ORDER BY [Avg Exec Time in ms] DESC
';



exec dbadmin.dbo.usp_p @sqltext

go


Below is a sample output from my test sql server instance:

$ sqlcmd -i  top10_ela.sql


OUTPUT COLUMNS AS ROWS - MISSING COLUMN NAME MEANS NULL VALUE

----------------------------------------------
sql_handle                    : 0x0200000027337b02ca2b54f71198517d10d457c2e93900b900000000000000000000000000000000
sql_statement                 : declare StmtCur cursor for
SELECT   top 10
sql_handle
, (SELECT TOP 1 SUBSTRING(s2.text,statement_start_offset / 2+1 ,
     ( (CASE WHEN statement_end_offset = -1
            THEN (LEN(CONVERT(nvarchar(max),s2.text)) * 2)
      ELSE statement_end_offset END)  - statement_start_offset) / 2+1))  AS sql_statement
 , (total_elapsed_time/execution_count)/1000 AS [Avg Exec Time in ms]
 , max_elapsed_time/1000 AS [MaxExecTime in ms]
 , min_elapsed_time/1000 AS [MinExecTime in ms]
 , (total_worker_time/execution_count)/1000 AS [Avg CPU Time in ms]
, qs.execution_count AS NumberOfExecs
, (total_logical_writes+total_logical_Reads)/execution_count AS [Avg Logical IOs]
, max_logical_reads AS MaxLogicalReads
, min_logical_reads AS MinLogicalReads
, max_logical_writes AS MaxLogicalWrites
, min_logical_writes AS MinLogicalWrites
, creation_time
, last_execution_time
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(sql_handle)  s2
WHERE s2.objectid is null
ORDER BY [Avg Exec Time in ms] DESC

Avg Exec Time in ms           :        307
MaxExecTime in ms             :        307
MinExecTime in ms             :        307
Avg CPU Time in ms            :        307
NumberOfExecs                 :          1
Avg Logical IOs               :          0
MaxLogicalReads               :          0
MinLogicalReads               :          0
MaxLogicalWrites              :          0
MinLogicalWrites              :          0
creation_time                 : Oct 12 2012  8:46PM
last_execution_time           : Oct 12 2012  8:46PM
----------------------------------------------
sql_handle                    : 0x02000000cff2b929b1aebd642c8187892cf718f0921cf8bb00000000000000000000000000000000
sql_statement                 : select * from sys.dm_exec_query_stats;

Avg Exec Time in ms           :          0
MaxExecTime in ms             :          0
MinExecTime in ms             :          0
Avg CPU Time in ms            :          0
NumberOfExecs                 :          1
Avg Logical IOs               :          0
MaxLogicalReads               :          0
MinLogicalReads               :          0
MaxLogicalWrites              :          0
MinLogicalWrites              :          0
creation_time                 : Oct 12 2012  8:45PM
last_execution_time           : Oct 12 2012  8:45PM
----------------------------------------------
sql_handle                    : 0x020000004bee4622a78521352165a8a19fc021a4e00df3c900000000000000000000000000000000
sql_statement                 : select table_id, item_guid, oplsn_fseqno, oplsn_bOffset, oplsn_slotid
 from [DBAdmin].[sys].[filetable_updates_2105058535] with (readpast) order by table_id
Avg Exec Time in ms           :          0
MaxExecTime in ms             :          0
MinExecTime in ms             :          0
Avg CPU Time in ms            :          0
NumberOfExecs                 :          2
Avg Logical IOs               :          0
MaxLogicalReads               :          0
MinLogicalReads               :          0
MaxLogicalWrites              :          0
MinLogicalWrites              :          0
creation_time                 : Oct 12 2012  8:46PM
last_execution_time           : Oct 12 2012  8:46PM
----------------------------------------------








Note: I did not verify that every data type can be shown properly as of now, I will probably have to modify the code as time goes.


Update: Oct 19,2012

Learned that SQL Server has a very simple way to turn the query output to XML format by appending "for xml path" at the end.  This has similar effect as output "columns as rows". For example, run: select top 2 * from sys.objects for xml path , it will generate the following XML format:

Wednesday, September 21, 2011

SQL Server - Create a Policy to Enfore Naming Convention on Stored Procedure

In SQL Server 2008, assuming we need to enforce a naming standard on stored procedures:
All stored procedures in the database (TestData) must start with "usp_" - ("usp" stands for user stored procedure).

Step 1 Create the Condition
  1.  In Object Explorer, expand Management, expand Policy Management, expand Conditions, right-click the Conditions node and then click New Condition.
  2.  On the Create New Condition, General page, in the Name box, type the name of the new condition: SP Naming
  3. Select the Multipart Name facet in the Facet box.
  4. In the Expression area, construct the condition expressions : @Name like 'usp_%'.
  5. On the Description page, type a description and then click OK.


Step 2 Create the Policy
  1. In Object Explorer, expand Management, expand Policy Management, right-click Policies, and then click New Policy.
  2. On the Create New Policy, General page, in the Name box, type the name of the new policy: SP Naming Policy.
  3. If you want the policy to be enabled as soon as it is created, select the Enabled check box.
  4. If the evaluation mode is On demand, the Enabled check box is not available.
  5. In the Check condition box, select the existing condition: SP Naming. To edit the condition, select the condition and then click the build (...) button.
  6.  In the Against targets box, select the Every StoredProcedure target. Create a new condition TestData DB Only in the Database Node (Facet: Database, Condition: @Name='testdata').
  7. In the Evaluation Mode box, select how this policy will behave: On Change: Prevent. Different conditions can have different valid evaluation modes.
  8. To limit the policy to subset of the target types, in the Server restriction box, select from limiting conditions or create a new condition.
  9. On the Description page, in the Category box, select an optional policy category or create a new one.
  10. Type n optional description of the policy.
  11.  Click OK.


When the policy is enabled, trying to create a procedure that violates the policy, the following message is received:

Changed database context to 'testdata'.
Policy 'SP Naming Policy' has been violated by 'SQLSERVER:\SQL\TUSNC012LKVT006\DEFAULT\Databases\testdata\StoredProcedures\dbo.HelloWorld3_proc'.
This transaction will be rolled back.
Policy condition: '@Name LIKE 'usp_%''
Policy description: ''
Additional help: '' : ''
Statement: '
create procedure HelloWorld3_proc
as
select 'HelloWorld'
'.
Msg 3609, Level 16, State 1, Server TUSNC012LKVT006, Procedure sp_syspolicy_dispatch_event, Line 65
The transaction ended in the trigger. The batch has been aborted.

Thursday, September 08, 2011

SQL Server - test case showing rows moved when creating a clustered index

Recently I have determined to study SQL Server. Of course, this is not the first time I attempt to do so. Just this time I decided not to spend time on Oracle voluntarily and to concentrate on SQL server instead. 

I have noticed that in SQL Server it is highly recommended that every table should have a clustered index. A table with a clustered index (CI) conceptually corresponds to the Index Organized Table (IOT) in Oracle. Basically, the leaf node of the index contains the data block (called B+ tree index). I also found a blog post that attempted to explain why SQL Server needs to use CI to achieve performance while IOT is not used in Oracle as widely as the CI in SQL Sever. But I am still not very clear about the reasons after reading the post.

If a table does not have a CI and we want to create  CI on it, the existing rows should be reorganized to occupy the pages in the sorted key order. This is what I try to confirm with the following test case.

Test case:
-- script: rowmove.sql
-- purpose: demonstrate table rows moved when creating clustered index
-- env    : SQL Server 2008
--

:setvar sqlcmdheaders            40     -- "page size"
:setvar sqlcmdcolwidth          132     -- line width
:setvar sqlcmdmaxfixedtypewidth  32     -- max column width (fixed length)
:setvar sqlcmdmaxvartypewidth    32     -- max column width (varying length)

USE testdata
go

IF OBJECT_ID ( 'mytable', 'U' ) IS NOT NULL 
DROP TABLE mytable;
GO


CREATE TABLE mytable
 (
  id  INT,
  col1 VARCHAR(2000),
  col2 VARCHAR(2000));

INSERT INTO mytable
SELECT 1, REPLICATE('a', 2000), REPLICATE('b', 2000);

INSERT INTO mytable
SELECT 4, REPLICATE('a', 2000), REPLICATE('b', 2000);


INSERT INTO mytable
SELECT 2, REPLICATE('a', 2000), REPLICATE('b', 2000);

INSERT INTO mytable
SELECT 3, REPLICATE('a', 2000), REPLICATE('b', 2000);


go

select 
       a.%%physloc%%                          AS Address,
       sys.fn_PhysLocFormatter(a.%%physloc%%) AS AddressText,
       a.id
FROM   mytable a
ORDER BY 2;
go

print " "
print "  ----  After created clustered index on ID ----"
print " "

go

create unique clustered index index01 
on mytable(id);
go

select 
       a.%%physloc%%                          AS Address,
       sys.fn_PhysLocFormatter(a.%%physloc%%) AS AddressText,
       a.id
FROM   mytable a
ORDER BY 2;
go



Test output:

Changed database context to 'testdata'.

(1 rows affected)
Address    AddressText                      id         
---------- -------------------------------- -----------
0xFA420000 (1:17146:0)                                1
0xFA420000 (1:17146:1)                                4
0xFD420000 (1:17149:0)                                2
0xFD420000 (1:17149:1)                                3

(4 rows affected)
 
  ----  After created clustered index on ID ----
 
Address    AddressText                      id         
---------- -------------------------------- -----------
0x99000000 (1:153:0)                                  3
0x99000000 (1:153:1)                                  4
0xFE420000 (1:17150:0)                                1
0xFE420000 (1:17150:1)                                2

(4 rows affected)



It can be seen that in this test case one page can hold maximum 2 table rows. At the begining, table rows with id=1 and 4 reside on page 17146, and with id=2,3 resides on page 17149. This is understandable as we inserted the rows in the order of 1,4,2,3. After create a CI on ID column, the rows with id=1,2 moved to page 153 and rows with id=3,4 moved to page 17150. So the rows occupies the pages in the sorted order of ID. It should be noted that the pages that belong to the table do not need to physically on the disk files closely to each other.

Wednesday, May 11, 2011

Setting CUROSR_SHARING To FORCE causes large amount of child cursors for an insert statement

In a pre-production test, we found out that application did not use bind variables and there was no time to change code before the production rollout. So we suggested changing CURSOR_SHARING parameter from EXACT to FORCE in order to turn hard parse to soft parse. When testing this change for the two webservice functions , which mainly consists of two inserts, one update and bunch of select statements, the results are promising:

Summary of testing results from 15 min interval AWR reports from a 4-node 11.2.0.2 RAC database

2-node test (CURSOR_SHARING=EXACT)

dd1    DB Time:   23.04 (mins)  143 tx/s   Parses: 440.7 per sec  Hard parses: 315.2 per sec       
dd4    DB Time:   23.35 (mins)  140 tx/s   Parses: 414.4 per sec  Hard parses: 303.5 per sec               


2-node test (CURSOR_SHARING=FORCE)

dd1   DB Time:    16.68 (mins)  146 tx/s   Parses: 383.9 per sec  Hard parses: 2.6 per sec
dd4   DB Time:    16.01 (mins)  147 tx/s   Parses: 384.2 per sec  Hard parses: 2.6 per sec


-- dd1  Time Model Statistics (CURSOR_SHARING=FORCE) 
 
Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time                                666.6         66.6
DB CPU                                                  350.0         35.0
parse time elapsed                                       80.0          8.0
hard parse elapsed time                                  15.1          1.5
hard parse (sharing criteria) elapsed time                1.7           .2
PL/SQL execution elapsed time                             1.1           .1
hard parse (bind mismatch) elapsed time                   1.0           .1
PL/SQL compilation elapsed time                           0.8           .1
connection management call elapsed time                   0.4           .0
sequence load elapsed time                                0.4           .0
repeated bind elapsed time                                0.0           .0
DB time                                               1,000.9
background elapsed time                                 200.0
background cpu time                                     143.9
          -------------------------------------------------------------
 
-- dd1  Time Model Statistics (CURSOR_SHARING=EXACT) 

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
DB CPU                                                  728.2         52.7
sql execute elapsed time                                632.9         45.8
parse time elapsed                                      481.2         34.8
hard parse elapsed time                                 390.0         28.2
hard parse (sharing criteria) elapsed time                3.2           .2
hard parse (bind mismatch) elapsed time                   2.9           .2
PL/SQL execution elapsed time                             1.4           .1
PL/SQL compilation elapsed time                           1.2           .1
connection management call elapsed time                   0.5           .0
sequence load elapsed time                                0.5           .0
repeated bind elapsed time                                0.0           .0
failed parse elapsed time                                 0.0           .0
DB time                                               1,382.4
background elapsed time                                 261.8
background cpu time                                     115.5
          -------------------------------------------------------------
 

Bascially, we saw hard parse was greatly reduced. For the same level transaction rate, DB time was reduced from 46 min to 32 min after changing to FORCE. However, when another module was enabled and added to the two webserverice workload, things went wrong. We saw large amount of "cursor:mutex S" and "liberary cache lock" waits (>80% DB time). We identified an insert statement that has large amount of child cursors ( ~ 8000) caused the problem.

Below is a test case demonstrating large number of child cursors are created with CURSOR_SHARING=FORCE:

Test case 1

This test was carried out to repeat what we encountered in our pre-production test. Inserts into a table called MY_STB_LOG2 were performed with CUROSR_SHARING=FORCE, with 324 total number of inserts similar to the following:

insert into MY_STB_LOG2 values('0000043862420080','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-04 07:51:40.000',timestamp'2011-05-04 02:20:45.000',timestamp'2011-05-04 02:35:07.000','N','N','','','','P',SYSDATE);
insert into MY_STB_LOG2 values('0000048201268050','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:02:07.000',timestamp'2011-05-04 21:10:22.000','','N','N','','','','P',SYSDATE);


After run, checking v$sqlarea and v$sql, we got:


SQL> select sql_text,sql_id, executions from v$sqlarea where sql_text like 'insert into MY_STB_LOG2%';
 
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
SQL_ID        EXECUTIONS
------------- ----------
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",timestamp:"SYS_B_03",:"SYS
_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
16yq35g1c433b         71
 
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",:"SYS_B_03",:"SYS_B_04",:"
SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
4yzz9r14n53fg         28
 
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",timestamp:"SYS_B_03",times
tamp:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
gpb19na8zd67s        210
 
insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",:"SYS_B_03",timestamp:"SYS
_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
6ua1jndb5ud4x         15


SQL> select sql_id, count(*) from v$sql  where sql_text like 'insert into MY_STB_LOG2%' group by sql_id;

SQL> select sql_id, count(*) from v$sql  where sql_text like 'insert into MY_STB_LOG2%' group by sql_id;
 
SQL_ID          COUNT(*)
------------- ----------
gpb19na8zd67s        210
16yq35g1c433b         71
4yzz9r14n53fg         28
6ua1jndb5ud4x         15


It can be seen that we have 4 versions of insert statements after literals are replaced by system-generated bind varialbes. For each version, the execution times equal to the number of its child cursors. It indicates for every insert, Oracle actually does hard parse with extra cost to search child cursors.


When using Dion's script to query v$sql_shared_cursor, we can see the reason for unshared cursor is "HASH_MATCH_FAILED"




--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 0000000093C96F80
CHILD_NUMBER = 68
HASH_MATCH_FAILED = Y
--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 00000000AB5E4300
CHILD_NUMBER = 69
HASH_MATCH_FAILED = Y
--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 000000013C695090
CHILD_NUMBER = 70
HASH_MATCH_FAILED = Y
--------------------------------------------------



It should be noted that even application using the bind varialbe, this problem could occur. One possible solution is to use PL/SQL procedure to do the insert:


Test case 2

I create a procedure STB_INS (see appendix) to insert into a table called MY_STB_LOG3 ( same structure as LOG2), then I run 324 exec procedure such as:

exec STB_INS('0001097562293114','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:30:01.000',timestamp'2011-05-05 00:20:03.000',timestamp'2011-05-04 23:42:57.000','N','N','','','','P',SYSDATE);

exec STB_INS('0000027988805135','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:46:21.000',timestamp'2011-05-05 01:02:54.000',timestamp'2011-05-04 22:55:10.000','N','N','','','','P',SYSDATE);


After run, check v$sqlarea and v$sql

SQL>  select sql_id, sql_text, executions from v$sqlarea where sql_text like '%MY_STB_LOG3%';

SQL_ID
-------------
SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
EXECUTIONS
----------
4fdv39rhjag5n
INSERT INTO MY_STB_LOG3 VALUES( :B13 ,:B12 ,:B11 ,:B10 ,:B9 ,:B8 ,:B7 ,:B6 ,:B5 ,:B4 ,:B3 ,:B2 ,:B1 )
       324



SQL> select count(*) from v$sql where sql_id='4fdv39rhjag5n';

  COUNT(*)
----------
         1



We see 324 executions shared same cursor.

Appendix

create or replace procedure stb_ins(
p_UNIT_ADDRESS             VARCHAR2
,p_BATCH_NUMBER            VARCHAR2
,p_RECEIVED_TIME           TIMESTAMP
,p_LAST_LOG_TIME           TIMESTAMP
,p_POWERON_TIME            TIMESTAMP
,p_POWEROFF_TIME           TIMESTAMP
,p_UNAVAILABLE_FLAG        VARCHAR2
,p_UNSUBSCRIBE_FLAG        VARCHAR2
,p_WORK_ID                 VARCHAR2
,p_STATUS_CODE             VARCHAR2
,p_STATUS_DESC             VARCHAR2
,p_PROC_STATUS             VARCHAR2
,p_CREATE_DATE             DATE
) 
is
begin
  insert into my_stb_log3 values(
               p_UNIT_ADDRESS           
                ,p_BATCH_NUMBER          
                ,p_RECEIVED_TIME         
                ,p_LAST_LOG_TIME         
                ,p_POWERON_TIME          
                ,p_POWEROFF_TIME         
                ,p_UNAVAILABLE_FLAG      
                ,p_UNSUBSCRIBE_FLAG      
                ,p_WORK_ID               
                ,p_STATUS_CODE           
                ,p_STATUS_DESC           
                ,p_PROC_STATUS            
                ,p_CREATE_DATE            
  );
  commit;
end;
/


Some related references about cursor sharing:

http://www.freelists.org/post/oracle-l/Multiple-SQL-version-count-with-cusror-sharingsimilar,5
http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:599762300346943686
http://kerryosborne.oracle-guy.com/2009/06/oracle-11g-adaptive-cursor-sharing-acs/
http://download.oracle.com/docs/cd/E11882_01/server.112/e16638/optimops.htm#sthref874

Monday, April 11, 2011

Index rebuild and archival procedure

I administer one of the production databases that supports retail ordering application. We have an archival procedure that archives old orders. Last weekend, I rebuilt all of the indexes of 5 tables against which the delete statements in the archival procedure are identified most expensive. The total size of those indexes are reduced by 460GB after rebuild. After the rebuild, the archival of 350K orders took 1h40min compared to 2h30min typically before rebuild. The reason for the performance improvement as far as I can see are as follows:

(1) Decreasing the number of gets in the index range scan operation due to indexes are more compressed
(2) Increasing the chances of caching,  thus reducing the need to wait for db file sequential read.
For example, let's say, index entry 1 is in block 1 and entry 2 is in block 2 before rebuild, so Oracle needs to read block1 and 2 to the buffer cache to delete them; while after rebuild both entry 1 and entry 2 could be in block 1, so Oracle needs to read block 1 once and can work on two entries.

Among those 5 tables, the top-most expensive delete is the one from a table called ORDER_TRANS. There is an index called ORDER_TRANS_IX4 of this table is 16GB after rebuild as compared to 150GB before rebuild. Why is the index so sparse? The index is on the LAST_MODIFIED_DATE column of the table. This is a typical right-hand index, i.e. new index key entries are added to the right hand size of the index tree. The key value is monotonically increasing, like a sequence-based PK. If assuming a leaf block of the index can hold 360 index entries, 99.9% blocks (hold  <=180 entries) are  >50% empty; 97.5% blocks (hold <=90 entries) are >75% empty. (see appendix) .The reasons that why especially right-hand index can grow bigger are described in a Jonathan Lewis's blog post. In my particular case, I believe the problems of the archival procedure itself contribute to the sparsity of the index greatly.

The candidate orders that are eligible for archiving is based on certain business logic. However I found that there are very old orders. e.g. competed in 2004, 2005, that are not selected out for archiving. I confirmed with a lead developer who called those orders "fallout" that those orders should be updated so that they could become eligible for archiving long time ago. In addition, the orders are not selected based on the increasing order of its completion date or cancel date. We can imagine that if we really archive old orders based on their completion or cancel date, i.e, the older the earlier to be archived, we won't have that sparse index in the first place, because left-hand size leaf block can become empty much sooner and easily and thus reused.

In summary, it appears that rebuild index improves our archival procedure performance; however, we may want to  look it in the other way around. If the old orders are really archived based on common sense, we probably don't need to rebuild index at all.


Appendix - How the leaf blocks of ORDER_TRANS_IX4 are used based on JL's script. ( Sample 5% blocks)

ROWS_PER_BLOCK     BLOCKS     ROW_CT CUMULATIVE_BLOCKS
-------------- ---------- ---------- -----------------
             1      16232      16232             16232
             2      14696      29392             30928
             3      13739      41217             44667
             4      13840      55360             58507
             5      13316      66580             71823
             6      13859      83154             85682
             7      13787      96509             99469
             8      13842     110736            113311
             9      13937     125433            127248
            10      14127     141270            141375
            11      14244     156684            155619
            12      14528     174336            170147
            13      14566     189358            184713
            14      15005     210070            199718
            15      15150     227250            214868
            16      15492     247872            230360
            17      15868     269756            246228
            18      16015     288270            262243
            19      16026     304494            278269
            20      16217     324340            294486
            21      16106     338226            310592
            22      16121     354662            326713
            23      16257     373911            342970
            24      15860     380640            358830
            25      15912     397800            374742
            26      15920     413920            390662
            27      15859     428193            406521
            28      15462     432936            421983
            29      15288     443352            437271
            30      15095     452850            452366
            31      15346     475726            467712
            32      15000     480000            482712
            33      14832     489456            497544
            34      14719     500446            512263
            35      14147     495145            526410
            36      13925     501300            540335
            37      13671     505827            554006
            38      13452     511176            567458
            39      13278     517842            580736
            40      13109     524360            593845
            41      13040     534640            606885
            42      12801     537642            619686
            43      12338     530534            632024
            44      11986     527384            644010
            45      11732     527940            655742
            46      11123     511658            666865
            47      11126     522922            677991
            48      10896     523008            688887
            49      10546     516754            699433
            50      10178     508900            709611
            51       9644     491844            719255
            52       9593     498836            728848
            53       9208     488024            738056
            54       9009     486486            747065
            55       8421     463155            755486
            56       8393     470008            763879
            57       7992     455544            771871
            58       7651     443758            779522
            59       7329     432411            786851
            60       6941     416460            793792
            61       6662     406382            800454
            62       6526     404612            806980
            63       6320     398160            813300
            64       5864     375296            819164
            65       5687     369655            824851
            66       5334     352044            830185
            67       5182     347194            835367
            68       4953     336804            840320
            69       4728     326232            845048
            70       4379     306530            849427
            71       4219     299549            853646
            72       4124     296928            857770
            73       3769     275137            861539
            74       3737     276538            865276
            75       3553     266475            868829
            76       3268     248368            872097
            77       3102     238854            875199
            78       3010     234780            878209
            79       2860     225940            881069
            80       2608     208640            883677
            81       2552     206712            886229
            82       2408     197456            888637
            83       2238     185754            890875
            84       2236     187824            893111
            85       1989     169065            895100
            86       1883     161938            896983
            87       1737     151119            898720
            88       1705     150040            900425
            89       1627     144803            902052
            90       1479     133110            903531
            91       1447     131677            904978
            92       1314     120888            906292
            93       1316     122388            907608
            94       1207     113458            908815
            95       1258     119510            910073
            96       1065     102240            911138
            97       1049     101753            912187
            98        974      95452            913161
            99        927      91773            914088
           100        919      91900            915007
           101        877      88577            915884
           102        828      84456            916712
           103        794      81782            917506
           104        666      69264            918172
           105        635      66675            918807
           106        617      65402            919424
           107        549      58743            919973
           108        458      49464            920431
           109        475      51775            920906
           110        292      32120            921198
           111        243      26973            921441
           112        244      27328            921685
           113        201      22713            921886
           114        219      24966            922105
           115        169      19435            922274
           116        150      17400            922424
           117        167      19539            922591
           118        177      20886            922768
           119        128      15232            922896
           120        135      16200            923031
           121        140      16940            923171
           122        134      16348            923305
           123        130      15990            923435
           124         99      12276            923534
           125        107      13375            923641
           126        104      13104            923745
           127         84      10668            923829
           128        106      13568            923935
           129         86      11094            924021
           130         68       8840            924089
           131         97      12707            924186
           132         71       9372            924257
           133         71       9443            924328
           134         61       8174            924389
           135         72       9720            924461
           136         82      11152            924543
           137         48       6576            924591
           138         72       9936            924663
           139         64       8896            924727
           140         58       8120            924785
           141         41       5781            924826
           142         41       5822            924867
           143         35       5005            924902
           144         45       6480            924947
           145         39       5655            924986
           146         37       5402            925023
           147         32       4704            925055
           148         39       5772            925094
           149         26       3874            925120
           150         25       3750            925145
           151         38       5738            925183
           152         33       5016            925216
           153         34       5202            925250
           154         36       5544            925286
           155         33       5115            925319
           156         29       4524            925348
           157         33       5181            925381
           158         25       3950            925406
           159         22       3498            925428
           160         34       5440            925462
           161         22       3542            925484
           162         21       3402            925505
           163         21       3423            925526
           164         22       3608            925548
           165         21       3465            925569
           166         25       4150            925594
           167         19       3173            925613
           168         17       2856            925630
           169         16       2704            925646
           170         15       2550            925661
           171         17       2907            925678
           172          9       1548            925687
           173          9       1557            925696
           174         17       2958            925713
           175         13       2275            925726
           176         16       2816            925742
           177         13       2301            925755
           178         14       2492            925769
           179         10       1790            925779
           180          7       1260            925786
           181          7       1267            925793
           182          6       1092            925799
           183          9       1647            925808
           184          7       1288            925815
           185          7       1295            925822
           186          9       1674            925831
           187          6       1122            925837
           188          8       1504            925845
           189          5        945            925850
           190          7       1330            925857
           191          5        955            925862
           192          9       1728            925871
           193          6       1158            925877
           194          5        970            925882
           195          8       1560            925890
           196          8       1568            925898
           197          9       1773            925907
           198          6       1188            925913
           199          5        995            925918
           200          3        600            925921
           201          2        402            925923
           202          6       1212            925929
           203          5       1015            925934
           204          5       1020            925939
           205          4        820            925943
           206          5       1030            925948
           207          3        621            925951
           209          1        209            925952
           210          5       1050            925957
           211          3        633            925960
           212          3        636            925963
           213          3        639            925966
           214          4        856            925970
           215          3        645            925973
           216          1        216            925974
           217          2        434            925976
           218          4        872            925980
           219          3        657            925983
           220          2        440            925985
           221          2        442            925987
           222          2        444            925989
           223          4        892            925993
           224          2        448            925995
           225          2        450            925997
           226          2        452            925999
           227          2        454            926001
           228          1        228            926002
           229          4        916            926006
           230          5       1150            926011
           231          2        462            926013
           232          3        696            926016
           233          2        466            926018
           234          1        234            926019
           235          5       1175            926024
           236          3        708            926027
           237          3        711            926030
           239          3        717            926033
           240          4        960            926037
           241          4        964            926041
           242          1        242            926042
           243          2        486            926044
           244          5       1220            926049
           245          3        735            926052
           246          2        492            926054
           248          1        248            926055
           249          1        249            926056
           250          2        500            926058
           252          4       1008            926062
           255          4       1020            926066
           256          4       1024            926070
           257          2        514            926072
           258          1        258            926073
           259          4       1036            926077
           261          1        261            926078
           262          2        524            926080
           263          1        263            926081
           264          2        528            926083
           265          1        265            926084
           266          2        532            926086
           267          4       1068            926090
           268          2        536            926092
           269          2        538            926094
           271          1        271            926095
           272          1        272            926096
           273          3        819            926099
           275          2        550            926101
           277          1        277            926102
           278          1        278            926103
           279          1        279            926104
           280          2        560            926106
           281          1        281            926107
           283          1        283            926108
           284          3        852            926111
           285          1        285            926112
           286          3        858            926115
           288          2        576            926117
           289          1        289            926118
           290          1        290            926119
           291          2        582            926121
           292          3        876            926124
           293          3        879            926127
           294          1        294            926128
           295          1        295            926129
           296          1        296            926130
           297          2        594            926132
           298          2        596            926134
           299          1        299            926135
           301          1        301            926136
           302          4       1208            926140
           305          1        305            926141
           306          1        306            926142
           308          1        308            926143
           309          3        927            926146
           310          1        310            926147
           313          1        313            926148
           314          1        314            926149
           315          2        630            926151
           317          1        317            926152
           318          2        636            926154
           319          1        319            926155
           320          2        640            926157
           321          2        642            926159
           322          3        966            926162
           323          2        646            926164
           324          2        648            926166
           325          1        325            926167
           326          1        326            926168
           327          2        654            926170
           328          3        984            926173
           329          3        987            926176
           330          3        990            926179
           331          2        662            926181
           332          2        664            926183
           333          2        666            926185
           334          2        668            926187
           335          2        670            926189
           336          1        336            926190
           337          2        674            926192
           338          3       1014            926195
           340          3       1020            926198
           341          3       1023            926201
           342          1        342            926202
           343          3       1029            926205
           344          6       2064            926211
           345          4       1380            926215
           346          2        692            926217
           347          2        694            926219
           348          4       1392            926223
           349          4       1396            926227
           350          5       1750            926232
           351          3       1053            926235
           352          4       1408            926239
           354          3       1062            926242
           355          5       1775            926247
           356          5       1780            926252
           357          4       1428            926256
           358          6       2148            926262
           359          2        718            926264
           360          6       2160            926270
           361          9       3249            926279
           362          6       2172            926285
           363          5       1815            926290
           364          6       2184            926296
           365          9       3285            926305
           366         11       4026            926316
           367         43      15781            926359
               ---------- ----------
sum                926359   32433921

Monday, February 28, 2011

How can I confirm there was an I/O problem (2) ?

In a previous post, I have mentioned that I have tried to mine AWR data to confirm an I/O issue occurred around 2:18 PM of Feb 18; however I encountered some issue and instead found out 'sar' was helpful. Today, I worked out the query against AWR tables. The query is as follows:

rem  awr_io_file_smpl.sql  
rem   -- Adapted from the scripts written by Karl Arao: http://karlarao.wordpress.com
rem
rem  check if there are I/O problem from AWR. 
rem  normally atpr (Average time per read)  should be less than 20 ms
rem  if atpr > 100 ms, it obviously indicates that we have problem
rem   
rem  note: the statistics are based on  (tm-interval, tm)
rem    


col atpr format 999,999
col atpw format 999,999

set echo off
-- set markup HTML ON
-- SPOOL ON ENTMAP ON PREFORMAT OFF
-- spool awr_io_file_smpl.html
spool awr_io_file_smpl.log
select * from (
SELECT 
--      s0.snap_id snap_id,
       to_char(s1.END_INTERVAL_TIME, 'YYMMDD HH24:MI') tm,
--      s0.instance_number inst,
       ROUND(EXTRACT(DAY FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 1440 + EXTRACT(HOUR FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 60 + EXTRACT(MINUTE FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) + EXTRACT(SECOND FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) / 60, 2) dur,
--      e.tsname,
      e.file# ,
--      SUBSTR(e.filename, 1, 52) filename ,
--      e.readtim         - NVL(b.readtim,0) readtim ,
      e.phyrds          - NVL(b.phyrds,0) reads ,
      DECODE ((e.phyrds - NVL(b.phyrds, 0)), 0, to_number(NULL), ((e.readtim - NVL(b.readtim,0)) 
                   / (e.phyrds - NVL(b.phyrds,0)))*10) atpr ,
--      (e.phyrds         - NVL(b.phyrds,0)) / ((ROUND(EXTRACT(DAY FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 1440 + EXTRACT(HOUR FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 60 + EXTRACT(MINUTE FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) + EXTRACT(SECOND FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) / 60, 2))*60) rps  ,
--      DECODE ((e.phyrds  - NVL(b.phyrds, 0)), 0, to_number(NULL), (e.phyblkrd - NVL(b.phyblkrd,0)) / (e.phyrds - NVL(b.phyrds,0)) ) bpr ,
--      e.writetim         - NVL(b.writetim,0) writetim ,
      e.phywrts          - NVL(b.phywrts,0) writes ,
      DECODE ((e.phywrts - NVL(b.phywrts, 0)), 0, to_number(NULL), ((e.writetim - NVL(b.writetim,0)) / (e.phywrts - NVL(b.phywrts,0)))*10) atpw ,
--      (e.phywrts         - NVL(b.phywrts,0)) / ((ROUND(EXTRACT(DAY FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 1440 + EXTRACT(HOUR FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 60 + EXTRACT(MINUTE FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) + EXTRACT(SECOND FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) / 60, 2))*60) wps ,
--      DECODE ((e.phywrts    - NVL(b.phywrts, 0)), 0, to_number(NULL), (e.phyblkwrt - NVL(b.phyblkwrt,0)) / (e.phywrts - NVL(b.phywrts,0)) ) bpw ,
--      e.wait_count          - NVL(b.wait_count,0) waits ,
--      DECODE ((e.wait_count - NVL(b.wait_count, 0)), 0, 0, ((e.time - NVL(b.time,0)) / (e.wait_count - NVL(b.wait_count,0)))*10) atpwt,
      (e.phyrds             - NVL(b.phyrds,0)) + (e.phywrts - NVL(b.phywrts,0)) ios,
      ((e.phyrds            - NVL(b.phyrds,0)) + (e.phywrts - NVL(b.phywrts,0))) / ((ROUND(EXTRACT(DAY FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 1440 + EXTRACT(HOUR FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) * 60 + EXTRACT(MINUTE FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) + EXTRACT(SECOND FROM s1.END_INTERVAL_TIME - s0.END_INTERVAL_TIME) / 60, 2))*60) iops
    FROM dba_hist_snapshot s0,
      dba_hist_snapshot s1,
      dba_hist_filestatxs e,
      dba_hist_filestatxs b
    WHERE s0.dbid =(select dbid from v$database)
    AND s1.dbid            = s0.dbid
    AND b.dbid(+)          = s0.dbid -- begin dbid
    AND e.dbid             = s0.dbid -- end dbid
    AND b.dbid             = e.dbid  -- remove oj
    AND s0.instance_number =dbms_utility.CURRENT_INSTANCE
    AND s1.instance_number = s0.instance_number
    AND b.instance_number(+) = s0.instance_number 
    AND e.instance_number    = s0.instance_number 
    AND b.instance_number    = e.instance_number 
    AND s1.snap_id           = s0.snap_id + 1
    AND b.snap_id(+)         = s0.snap_id      
    AND e.snap_id            = s0.snap_id + 1 
    AND b.tsname             = e.tsname      
    AND b.file#              = e.file#           
    AND b.creation_change#   = e.creation_change# 
    AND ((e.phyrds - NVL(b.phyrds,0)) + (e.phywrts - NVL(b.phywrts,0))) > 0
    AND s0.END_INTERVAL_TIME >= to_date('2011-02-18 13:00:00', 'YYYY-MM-DD HH24:MI:SS') 
    AND s0.END_INTERVAL_TIME <= to_date('2011-02-18 16:00:00', 'YYYY-MM-DD HH24:MI:SS') 
    order by s1.END_INTERVAL_TIME, e.tsname
--    and b.tsname='xxxx'
)
where atpr > 100 
;
spool off
set markup html off spool off
set termout on



The output of above query is as follows:

TM                  DUR      FILE#      READS     ATPR     WRITES     ATPW        IOS       IOPS
------------ ---------- ---------- ---------- -------- ---------- -------- ---------- ----------
110218 14:00      15.04        268          8      124          1        0          9 .009973404
110218 14:00      15.04        283          7      141          1        0          8 .008865248
110218 14:00      15.04        281          8      118          1        0          9 .009973404
110218 14:00      15.04        296          8      116          1        0          9 .009973404
110218 14:00      15.04        273          8      123          1        0          9 .009973404
110218 14:00      15.04        293          8      123          1        0          9 .009973404
110218 14:00      15.04        288          8      125          1        0          9 .009973404
110218 14:00      15.04        276          8      120          1        0          9 .009973404
110218 14:00      15.04        286          7      133          1        0          8 .008865248
110218 14:00      15.04        278          8      123          1        0          9 .009973404
110218 14:00      15.04        308          8      125          1        0          9 .009973404
110218 14:00      15.04        271          8      116          1        0          9 .009973404
110218 14:00      15.04        248          7      139          1       10          8 .008865248
110218 14:30       14.6        502       3472      205        620      816       4092 4.67123288
110218 14:30       14.6        519        351    1,695         72    1,749        423 .482876712
110218 14:30       14.6        515        664      347         90        6        754 .860730594
110218 14:30       14.6        504       1174      214        114    1,107       1288 1.47031963
110218 14:30       14.6        448       8463      139        550      461       9013 10.2888128
110218 14:30       14.6        412       5772      131        361      353       6133 7.00114155
110218 14:30       14.6        462       5889      215        437      291       6326 7.22146119
110218 14:30       14.6        429      10276      313        356      360      10632 12.1369863
110218 14:30       14.6        427       4255      189        183      691       4438 5.06621005
110218 14:30       14.6        473       7355      298        865      149       8220 9.38356164
110218 14:30       14.6        513        867      148        218      587       1085 1.23858447
110218 14:30       14.6        479       5903      196        986      144       6889 7.86415525
110218 14:30       14.6        475       7702      263       1163      221       8865  10.119863
110218 14:30       14.6        471       9543      155        141      906       9684 11.0547945
110218 14:30       14.6        523       2187      378       1014      253       3201 3.65410959
110218 14:30       14.6        482       6674      150       1536      252       8210 9.37214612
110218 14:30       14.6        437      10793      271       1920      401      12713 14.5125571
110218 14:30       14.6        395       8062      151        555      233       8617 9.83675799
110218 14:30       14.6        464      19537      431       4212      144      23749 27.1107306
110218 14:30       14.6        491      14568      440       4247      220      18815 21.4783105
110218 14:30       14.6        444      20026      385       2541      212      22567 25.7614155
110218 14:30       14.6        481      15496      444       3763      287      19259 21.9851598
110218 14:30       14.6        421      14930      334       1642       85      16572 18.9178082
110218 14:30       14.6        514       5464      597       2542      360       8006 9.13926941
110218 14:30       14.6        435       3804      165        167      751       3971 4.53310502
110218 14:30       14.6        512       2065      237        474      276       2539 2.89840183
110218 14:30       14.6        498       4540      186        508      993       5048 5.76255708
110218 14:30       14.6        478       8505      159       1161      561       9666 11.0342466
110218 14:30       14.6        470       8134      182        454      283       8588 9.80365297
110218 14:30       14.6        460       4841      168        391      325       5232 5.97260274
110218 14:30       14.6        474       6486      130        779      166       7265   8.293379
110218 14:30       14.6        411       3368      291        186      678       3554 4.05707763
110218 14:30       14.6        521       2447      183        543      235       2990 3.41324201
110218 14:30       14.6        418       3837      124        128      991       3965 4.52625571
110218 14:30       14.6        100        160    1,370        670      213        830 .947488584
110218 14:30       14.6        139        408      273       1061      366       1469 1.67694064
110218 15:00      15.03         62          4      103          1       10          5 .005544467
110218 15:30      15.04         69          6      107          2        0          8 .008865248
110218 15:30      15.04         62          6      102          2        5          8 .008865248
110218 15:30      15.04         63          6      102          2        5          8 .008865248
110218 15:30      15.04         64          6      107          2        5          8 .008865248
110218 15:30      15.04         78          6      113          2        5          8 .008865248
110218 15:30      15.04         77          6      107          2       10          8 .008865248
110218 15:30      15.04         66          6      107          2        5          8 .008865248
110218 16:00      15.04        125          6      282          1      180          7 .007757092
110218 16:00      15.04        110          6      282          1       70          7 .007757092

59 rows selected.

From the above output, it can be seen from about 14:15 -14:30, there are many data files having APTR > 100 ms. This clearly indicates there was I/O problem during that period.