ORA-16957: SQL Analyze time limit interrupt

time_expired

First thing this morning, I was greeted with an email from my alert log monitor containing the error in the title.  This is one of the less cryptic error messages from an Oracle database, but what does it mean?

If you are an Oracle DBA and have been dealing with performance issues for any length of time, you are familiar with the SQL Tuning Advisor.  This tool is part of the Oracle Tuning Pack .  It takes one or more SQL statements as input, analyzes them, and displays recommendations to tune the statements with rationale and expected benefits.  These recommendations can include collecting object statistics, creating indexes, creating SQL profiles or SQL plan baselines, and even recommendations to rewrite.

The SQL Tuning Advisor has two modes – automatic and manual.  The automatic mode is referred to as the Automatic SQL Tuning Task or SQL Analyze for short.  This task when enabled runs nightly as part of the default maintenance plan.  Usually it runs happily in the background and goes mostly unnoticed.  Other times it generates an ORA-16957 error. This error means that it has not completed within its limit settings. You can view these settings like this:

COLUMN parameter_value FORMAT A30  

SELECT parameter_name, parameter_value  
FROM dba_advisor_parameters  
WHERE task_name = 'SYS_AUTO_SQL_TUNING_TASK'  
AND parameter_name IN ('TIME_LIMIT','DEFAULT_EXECUTION_TYPE',
'SQL_LIMIT','LOCAL_TIME_LIMIT');

PARAMETER_NAME                 PARAMETER_VALUE  

------------------------------ ------------------------------  

LOCAL_TIME_LIMIT               1200  
TIME_LIMIT                     7200  
DEFAULT_EXECUTION_TYPE         TUNE SQL
SQL_LIMIT                      -1

The time_limit value is the total time in seconds that the SQL Analyze job is allowed per execution within the maintenance window.  The local_time_limit is the value in seconds that the SQL Analyze job is allowed to spend analyzing each individual SQL statement.  The sql_limit parameter is the number of SQL statements to examine per execution of the job.  The -1 number indicates no limit to the number of SQL statements the job can review within its time limit.

How does it determine which statements need to be analyzed?  From the Oracle documentation, the following quote is taken:

The automated SQL tuning task does not process the following types of SQL:

  • Ad hoc SQL statements or SQL statements that do not repeat within a week
  • Parallel queries
  • Queries that take too long to run after being SQL profiled, so that it is not practical for SQL Tuning Advisor to test execution
  • Recursive SQL

 You can run SQL Tuning Advisor on demand to tune the preceding types of SQL statements.

 

Can we find out what SQL statement caused the ORA-16957 error?

Get the execution_name for the long run day:

set lines 200 pages 100 
col error_message for a60 
col execution_name for a15 

select execution_name, advisor_name,to_char(execution_start,'dd-mon-yy hh:mi:ss'), to_char(execution_end,'dd-mon-yy hh:mi:ss'), status,error_message 
from dba_advisor_executions 
where task_name = 'SYS_AUTO_SQL_TUNING_TASK' 
order by execution_start desc;

Take the name of the execution you are interested in and place it into the query below to identify the ID of the SQL causing the overrun.  If a sufficient amount of time has passed, you may not get any data from this query.

SELECT sql_id, sql_text FROM dba_hist_sqltext 
WHERE sql_id IN (SELECT attr1 FROM dba_advisor_objects 
WHERE execution_name = '&execution_name' 
AND task_name = 'SYS_AUTO_SQL_TUNING_TASK' 
AND type = 'SQL' AND bitand(attr7,64) <> 0 );


 Then you can take the SQL_ID from the query above and run it through the manual mode of the SQL Tuning Advisor:

Create the tuning task:

DECLARE 
l_sql_tune_task_id VARCHAR2(100); 
BEGIN 
l_sql_tune_task_id := DBMS_SQLTUNE.create_tuning_task ( 
sql_id => '&SQL_ID', 
scope => DBMS_SQLTUNE.scope_comprehensive, 
time_limit => 99999,   --I use a large time out value 
task_name => 'my_tuning_task', 
description => 'Tuning task for statement blahblah.'); 
DBMS_OUTPUT.put_line('l_sql_tune_task_id: ' || l_sql_tune_task_id); 
END; 
/

 

Execute the tuning task:

BEGIN 
DBMS_SQLTUNE.EXECUTE_TUNING_TASK( task_name => 'my_tuning_task'); 
end; 
/

When the task is complete, get the report:

SET LONG 5000 
SET LONGCHUNKSIZE 5000 
SET LINESIZE 200 
SELECT DBMS_SQLTUNE.REPORT_TUNING_TASK('my_tuning_task') from DUAL;

Be sure to drop the tuning task before executing another.  NOTE – If the tuning task results recommend using a SQL Profile, then you MUST accept the profile before dropping the tuning task.  Otherwise, the recommended profile will be lost and you will need to run the tuning task again.

BEGIN
  dbms_sqltune.drop_tuning_task (task_name => 'my_tuning_task');
END;
/

 

In the event that the ORA-16957 error is seen on a regular basis, you may need to adjust the SQL Analyze task limits or limit the number of SQL statements analyzed. Use the DBMS_SQL_AUTOTUNE.SET_TUNING_TASK_PARAMETER procedure to change these values.  Here is an example of changing the time limit to 7200 seconds (2 hours):

BEGIN 
DBMS_SQLTUNE.SET_TUNING_TASK_PARAMETER(task_name => 'SYS_AUTO_SQL_TUNING_TASK', 
parameter => 'TIME_LIMIT', value => 7200); 
END; 
/

 

If you need to determine if the SQL Analyze job is running against your database, use this query:

SELECT CLIENT_NAME, STATUS
 FROM   DBA_AUTOTASK_CLIENT
 WHERE  CLIENT_NAME = 'sql tuning advisor';
  
 CLIENT_NAME          STATUS
 -------------------- --------
 sql tuning advisor   ENABLED

 

You can disable or enable the SQL Analyze job with these commands:

BEGIN
   DBMS_AUTO_TASK_ADMIN.ENABLE (
     client_name => 'sql tuning advisor'
 ,   operation   => NULL
 ,   window_name => NULL
 );
 END;
 /


 BEGIN
   DBMS_AUTO_TASK_ADMIN.DISABLE (
     client_name => 'sql tuning advisor'
 ,   operation   => NULL
 ,   window_name => NULL
 );
 END;
 /

If you are interested in viewing the latest SQL Analyze report:

VARIABLE l_report CLOB;

BEGIN
:l_report := DBMS_SQLTUNE.report_auto_tuning_task(
begin_exec => NULL,
end_exec => NULL,
type => DBMS_SQLTUNE.type_text,
level => DBMS_SQLTUNE.level_typical,
section => DBMS_SQLTUNE.section_all,
object_id => NULL,
result_limit => NULL
);
END;
/

SET LONG 1000000
PRINT :l_report

If this task is enabled in your database, then take advantage of its analysis.  Regular viewing of its output may help identify ‘usual suspects’ that continue to run poorly.

 

Advertisements

Blast from the past – Rollback segments

Those of us that have worked with Oracle databases over the years have seen new features come along that relieved some of the more challenging aspects of database administration (i.e. things that drove us crazy).  One of the new features we were happy to see was automatic undo management in Oracle 9i release 1.  This new feature made the challenge of managing rollback segments obsolete. In the days before automatic undo management, the DBA not only had to create the rollback tablespace, but also size and manage the rollback segments it contained.

For newer DBA’s, these terms may not be familiar, so a little background may be in order.  Before the undo tablespace, there was the rollback tablespace.  This was where Oracle maintained changed, but uncommitted data for read consistency, much like the undo tablespace.  The rollback tablespace was comprised of rollback segments which needed to be manually created by the DBA.  The number and size of these segments was at the discretion of the DBA.  If the number or size of the rollback segments was insufficient for the amount of database activity, then contention for the rollback segment data blocks was a real, and common, occurrence.

Here is a typical database creation script from the Oracle 8i release 3 (8.1.7) documentation:

CREATE DATABASE rbdb1
    CONTROLFILE REUSE
    LOGFILE '/u01/oracle/rbdb1/redo01.log' SIZE 1M REUSE,
            '/u01/oracle/rbdb1/redo02.log' SIZE 1M REUSE,
            '/u01/oracle/rbdb1/redo03.log' SIZE 1M REUSE,
            '/u01/oracle/rbdb1/redo04.log' SIZE 1M REUSE
    DATAFILE '/u01/oracle/rbdb1/system01.dbf' SIZE 10M REUSE 
      AUTOEXTEND ON
      NEXT 10M MAXSIZE 200M 
    CHARACTER SET WE8ISO8859P1;

CREATE ROLLBACK SEGMENT rb_temp STORAGE (INITIAL 100 k NEXT 250 k);

-- Alter temporary system tablespace online before proceding
ALTER ROLLBACK SEGMENT rb_temp ONLINE;

-- Create additional tablespaces ...
-- RBS: For rollback segments
-- USERs: Create user sets this as the default tablespace
-- TEMP: Create user sets this as the temporary tablespace
CREATE TABLESPACE rbs
    DATAFILE '/u01/oracle/rbdb1/rbs01.dbf' SIZE 5M REUSE AUTOEXTEND ON
      NEXT 5M MAXSIZE 150M;
CREATE TABLESPACE users
    DATAFILE '/u01/oracle/rbdb1/users01.dbf' SIZE 3M REUSE AUTOEXTEND ON
      NEXT 5M MAXSIZE 150M;
CREATE TABLESPACE temp
    DATAFILE '/u01/oracle/rbdb1/temp01.dbf' SIZE 2M REUSE AUTOEXTEND ON
      NEXT 5M MAXSIZE 150M;

-- Create rollback segments.  
CREATE ROLLBACK SEGMENT rb1 STORAGE(INITIAL 50K NEXT 250K)
  tablespace rbs;
CREATE ROLLBACK SEGMENT rb2 STORAGE(INITIAL 50K NEXT 250K)
  tablespace rbs;
CREATE ROLLBACK SEGMENT rb3 STORAGE(INITIAL 50K NEXT 250K)
  tablespace rbs;
CREATE ROLLBACK SEGMENT rb4 STORAGE(INITIAL 50K NEXT 250K)
  tablespace rbs;

-- Bring new rollback segments online and drop the temporary system one
ALTER ROLLBACK SEGMENT rb1 ONLINE;
ALTER ROLLBACK SEGMENT rb2 ONLINE;
ALTER ROLLBACK SEGMENT rb3 ONLINE;
ALTER ROLLBACK SEGMENT rb4 ONLINE;

ALTER ROLLBACK SEGMENT rb_temp OFFLINE;
DROP ROLLBACK SEGMENT rb_temp ;

As you can see, you had to create and online one system rollback segment in the system tablespace before you could create the other tablespaces including rollback with its inclusive rollback segments.  You then had to bring the rollback segments you created online.  The temporary rollback segment was taken offline and removed at the end for housekeeping.

Rollback segments still exist in the newer versions of the Oracle database, but they are automatically created and managed by internal processes.  Additional segments are automatically created as needed.

Here is the output from a 9i release 1 database.  The sys-owned rollback segment takes the place of the rb_temp rollback segment in the 8i database creation script present during the creation of the database.  The difference here is that it is created automatically as part of the database creation process.  The remaining rollback segments were created automatically when the undo tablespace was created.

SQL> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle9i Enterprise Edition Release 9.0.1.1.1 - Production
PL/SQL Release 9.0.1.1.1 - Production
CORE    9.0.1.1.1       Production
TNS for 32-bit Windows: Version 9.0.1.1.0 - Production
NLSRTL Version 9.0.1.1.1 - Production


SQL> select segment_name, owner from dba_rollback_segs;

SEGMENT_NAME                   OWNER
------------------------------ ------
SYSTEM                         SYS
_SYSSMU1$                      PUBLIC
_SYSSMU2$                      PUBLIC
_SYSSMU3$                      PUBLIC
_SYSSMU4$                      PUBLIC
_SYSSMU5$                      PUBLIC
_SYSSMU6$                      PUBLIC
_SYSSMU7$                      PUBLIC
_SYSSMU8$                      PUBLIC
_SYSSMU9$                      PUBLIC
_SYSSMU10$                     PUBLIC


Except for the segment naming convention, things look very similar in a version 11.2.0.4.0 database

SQL> select * from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
PL/SQL Release 11.2.0.4.0 - Production
CORE    11.2.0.4.0      Production
TNS for Linux: Version 11.2.0.4.0 - Production
NLSRTL Version 11.2.0.4.0 - Production

SQL> select segment_name, owner from dba_rollback_segs;

SEGMENT_NAME                   OWNER
------------------------------ ------
SYSTEM                         SYS
_SYSSMU10_1197734989$          PUBLIC
_SYSSMU9_1650507775$           PUBLIC
_SYSSMU8_517538920$            PUBLIC
_SYSSMU7_2070203016$           PUBLIC
_SYSSMU6_1263032392$           PUBLIC
_SYSSMU5_898567397$            PUBLIC
_SYSSMU4_1254879796$           PUBLIC
_SYSSMU3_1723003836$           PUBLIC
_SYSSMU2_2996391332$           PUBLIC
_SYSSMU1_3724004606$           PUBLIC

When automatic undo management was first introduced, you could choose between MANUAL or AUTO.  The manual setting was the default and I suspect this had to do with not wanting to force this new feature on anyone.  It wasn’t until 11g release 1 that the AUTO setting became the default for this parameter.  These days, I don’t know of anyone who still uses manual redo management, although it is still available as of 12c release 2.   Although there are occasional ORA-01555 (snapshot too old) errors encountered with the use of auto undo management, this is one feature that I think was worth the wait.

 

 

SQL Server Health Check v2

The new version of my SQL Server health check script adds the following improvements:

–Added queries for database start time and up time
–Added query to display memory usage of in-memory OLTP tables

----------------------------------------------------------Start of script
--sql_server_health_check_v2.sql
--v2
--This is a non-intrusive script written to give an overall informational view of a 
--SQL Server 2005-2016(CTP3) server instance for the purpose of first-time review.
--
--Version 2 additions
--Added queries for start time and up time
--Added query to display memory usage of in-memory OLTP tables


use master
GO

--Node name

SELECT SERVERPROPERTY('ComputerNamePhysicalNetBIOS') AS [CurrentNodeName];

--Version

select @@version as [VERSION];


--Instance parameters

print N'Instance Parameter';


SELECT  *
FROM    sys.configurations
ORDER BY name ;


--Database listing

print N'Database list with Status and Recovery Model';

--Database startup time

print N'Start time';

SELECT DATEADD(ms,-sample_ms,GETDATE() )AS StartTime
FROM sys.dm_io_virtual_file_stats(1,1);


--Database uptime

print N'Up time';


DECLARE @server_start_time DATETIME,
@seconds_diff INT,
@years_online INT,
@days_online INT,
@hours_online INT,
@minutes_online INT,
@seconds_online INT ;

SELECT @server_start_time = login_time
FROM master.sys.sysprocesses
WHERE spid = 1 ;

SELECT @seconds_diff = DATEDIFF(SECOND, @server_start_time, GETDATE()),
@years_online = @seconds_diff / 31536000,
@seconds_diff = @seconds_diff % 31536000,
@days_online = @seconds_diff / 86400,
@seconds_diff = @seconds_diff % 86400,
@hours_online = @seconds_diff / 3600,
@seconds_diff = @seconds_diff % 3600,
@minutes_online = @seconds_diff / 60,
@seconds_online = @seconds_diff % 60 ;

SELECT @server_start_time AS server_start_time,
@years_online AS years_online,
@days_online AS days_online,
@hours_online AS hours_online,
@minutes_online AS minutes_online,
@seconds_online AS seconds_online ;


SELECT substring(name,1,40) AS name,  substring(state_desc,1,20) AS STATE, 
substring(recovery_model_desc,1,20) AS RECOVERY_MODEL
   FROM sys.databases
order by name;



--Database file size and growth settings

print N'Size and Growth';


select substring(b.name,1,40) AS DB_Name, substring(a.name,1,40) AS Logical_name, 
substring(a.filename,1,100) AS File_Name,
cast((a.size * 8.00) / 1024 as numeric(12,2)) as DB_Size_in_MB,
case when a.growth > 100 then 'In MB' else 'In Percentage' end File_Growth,
cast(case when a.growth > 100 then (a.growth * 8.00) / 1024
else (((a.size * a.growth) / 100) * 8.00) / 1024
end as numeric(12,2)) File_Growth_Size_in_MB,
case when ( maxsize = -1 or maxsize=268435456 ) then 'AutoGrowth Not Restricted' else 'AutoGrowth Restricted' end AutoGrowth_Status
from sysaltfiles a
join sysdatabases b on a.dbid = b.dbid
where DATABASEPROPERTYEX(b.name, 'status') = 'ONLINE'
order by b.name;


--Is this a Cluster Node?

SELECT 'Clustered', case when SERVERPROPERTY('IsClustered') = 0 then 'No'
else 'Yes' end;

--Nodes in Cluster

print N'Cluster Nodes';

SELECT * FROM fn_virtualservernodes();


--Is AlwaysOn enabled (2012 and above)?

SELECT 'AlwaysOn', case when SERVERPROPERTY('IsHadrEnabled') = 0 then 'No'
                        when SERVERPROPERTY('IsHadrEnabled') = 1 then 'Yes'
                        else SERVERPROPERTY('IsHadrEnabled') end;


--AlwaysOn status

declare @c int;
declare @rd nvarchar(60); 
declare @osd nvarchar(60);
declare @rhd nvarchar(60); 
declare @shd nvarchar(60); 
declare @csd nvarchar(60);
select @c = COUNT(name) 
from sys.all_objects
where name = 'dm_hadr_availability_replica_states';
if @c = 0
print N'No AlwaysOn Status';
else
select @rd = role_desc, @osd= case when operational_state_desc is null then 'Replica is not local'
                  else operational_state_desc end,
       @rhd = recovery_health_desc, @shd = synchronization_health_desc,
       @csd = connected_state_desc
from sys.dm_hadr_availability_replica_states;
print @rd
print @osd
print @rhd
print @shd
print @csd
  
	

--Memory usage per database

print N'Memory Usage per User Database';


SELECT 
                substring(DB_NAME(database_id),1,40) AS [Database Name]
                ,COUNT(*) * 8/1024.0 AS [Cached Size (MB)]
FROM 
                sys.dm_os_buffer_descriptors
WHERE 
                database_id > 4 
                AND database_id <> 32767
                AND db_name(database_id) <> 'SSISDB'
GROUP BY DB_NAME(database_id)
ORDER BY [Cached Size (MB)] DESC OPTION (RECOMPILE);



--Memory usage of in-memory OLTP tables

print N'In-memory OLTP table usage';
				      SELECT object_name(object_id) AS Name, *  
				      FROM sys.dm_db_xtp_table_memory_stats;


--Last backup time per database

SELECT substring(sdb.Name,1,40) AS DatabaseName,
COALESCE(CONVERT(VARCHAR(12), MAX(bus.backup_finish_date), 101),'-') AS LastBackUpTime
FROM sys.sysdatabases sdb
LEFT OUTER JOIN msdb.dbo.backupset bus ON bus.database_name = sdb.name
where sdb.Name <> 'tempdb'
GROUP BY sdb.Name;


--No log backups for FULL or BULK_LOGGED recovery model databases in last 30 days


print N'Databases with FULL or BULK_LOGGED recovery model and no log backups in last 30 days';


SELECT name AS at_risk_database
   FROM sys.databases
where recovery_model_desc in('FULL','BULK_LOGGED')
and name not in(
SELECT 
msdb.dbo.backupset.database_name AS DBName 
FROM msdb.dbo.backupmediafamily 
INNER JOIN msdb.dbo.backupset ON msdb.dbo.backupmediafamily.media_set_id = msdb.dbo.backupset.media_set_id 
WHERE (CONVERT(datetime, msdb.dbo.backupset.backup_start_date, 102) >= GETDATE() - 30)
and msdb..backupset.type = 'L'
group by msdb.dbo.backupset.database_name
);



--Databases with no backups at all in the last 30 says

print N'Databases with NO backups in last 30 days';

SELECT name AS at_risk_database
   FROM sys.databases
where name <> 'tempdb'
and name not in(
SELECT 
substring(msdb.dbo.backupset.database_name,1,40) AS DBName 
FROM msdb.dbo.backupmediafamily 
INNER JOIN msdb.dbo.backupset ON msdb.dbo.backupmediafamily.media_set_id = msdb.dbo.backupset.media_set_id 
WHERE (CONVERT(datetime, msdb.dbo.backupset.backup_start_date, 102) >= GETDATE() - 30)
group by msdb.dbo.backupset.database_name
);


--Backups for the previous week per database

print N'All backups for previous week';

SELECT 
CONVERT(CHAR(40), SERVERPROPERTY('Servername')) AS Server, 
substring(msdb.dbo.backupset.database_name,1,40) AS DBName, 
msdb.dbo.backupset.backup_start_date, 
msdb.dbo.backupset.backup_finish_date, 
msdb.dbo.backupset.expiration_date, 
CASE msdb..backupset.type 
WHEN 'D' THEN 'Database' 
WHEN 'L' THEN 'Log'
WHEN 'F' THEN 'File'
WHEN 'P' THEN 'Partial'
WHEN 'I' THEN 'Differential database'
WHEN 'G' THEN 'Differential file'
WHEN 'Q' THEN 'Differential partial'
WHEN NULL THEN msdb..backupset.type 
END AS backup_type, 
msdb.dbo.backupset.backup_size, 
substring(msdb.dbo.backupmediafamily.logical_device_name,1,50) AS logical_device_name, 
substring(msdb.dbo.backupmediafamily.physical_device_name,1,50) AS physical_device_name, 
substring(msdb.dbo.backupset.name,1,50) AS backupset_name, 
substring(msdb.dbo.backupset.description,1,50) AS description 
FROM msdb.dbo.backupmediafamily 
INNER JOIN msdb.dbo.backupset ON msdb.dbo.backupmediafamily.media_set_id = msdb.dbo.backupset.media_set_id 
WHERE (CONVERT(datetime, msdb.dbo.backupset.backup_start_date, 102) >= GETDATE() - 7) 
ORDER BY 
msdb.dbo.backupset.database_name, 
msdb.dbo.backupset.backup_finish_date;


--Jobs that failed in the last 24 hours

print N'Jobs Failing in last 24 hours';

-- Variable Declarations
DECLARE @PreviousDate datetime
DECLARE @Year VARCHAR(4)
DECLARE @Month VARCHAR(2)
DECLARE @MonthPre VARCHAR(2)
DECLARE @Day VARCHAR(2)
DECLARE @DayPre VARCHAR(2)
DECLARE @FinalDate INT
-- Initialize Variables
SET @PreviousDate = DATEADD(dd, -1, GETDATE()) -- Last 1 day
SET @Year = DATEPART(yyyy, @PreviousDate)
SELECT @MonthPre = CONVERT(VARCHAR(2), DATEPART(mm, @PreviousDate))
SELECT @Month = RIGHT(CONVERT(VARCHAR, (@MonthPre + 1000000000)),2)
SELECT @DayPre = CONVERT(VARCHAR(2), DATEPART(dd, @PreviousDate))
SELECT @Day = RIGHT(CONVERT(VARCHAR, (@DayPre + 1000000000)),2)
SET @FinalDate = CAST(@Year + @Month + @Day AS INT)
-- Final Logic
SELECT substring(j.[name],1,40) AS JOB,
substring(s.step_name,1,40) AS Step,
h.step_id,
substring(h.step_name,1,40) AS Step,
h.run_date,
h.run_time,
h.sql_severity,
substring(h.message,1,100) AS Message,
h.server
FROM msdb.dbo.sysjobhistory h
INNER JOIN msdb.dbo.sysjobs j
ON h.job_id = j.job_id
INNER JOIN msdb.dbo.sysjobsteps s
ON j.job_id = s.job_id AND h.step_id = s.step_id
WHERE h.run_status = 0 -- Failure
AND h.run_date > @FinalDate
ORDER BY h.instance_id DESC;



--Missing indexes

print N'Missing Indexes';


SELECT substring(so.name,1,40) AS Name
, (avg_total_user_cost * avg_user_impact) * (user_seeks + user_scans) as Impact
, ddmid.equality_columns
, ddmid.inequality_columns
, ddmid.included_columns
FROM sys.dm_db_missing_index_group_stats AS ddmigs
INNER JOIN sys.dm_db_missing_index_groups AS ddmig
ON ddmigs.group_handle = ddmig.index_group_handle
INNER JOIN sys.dm_db_missing_index_details AS ddmid
ON ddmig.index_handle = ddmid.index_handle
INNER JOIN sys.objects so WITH (nolock)
ON ddmid.object_id = so.object_id
WHERE ddmigs.group_handle IN (
SELECT TOP (5000) group_handle
FROM sys.dm_db_missing_index_group_stats WITH (nolock)
ORDER BY (avg_total_user_cost * avg_user_impact)*(user_seeks+user_scans)DESC);



--Duplicate indexes

print N'Duplicate Indexes';

DECLARE @SCHEMANAME VARCHAR(30);
DECLARE @TABLENAME VARCHAR(127);
WITH ind_list AS(
  select o.schema_id, i.object_id, i.index_id,
    i.name, i.type_desc,
    i.is_unique, i.is_primary_key, 
    STUFF( (SELECT ',' + tc.name
            FROM sys.index_columns ic
              JOIN sys.columns tc
               ON tc.column_id = ic.column_id AND
                  tc.object_id = ic.object_id
            WHERE ic.object_id = i.object_id AND
                  ic.index_id = i.index_id 
              AND ic.is_included_column = 0
            ORDER BY ic.index_column_id
            FOR XML PATH ('') ),1,1,'' ) index_columns,
    STUFF( (SELECT ',' + tc.name
            FROM sys.index_columns ic
              JOIN sys.columns tc
               ON tc.column_id = ic.column_id AND
                  tc.object_id = ic.object_id
            WHERE ic.object_id = i.object_id AND
                  ic.index_id = i.index_id
               AND ic.is_included_column = 1
            ORDER BY ic.index_column_id
            FOR XML PATH ('') ),1,1,'' ) include_columns
  FROM sys.indexes i
    JOIN sys.objects o ON o.object_id = i.object_id
  WHERE i.index_id > 0 AND i.type_desc <> 'XML'
    AND object_name(i.object_id) LIKE @TABLENAME
    AND i.is_disabled = 0 
    AND schema_name(o.schema_id) LIKE @SCHEMANAME )
SELECT substring(schema_name(included_indexes.schema_id),1,30) AS owner, 
  object_name(included_indexes.object_id) table_name,
  (SELECT SUM(st.row_count) FROM sys.dm_db_partition_stats st
   WHERE st.object_id = included_indexes.object_id
     AND st.index_id < 2 ) num_rows,
  included_indexes.name included_index_name, 
  included_indexes.index_columns included_index_columns, 
  included_indexes.include_columns
       included_index_include_columns,
  included_indexes.type_desc included_index_type, 
  included_indexes.is_unique included_index_uniqueness,
  included_indexes.is_primary_key included_index_PK,
  (SELECT SUM(a.total_pages) * 8 FROM sys.allocation_units a
    JOIN sys.partitions p ON a.container_id = p.partition_id
   WHERE p.object_id = included_indexes.object_id AND
     p.index_id = included_indexes.index_id
  ) included_index_size_kb,
  including_indexes.name including_index_name, 
  including_indexes.index_columns including_index_columns, 
  including_indexes.include_columns
       including_index_include_columns,
  including_indexes.type_desc including_index_type, 
  including_indexes.is_unique including_index_uniqueness,
  including_indexes.is_primary_key including_index_PK,
  (SELECT SUM(a.total_pages) * 8 FROM sys.allocation_units a
     JOIN sys.partitions p ON a.container_id = p.partition_id
   WHERE p.object_id = including_indexes.object_id AND
    p.index_id = including_indexes.index_id
  ) including_index_size_kb
FROM ind_list included_indexes
  JOIN ind_list including_indexes
    ON including_indexes.object_id = included_indexes.object_id
  JOIN sys.partitions ing_p 
   ON ing_p.object_id = including_indexes.object_id AND
      ing_p.index_id = including_indexes.index_id
  JOIN sys.allocation_units ing_a
   ON ing_a.container_id = ing_p.partition_id
WHERE including_indexes.index_id <> included_indexes.index_id
  AND LEN(included_indexes.index_columns) <= LEN(including_indexes.index_columns) AND included_indexes.index_columns + ',' = SUBSTRING(including_indexes.index_columns,1, LEN(included_indexes.index_columns + ',')) ORDER BY 2 DESC; --High index fragmentation check print N'Index with HIGH Fragmentation'; EXEC sp_MSforeachdb ' USE [?] SELECT ''?'' AS DB_NAME, QUOTENAME(sysind.name) AS [index_name], indstat.* FROM sys.dm_db_index_physical_stats (DB_ID(), NULL, NULL, NULL, ''LIMITED'') AS indstat INNER JOIN sys.indexes sysind ON indstat.object_id = sysind.object_id AND indstat.index_id = sysind.index_id where avg_fragmentation_in_percent >= 30
ORDER BY avg_fragmentation_in_percent DESC;
'

use master
GO


--Wait stats

print N'Wait Stats';

SELECT *
FROM sys.dm_os_wait_stats
where wait_time_ms > 10000
ORDER BY wait_time_ms DESC;


--Users and roles

print N'Users and Roles';

WITH Roles_CTE(Role_Name, Username)
AS
(
	SELECT 
		User_Name(sm.[groupuid]) as [Role_Name],
		user_name(sm.[memberuid]) as [Username]
	FROM [sys].[sysmembers] sm
)

SELECT  
    Roles_CTE.Role_Name,
    [DatabaseUserName] = princ.[name],
    [UserType] = CASE princ.[type]
                    WHEN 'S' THEN 'SQL User'
                    WHEN 'U' THEN 'Windows User'
                    WHEN 'G' THEN 'Windows Group'
                    WHEN 'A' THEN 'Application Role'
                    WHEN 'R' THEN 'Database Role'
                    WHEN 'C' THEN 'User mapped to a certificate'
                    WHEN 'K' THEN 'User mapped to an asymmetric key'
                 END
FROM 
    sys.database_principals princ 
JOIN Roles_CTE on Username = princ.name
where princ.type in ('S', 'U', 'G', 'A', 'R', 'C', 'K')
ORDER BY princ.name;


--Job information

print N'Job Information';


SELECT	 [JobName] = [jobs].[name]
		,[Category] = [categories].[name]
		,[Owner] = SUSER_SNAME([jobs].[owner_sid])
		,[Enabled] = CASE [jobs].[enabled] WHEN 1 THEN 'Yes' ELSE 'No' END
		,[Scheduled] = CASE [schedule].[enabled] WHEN 1 THEN 'Yes' ELSE 'No' END
		,[Description] = [jobs].[description]
		,[Occurs] = 
				CASE [schedule].[freq_type]
					WHEN   1 THEN 'Once'
					WHEN   4 THEN 'Daily'
					WHEN   8 THEN 'Weekly'
					WHEN  16 THEN 'Monthly'
					WHEN  32 THEN 'Monthly relative'
					WHEN  64 THEN 'When SQL Server Agent starts'
					WHEN 128 THEN 'Start whenever the CPU(s) become idle' 
					ELSE ''
				END
		,[Occurs_detail] = 
				CASE [schedule].[freq_type]
					WHEN   1 THEN 'O'
					WHEN   4 THEN 'Every ' + CONVERT(VARCHAR, [schedule].[freq_interval]) + ' day(s)'
					WHEN   8 THEN 'Every ' + CONVERT(VARCHAR, [schedule].[freq_recurrence_factor]) + ' weeks(s) on ' + 
						LEFT(
							CASE WHEN [schedule].[freq_interval] &  1 =  1 THEN 'Sunday, '    ELSE '' END + 
							CASE WHEN [schedule].[freq_interval] &  2 =  2 THEN 'Monday, '    ELSE '' END + 
							CASE WHEN [schedule].[freq_interval] &  4 =  4 THEN 'Tuesday, '   ELSE '' END + 
							CASE WHEN [schedule].[freq_interval] &  8 =  8 THEN 'Wednesday, ' ELSE '' END + 
							CASE WHEN [schedule].[freq_interval] & 16 = 16 THEN 'Thursday, '  ELSE '' END + 
							CASE WHEN [schedule].[freq_interval] & 32 = 32 THEN 'Friday, '    ELSE '' END + 
							CASE WHEN [schedule].[freq_interval] & 64 = 64 THEN 'Saturday, '  ELSE '' END , 
							LEN(
								CASE WHEN [schedule].[freq_interval] &  1 =  1 THEN 'Sunday, '    ELSE '' END + 
								CASE WHEN [schedule].[freq_interval] &  2 =  2 THEN 'Monday, '    ELSE '' END + 
								CASE WHEN [schedule].[freq_interval] &  4 =  4 THEN 'Tuesday, '   ELSE '' END + 
								CASE WHEN [schedule].[freq_interval] &  8 =  8 THEN 'Wednesday, ' ELSE '' END + 
								CASE WHEN [schedule].[freq_interval] & 16 = 16 THEN 'Thursday, '  ELSE '' END + 
								CASE WHEN [schedule].[freq_interval] & 32 = 32 THEN 'Friday, '    ELSE '' END + 
								CASE WHEN [schedule].[freq_interval] & 64 = 64 THEN 'Saturday, '  ELSE '' END 
							) - 1
						)
					WHEN  16 THEN 'Day ' + CONVERT(VARCHAR, [schedule].[freq_interval]) + ' of every ' + CONVERT(VARCHAR, [schedule].[freq_recurrence_factor]) + ' month(s)'
					WHEN  32 THEN 'The ' + 
							CASE [schedule].[freq_relative_interval]
								WHEN  1 THEN 'First'
								WHEN  2 THEN 'Second'
								WHEN  4 THEN 'Third'
								WHEN  8 THEN 'Fourth'
								WHEN 16 THEN 'Last' 
							END +
							CASE [schedule].[freq_interval]
								WHEN  1 THEN ' Sunday'
								WHEN  2 THEN ' Monday'
								WHEN  3 THEN ' Tuesday'
								WHEN  4 THEN ' Wednesday'
								WHEN  5 THEN ' Thursday'
								WHEN  6 THEN ' Friday'
								WHEN  7 THEN ' Saturday'
								WHEN  8 THEN ' Day'
								WHEN  9 THEN ' Weekday'
								WHEN 10 THEN ' Weekend Day' 
							END + ' of every ' + CONVERT(VARCHAR, [schedule].[freq_recurrence_factor]) + ' month(s)' 
					ELSE ''
				END
		,[Frequency] = 
				CASE [schedule].[freq_subday_type]
					WHEN 1 THEN 'Occurs once at ' + 
								STUFF(STUFF(RIGHT('000000' + CONVERT(VARCHAR(8), [schedule].[active_start_time]), 6), 5, 0, ':'), 3, 0, ':')
					WHEN 2 THEN 'Occurs every ' + 
								CONVERT(VARCHAR, [schedule].[freq_subday_interval]) + ' Seconds(s) between ' + 
								STUFF(STUFF(RIGHT('000000' + CONVERT(VARCHAR(8), [schedule].[active_start_time]), 6), 5, 0, ':'), 3, 0, ':') + ' and ' + 
								STUFF(STUFF(RIGHT('000000' + CONVERT(VARCHAR(8), [schedule].[active_end_time]), 6), 5, 0, ':'), 3, 0, ':')
					WHEN 4 THEN 'Occurs every ' + 
								CONVERT(VARCHAR, [schedule].[freq_subday_interval]) + ' Minute(s) between ' + 
								STUFF(STUFF(RIGHT('000000' + CONVERT(VARCHAR(8), [schedule].[active_start_time]), 6), 5, 0, ':'), 3, 0, ':') + ' and ' + 
								STUFF(STUFF(RIGHT('000000' + CONVERT(VARCHAR(8), [schedule].[active_end_time]), 6), 5, 0, ':'), 3, 0, ':')
					WHEN 8 THEN 'Occurs every ' + 
								CONVERT(VARCHAR, [schedule].[freq_subday_interval]) + ' Hour(s) between ' + 
								STUFF(STUFF(RIGHT('000000' + CONVERT(VARCHAR(8), [schedule].[active_start_time]), 6), 5, 0, ':'), 3, 0, ':') + ' and ' + 
								STUFF(STUFF(RIGHT('000000' + CONVERT(VARCHAR(8), [schedule].[active_end_time]), 6), 5, 0, ':'), 3, 0, ':')
					ELSE ''
				END
		,[AvgDurationInSec] = CONVERT(DECIMAL(10, 2), [jobhistory].[AvgDuration])
		,[Next_Run_Date] = 
				CASE [jobschedule].[next_run_date]
					WHEN 0 THEN CONVERT(DATETIME, '1900/1/1')
					ELSE CONVERT(DATETIME, CONVERT(CHAR(8), [jobschedule].[next_run_date], 112) + ' ' + 
						 STUFF(STUFF(RIGHT('000000' + CONVERT(VARCHAR(8), [jobschedule].[next_run_time]), 6), 5, 0, ':'), 3, 0, ':'))
				END
FROM	 [msdb].[dbo].[sysjobs] AS [jobs] WITh(NOLOCK) 
		 LEFT OUTER JOIN [msdb].[dbo].[sysjobschedules] AS [jobschedule] WITh(NOLOCK) 
				 ON [jobs].[job_id] = [jobschedule].[job_id] 
		 LEFT OUTER JOIN [msdb].[dbo].[sysschedules] AS [schedule] WITh(NOLOCK) 
				 ON [jobschedule].[schedule_id] = [schedule].[schedule_id] 
		 INNER JOIN [msdb].[dbo].[syscategories] [categories] WITh(NOLOCK) 
				 ON [jobs].[category_id] = [categories].[category_id] 
		 LEFT OUTER JOIN 
					(	SELECT	 [job_id], [AvgDuration] = (SUM((([run_duration] / 10000 * 3600) + 
																(([run_duration] % 10000) / 100 * 60) + 
																 ([run_duration] % 10000) % 100)) * 1.0) / COUNT([job_id])
						FROM	 [msdb].[dbo].[sysjobhistory] WITh(NOLOCK)
						WHERE	 [step_id] = 0 
						GROUP BY [job_id]
					 ) AS [jobhistory] 
				 ON [jobhistory].[job_id] = [jobs].[job_id];


--Existing linked server listing


print N'Linked Server Information';


declare @x int;
select @x = COUNT(name) 
from sys.all_objects
where name = 'Servers';
if @x <> 0
SELECT * 
--c.name, provider, data_source, is_remote_login_enabled, b.modify_date
FROM sys.Servers a
LEFT OUTER JOIN sys.linked_logins b ON b.server_id = a.server_id
LEFT OUTER JOIN sys.server_principals c ON c.principal_id = b.local_principal_id
where a.server_id <> 0;
else
exec sp_linkedservers;


Script review

script-review-blog

I have written dozens of scripts over the years and some of my favorites have been ones I created to reverse-engineer various database objects such as indexes and packages.  These scripts proved useful during difficult database migrations or when source code was needed to troubleshoot performance problems.

As Oracle tools and features have improved, I have used these scripts less and less, but every once in awhile, there is a situation when I have to reach back and put them to use once more.  Sometimes, though, they don’t work that well on newer versions of the Oracle database.  I then have to rework them to bring them up to speed.

One of these scripts is the one I use to reverse-engineer packages.  Originally, I used a temp table and output from dba_source to get the desired output.  Later on, I reworked this script to utilize the dbms_metadata.get_ddl function to get my output.  Last week, I noticed that this script wasn’t giving me the output I needed, so it was back to the drawing board.

When I first started using the dbms_metadata.get_ddl function, I was using a variable with a LONG datatype to store the returned value, then parsing the variable’s contents line-by-line.  It turns out that the actual datatype returned from that function is a CLOB.  I can only guess in my earlier version of my script that there was an implicit conversion happening.  My latest reworking of my package reverse-engineer script does a better job of converting CLOB data into something readable.  Since it uses the dbms_metadata.get_ddl function to return the desired object’s code, this script can be reworked to reverse-engineer other database objects such as indexes, tables, and procedures.  You can refer to the Oracle documentation on the dbms_metadata package to get more detail on the kinds of objects supported.

Keep in mind the number of objects you are trying to reverse-engineer.  In database environments with thousands of packages and procedures, such as EBS, it would be better to narrow the scope of the driving query.

————————————————————————————————————————–

–package_code_regenerate.sql
–Substitute the owner for a different schema or remove the where clause
–for the current schema

set pagesize 9999
set linesize 200
set wrap on

set serveroutput on size unlimited;
spool ./pg.out
declare
c clob;
——————————-
procedure printout
(p_clob in out nocopy clob) is
offset number := 1;
amount number := 32767;
len    number := dbms_lob.getlength(p_clob);
lc_buffer varchar2(32767);
i pls_integer := 1;
begin
if ( dbms_lob.isopen(p_clob) != 1 ) then
dbms_lob.open(p_clob, 0);
end if;
while ( offset < len )
loop
— If no more newlines are found, read till end of CLOB
if (instr(p_clob, chr(10), offset) = 0) then
amount := len – offset + 1;
else
amount := instr(p_clob, chr(10), offset) – offset;
end if;

— This is to catch empty lines, otherwise we get a NULL error
if ( amount = 0 ) then
lc_buffer := ”;
else
dbms_lob.read(p_clob, amount, offset, lc_buffer);
end if;
–dbms_output.put_line(‘Line #’||i||’:’||lc_buffer);
dbms_output.put_line(lc_buffer);
— This is to catch a newline on the last line with 0 characters behind it
i := i + 1;
if (instr(p_clob, chr(10), offset) = len) then
lc_buffer := ”;
–dbms_output.put_line(‘Line #’||i||’:’||lc_buffer);
dbms_output.put_line(lc_buffer);
end if;

offset := offset + amount + 1;
end loop;
if ( dbms_lob.isopen(p_clob) = 1 ) then
dbms_lob.close(p_clob);
end if;
exception
when others then
dbms_output.put_line(‘Error : ‘||sqlerrm);
end printout;
—————————
begin  –This is the driving query of the script
for x in (select owner, object_name
from dba_objects
where owner not like ‘%SYS%’
and object_type = ‘PACKAGE’)
loop
SELECT DBMS_METADATA.GET_DDL(‘PACKAGE’, x.object_name, x.owner) into c
FROM dual;
dbms_output.put_line(‘———–‘);
printout(c);
dbms_output.put_line(‘/’);
dbms_output.put_line(chr(10));
end loop;
end;
/

spool off

————————————————————————————————————————–

Working with Oracle external tables in a nutshell

It’s easy to create data sets using a text editor or a spreadsheet utility. With the latest version of these utilities, you can even make them up to a million rows. Once the data is created, it needs to be loaded into a database table or tables so that is can be utilized. Oracle has a couple of utilities for loading data from flat file – SQL Loader and external tables. SQL Loader can be a bit complicated to work with, so I prefer external tables for quickly loading data from flat files. Here’s a quick method I recently used.

I created a .csv file with 1048576 rows and 25 columns.  Here is the first comma-delimited record.  You can copy and paste it into a spreadsheet or a text file over and over, creating as any records as you like:

123456,This is a test,3.14,14-Dec-14,http://www.msn.com/en-us/autos/classic-cars/the-derelict-1952-chrysler-town-and-country-beauty-in-the-beast/ar-BBt2Y1e,123456,This is a test,3.14,14-Dec-14,http://www.msn.com/en-us/autos/classic-cars/the-derelict-1952-chrysler-town-and-country-beauty-in-the-beast/ar-BBt2Y1e,123456,This is a test,3.14,14-Dec-14,http://www.msn.com/en-us/autos/classic-cars/the-derelict-1952-chrysler-town-and-country-beauty-in-the-beast/ar-BBt2Y1e,123456,This is a test,3.14,14-Dec-14,http://www.msn.com/en-us/autos/classic-cars/the-derelict-1952-chrysler-town-and-country-beauty-in-the-beast/ar-BBt2Y1e

This is the table I created to hold the data in the Oracle 11.2.0.1 database (please excuse the lack of creative column names):

create table jontest.jontab(
 ID1              number,
 LABEL1     varchar2(15),
 PI1              number,
 DATE1       date,
 URL1          varchar2(500),
 ID2             number,
 LABEL2     varchar2(15),
 PI2             number,
 DATE2      date,
 URL2         varchar2(500),
 ID3            number,
 LABEL3    varchar2(15),
 PI3             number,
 DATE3      date,
 URL3         varchar2(500),
 ID4             number,
 LABEL4    varchar2(15),
 PI4             number,
 DATE4      date,
 URL4        varchar2(500),
 ID5            number,
 LABEL5   varchar2(15),
 PI5            number,
 DATE5     date,
 URL5       varchar2(500)
 );

Now that the target has been created, we need to set up the system for the external table process.  We need to create a directory object in the database using a directory where the oracle software account has read and write access:

create directory impdir as ‘/home/oracle’;

Make sure the table owner has read and write permission on this directory object:

grant read, write on directory impdir to jontest;

Place the input .csv file (called ironically input.csv) in the directory object location and ensure the ownership and permissions on the file are appropriate.

Next, create the external table to access the input file.  An external table is not actually a physical table in the database, but more like a view that allows access to the data in the file.  Note that this table was created as the ‘jontest’ user.

 

CREATE TABLE extload
 (
 ID1              char(6),
 LABEL1     char(15),
 PI1               char(4),
 DATE1        date,
 URL1          char(500),
 ID2             char(6),
 LABEL2     char(15),
 PI2              char(4),
 DATE2       date,
 URL2         char(500),
 ID3             char(6),
 LABEL3    char(15),
 PI3             char(4),
 DATE3      date,
 URL3         char(500),
 ID4            char(6),
 LABEL4   char(15),
 PI4            char(4),
 DATE4     date,
 URL4       char(500),
 ID5           char(6),
 LABEL5   char(15),
 PI5            char(4),
 DATE5     date,
 URL5       char(500)
 )
 ORGANIZATION EXTERNAL (
 TYPE ORACLE_LOADER
 DEFAULT DIRECTORY impdir
 ACCESS PARAMETERS (
 RECORDS DELIMITED BY NEWLINE
 FIELDS TERMINATED BY ‘,’
 MISSING FIELD VALUES ARE NULL
 (
 ID1              char(6),
 LABEL1     char(15),
 PI1              char(4),
 DATE1       char(10) date_format DATE mask “DD-MON-YY”,
 URL1         char(500),
 ID2            char(6),
 LABEL2    char(15),
 PI2             char(4),
 DATE2      char(10) date_format DATE mask “DD-MON-YY”,
 URL2        char(500),
 ID3            char(6),
 LABEL3   char(15),
 PI3           char(4),
 DATE3     char(10) date_format DATE mask “DD-MON-YY”,
 URL3       char(500),
 ID4          char(6),
 LABEL4  char(15),
 PI4           char(4),
 DATE4    char(10) date_format DATE mask “DD-MON-YY”,
 URL4      char(500),
 ID5          char(6),
 LABEL5  char(15),
 PI5           char(4),
 DATE5    char(10) date_format DATE mask “DD-MON-YY”,
 URL5      char(500)
 )
 )
 LOCATION (‘input.csv’)
 ) reject limit unlimited;

I used the same column names as my target table, again lacking any creativity in this area.  Notice that the column data types are either ‘char’ or ‘date’.  This just makes thing easier and the data can be transformed during the loading into the target table, as I will demonstrate.  You can already see in the second listing of the columns in this table that I am already formatting the date columns.

If the creation is successful, you should be able to perform a count on the number of records in the table, or select one of the column values.  If the count or select comes back with no records or errors, check the directory object location for .bad or .log files with the table name as the prefix of the file name.  These files are created by default even though we did not specify them in the external table creation statement.

Once you can select from the external table, you can treat it like any other read-only table.  We can now perform any data conversion while we load our target table.

insert into jontest.jontab
 select
 to_number(ID1,999999),
 LABEL1,
 to_number(PI1,9.99),
 to_date(DATE1,’DD-MON-YY’),
 URL1,
 to_number(ID2,999999),
 LABEL2,
 to_number(PI2,9.99),
 to_date(DATE2,’DD-MON-YY’),
 URL2,
 to_number(ID3,999999),
 LABEL3,
 to_number(PI3,9.99),
 to_date(DATE3,’DD-MON-YY’),
 URL3,
 to_number(ID4,999999),
 LABEL4,
 to_number(PI4,9.99),
 to_date(DATE4,’DD-MON-YY’),
 URL4,
 to_number(ID5,999999),
 LABEL5,
 to_number(PI5,9.99),
 to_date(DATE5,’DD-MON-YY’),
 URL5
 from jontest.extload;

 

 

PL/SQL function result caching for better performance

Result caching has been around since Oracle database 11g release 1, but it was only recently that I was introduced to its full benefits in PL/SQL functions.  I was at a client site last month looking at a very poorly-written query that included millions of calls to PL/SQL functions, one for every row queried. The query had a ton of optimizer hints and still took hours to execute.

A colleague of mine at the Accenture Enkitec Group who is an Oracle developer by trade put forth that enabling result caching in the PL/SQL functions called could make a big difference in query performance without changing the actual query.  I had heard of result caching when querying tables, but had not used it before nor its PL/SQL function variation.  After enabling the result caching in the functions called by the previously-mentioned query, performance was dramatically increased.  I am now a believer and I want to make you one as well.

I set up a simple demonstration on a 11g release 1 database.  Here is my test table:

SQL> desc jontab
 Name                                      Null?    Type
 —————————————– ——– —————————-
 ID1                                                NUMBER
 LABEL1                                             VARCHAR2(15)
 PI1                                                NUMBER
 DATE1                                              DATE
 URL1                                               VARCHAR2(500)
 ID2                                                NUMBER
 LABEL2                                             VARCHAR2(15)
 PI2                                                NUMBER
 DATE2                                              DATE
 URL2                                               VARCHAR2(500)
 ID3                                                NUMBER
 LABEL3                                             VARCHAR2(15)
 PI3                                                NUMBER
 DATE3                                              DATE
 URL3                                               VARCHAR2(500)
 ID4                                                NUMBER
 LABEL4                                             VARCHAR2(15)
 PI4                                                NUMBER
 DATE4                                              DATE
 URL4                                               VARCHAR2(500)
 ID5                                                NUMBER
 LABEL5                                             VARCHAR2(15)
 PI5                                                NUMBER
 DATE5                                              DATE
 URL5                                               VARCHAR2(500)
SQL> select count(*)
 2  from jontab;

COUNT(*)
 ———-
 1048576

Now a simple PL/SQL function for testing:

create or replace FUNCTION jonfunc (employee_id_in IN number)
 RETURN number
 AS
 v_empno number;
 BEGIN
 SELECT empno
 INTO v_empno
 FROM scott.emp
 WHERE empno = employee_id_in;
 RETURN v_empno;
 EXCEPTION
 WHEN NO_DATA_FOUND
 THEN
 /* Return an empty record. */
 RETURN 0;
 END jonfunc;
 /

I compared the data in the scott.emp table with the column data I planned to use in my test table and the function will NEVER return a value other than zero.

Now I need to run a test query and trace it.  I use the level 12 of the 10046 event in order to get the most complete information I can.  The tracefile_identifier is just to make identifying the trace file easier:

alter session set statistics_level=ALL;
 alter session set tracefile_identifier = ‘jon_trace’;
 alter session set events = ‘10046 TRACE NAME CONTEXT FOREVER, LEVEL 12’;

select id1, jonfunc(id1)
 from jontab;

alter session set events = ‘10046 TRACE NAME CONTEXT OFF’;

I then processed the trace file using tkprof, sorting it by query execution time in descending order:

tkprof jon11g_ora_3308_jon_trace.trc output.log sort=EXEELA,FCHELA

Here is the particular session regarding the calls to our test function:

SQL ID: 5r2ba62345bqa
 Plan Hash: 56244932
 SELECT EMPNO
 FROM
 SCOTT.EMP WHERE EMPNO = :B1
call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        0      0.00       0.00          0          0          0           0
Execute 1048572     56.97      72.48          0          0          0           0
Fetch   1048572      4.26       6.56          0    1048572          0           0
——- ——  ——– ———- ———- ———- ———-  ———-
total   2097144     61.23      79.05          0    1048572          0           0

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 92     (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
—————————————-   Waited  ———-  ————
SQL*Net message to client                       1        0.00          0.00
SQL*Net message from client                     1       14.47         14.47
latch: shared pool                             51        0.00          0.03
********************************************************************************

There were 1048572 calls to this function taking a total elapsed time of 79 seconds.  Let’s enable result caching in the test function:

create or replace FUNCTION jonfunc (employee_id_in IN number)
 RETURN number
 RESULT_CACHE  --enabling result caching
 AS
 v_empno number;
 BEGIN
 SELECT empno
 INTO v_empno
 FROM scott.emp
 WHERE empno = employee_id_in;
 RETURN v_empno;
 EXCEPTION
 WHEN NO_DATA_FOUND
 THEN
 /* Return an empty record. */
 RETURN 0;
 END jonfunc;
 /

After rerunning the test query and processing the resulting trace file:

SQL ID: 5r2ba62345bqa
Plan Hash: 56244932
SELECT EMPNO
FROM
SCOTT.EMP WHERE EMPNO = :B1

call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00       0.00          0          1          0           0
——- ——  ——– ———- ———- ———- ———-  ———-
total        3      0.00       0.00          0          1          0           0

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 92     (recursive depth: 1)

Rows     Row Source Operation
——-  —————————————————
0  INDEX UNIQUE SCAN PK_EMP (cr=1 pr=0 pw=0 time=0 us cost=0 size=4 card=1)(object id 73202)

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

There was now only one execution of this function which resulted in sub-second performance removing the entire 79 seconds from the previous execution.  It used the result cache exclusively after the first execution since it returned the same value for all subsequent calls.

There is also an option for the result caching enabling that can be used to invalidate the cache whenever a change occurs in the underlying table.  After the result cache is invalidated (cleared), the next call causes an actual execution to create the cache once more.  The option could have been used in the test function with this modified line:

RESULT_CACHE relies on(emp);

I hope that this simple demonstration has convinced you of the usefulness of this option.

Update:

In Oracle version 11g, both release 1 and 2, you cannot enable result caching in a function with invoker rights (i.e. AUTHID CURRENT_USER clause).  If you do, you will receive the following error during compilation:

PLS-00999: implementation restriction 
(may be temporary) RESULT_CACHE is 
disallowed on subprograms in 
Invoker-Rights modules

This limitation is fixed in Oracle version 12c.  As a work around, you can place the ivoker rights in a package or procedure that calls the function with result caching enabled.

 

Working with Oracle trace files

magnifying glassBeing a contractor sometimes means working with clients in situations where you can’t access their databases and servers directly. Fortunately Oracle has utilities such as AWR and scripts like SQLTXPLAIN to help diagnose the system in your absence. If you are very fortunate, you may even get them to execute eDB360 for you.

However, if you really want to know where the database is spending all of its time, nothing beats a good old-fashioned trace. Trace (.trc) files are the ever-present files in the Oracle diagnostic destination that can tell you what processes are doing and how long they are doing it for. Most ignore these files and even delete them when they build up on the database server, but you can’t beat them for their wealth of information.  If I can’t touch a client’s system, the first thing I ask for is a trace of the session executing the problem code.   If they are unfamiliar with the tracing process, I offer to run it for them.

Creating a trace file

For a proper trace complete with timing information, the statistics_level parameter needs to be set to ALL. Fortunately, if it is not set at the system level, it can be set at the session level.

alter session set statistics_level=ALL;

To make identifying the trace file easier, you can set a trace file identifier at the session level. This identifier will become part of the name(s) of the trace file(s) generated:

alter session set tracefile_identifier = ‘my_trace_id’;

Tracing a session is simple, even if that session is not yours. To trace your own session, you can use any of these commands:

alter session set sql_trace=TRUE;
exec dbms_monitor.session_trace_enable;
exec dbms_support.start_trace;
alter session set events = ‘10046 TRACE NAME CONTEXT FOREVER, LEVEL 12’;

The last command provides the most detailed tracing with a maximum level setting of 12. Lower settings are also available, but I would not recommend a lower setting than 8.

If you need to trace a session other than your own, you just need the sid and serial number of the session.  You start tracing on the current session with any of this commands:

execute dbms_monitor.session_trace_enable(sid,serial#,TRUE, TRUE); (The last two arguments are to enable reporting on WAITS and BIND variables)

If this is a client server environment and there are several sessions connected with the same database account and you are not sure which one will handle the code execution, you can generate dynamic statements to trace them all:

set lines 200 pages 999
select ‘execute dbms_monitor.session_trace_enable(‘||sid||’,’||serial#||’,TRUE,TRUE);’
from v$session
where username = ‘SCOTT’
order by sid;

When the process or code you are tracing has completed, stop the tracing in the current session with any of these commands:

alter session set sql_trace = false;
exec dbms_monitor.session_trace_disable;
exec dbms_support.stop_trace;
alter session set events = ‘10046 TRACE NAME CONTEXT OFF’;

Or you can use this command if the session is not the current one (based on the earlier sid and serial number values):

exec dbms_monitor.session_trace_disable(sid, serial#);

If you were tracing multiple sessions, use this code to generate the stop tracing commands:

set lines 200 pages 999
select ‘execute dbms_monitor.session_trace_disable(‘||sid||’,’||serial#||’);’
from v$session
where username = ‘SCOTT’
order by sid;

Locating and processing a trace file

The trace file location on the database server is designated by the diagnostic_dest parameter (11g and above). From there, go to the rdbms\<sid>\<instance>\trace directory to see the actual trace files. In a pre-11g system, just go to the location designated by the parameter user_dump_dest. Use a list command with a sort such as ‘ls -lart’ to see the latest trace files. The trace files end in the .trc extension. The one(s) you are interested in should be the latest and probably largest of the trace files and you can usually see them dynamically grow as the code executes. Of course, if you set a trace file identifier, the file will be even easier to find.

Processing a trace file

Looking at a raw trace is a bit confusing and takes some experience to decipher. You can use the TKPROF utility to process it into something a little more readable. I recommend using the EXEELA and FCHELA options during the process to sort the SQL code in order of elapsed time and fetches descending. That way, the SQL taking the longest time will be at the top for easy access. Here is an example of the command to create this output:

tkprof <raw_trace_file.trc> <processed_file.log> sort=EXEELA,FCHELA

You can use any extension for the output file, but it is best to use one that is not foreign to the editor you are going to use to open the resulting file.

Reviewing a trace file

Opening the file, go straight to the bottom section that starts with ‘OVERALL TOTALS’. If you are unfamiliar with looking at trace file output, spend a minute reviewing the legend at the top of the file:

Trace file: dummy_ora_1369.trc
Sort options: exeela fchela
********************************************************************************
count = number of times OCI procedure was executed
cpu = cpu time in seconds executing
elapsed = elapsed time in seconds executing
disk = number of physical reads of buffers from disk
query = number of buffers gotten for consistent read
current = number of buffers gotten in current mode (usually for update)
rows = number of rows processed by the fetch or execute call
********************************************************************************

Then proceed to the bottom:

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute 209486    822.98     823.79       2526      33961    1607238      209486
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   209486    822.98     823.79       2526      33961    1607238      209486

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
log file sync                              154081        6.41      19315.04
SQL*Net message to client                  314407        0.00          1.51
SQL*Net message from client                314407        0.02         59.12
Disk file operations I/O                       22        0.00          0.00
db file sequential read                      2526        0.02          0.37
library cache: mutex X                        154        0.00          0.00
log buffer space                                8        0.17          0.96
buffer busy waits                               2        0.10          0.10
latch: In memory undo latch                     5        0.00          0.00
latch: shared pool                              3        0.00          0.00
undo segment extension                          1        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   628459     13.06      13.03          0          0          0           0
Execute 1256917    598.32     611.29       1889     425754     653042      418972
Fetch   418973     10.35      10.45          1          4          0      418973
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   2304349    621.73     634.78       1890     425758     653042      837945

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
Disk file operations I/O                       23        0.00          0.00
db file sequential read                      1890        0.04          0.30
log buffer space                               22        0.63          3.65
log file switch (private strand flush incomplete)
12        1.56          7.50
cursor: pin S                                   1        0.00          0.00
buffer busy waits                               1        0.00          0.00
latch: In memory undo latch                     2        0.00          0.00
latch free                                      3        0.00          0.00
resmgr:cpu quantum                             36        0.06          0.29
log file switch completion                      1        1.57          1.57

418978  user  SQL statements in session.
2  internal SQL statements in session.
418980  SQL statements in session.
6  statements EXPLAINed in this session.
********************************************************************************
Trace file: dummy_ora_1369.trc
Trace file compatibility: 11.1.0.7
Sort options: exeela  fchela
1  session in tracefile.
418978  user  SQL statements in trace file.
2  internal SQL statements in trace file.
418980  SQL statements in trace file.
23  unique SQL statements in trace file.
6  SQL statements EXPLAINed using schema:
APPS.prof$plan_table
Default table was used.
Table was created.
Table was dropped.
36460282  lines in trace file.
20970  elapsed seconds in trace file.

There are two sections for overall totals – one for Oracle-generated non-recursive statements and one for user code known as recursive statements. At the very bottom is the number of elapsed seconds covered in the trace file. In this case, it is 20970 seconds or about 5.8 hours. Each of these sections has a total elapsed time and wait events information. The first thing to notice is that the total for the non-recursive statements is 823.79 seconds and the total for the recursive statements is 634.78. The sum of these two values is drastically short of the 20,970 grand total. Where did the other time go? Now start looking at the wait events under each section and stop when you get to the event that has a total time waited of 19315.04. To put this in perspective, a total of 1458.57 seconds (823.79 + 634.78) or 24 minutes was spent during the trace time on actual database work and 19315.04 seconds or 5.3 hours was spent doing log file syncs. Now we can start looking for the sources of all these log file sync waits. Since this output file is already sorted by elapsed time descending, we just start at the top:

SQL ID: 9dtjfluf6rcct Plan Hash: 2730624675

INSERT INTO "BAD"."SIMP_STG" (REC_ID,INSTANCE_ID,
ORIGINAL_ID,REPROCESS_ID,TRANSACTION_ID,REPROCESS_CNT)
VALUES
(SIMP_STG_S.nextval, :INSTANCE_ID, :ORIGINAL_BPEL_ID,
:REPROCESS_BPEL_ID, :TRANSACTION_ID, :REPROCESS_COUNTER)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute 104743    462.81     463.34       1414      18029     752169      104743
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   104743    462.81     463.34       1414      18029     752169      104743

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 44  (APPS)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
0          0          0  LOAD TABLE CONVENTIONAL  (cr=2 pr=0 pw=0 time=5657 us)
1          1          1   SEQUENCE  SIMP_STG_S (cr=2 pr=0 pw=0 time=2488 us)

Rows     Execution Plan
-------  ---------------------------------------------------
0  INSERT STATEMENT   MODE: ALL_ROWS
0   LOAD TABLE CONVENTIONAL OF 'SIMP_STG'
1    SEQUENCE OF 'SIMP_STG_S' (SEQUENCE)

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
log file sync                               49337        6.41       9105.43
SQL*Net message to client                  104743        0.00          0.51
SQL*Net message from client                104743        0.02         17.95
db file sequential read                      1414        0.01          0.17
library cache: mutex X                         61        0.00          0.00
Disk file operations I/O                       16        0.00          0.00
log buffer space                                1        0.17          0.17
buffer busy waits                               2        0.10          0.10
latch: In memory undo latch                     2        0.00          0.00
latch: shared pool                              1        0.00          0.00
undo segment extension                          1        0.00          0.00
********************************************************************************

This first statement looks like it accounts for about half of the log file sync waits. This insert statement uses a sequence to generate a unique ID for every one of the 104,743 rows inserted. A review of this sequence revealed that it had the default cache setting of 20. Any sequence that is called thousands of times during the course of one process needs a cache value that will drastically reduce the number of times it actually needs to generate a value. A cache value of 10000 or more would be needed here so that every time the sequence is called, the next 10000 numbers of the sequence are cached in memory, speeding up the obtaining of the sequence values. Once these cached values are exhausted, only then is the sequence physically called again.

Sequence caching removed about 9000 log file sync waits, but a review of the rest of the output revealed no more log file sync waits in any of the other statements. Where were the other 10000 waits? One of the problems with TKPROF is that it does not report on commits and rollbacks that are recorded in the trace file. It just so happens that one source of log file sync waits is excessive commits. The process generating these insert statements was a SQL Loader process that had options(rows=1) in the control file. It was performing a commit for every row inserted. Removing this clause and switching from conventional path to direct path loading removed the remaining log file sync waits.

Sometimes the cause of a problem is not always readily apparent. Take this statement for example:

SQL ID: 1b8xbxk8jc712 Plan Hash: 2504779452
SELECT L.JON
FROM
SIMP_HDR_STG H, SIMP_LINES_STG L WHERE
L.RECORD_HEADER_ID = H.RECORD_HEADER_ID AND H.INSTANCE_ID = :B1 AND ROWNUM = 1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute     12      0.00       0.00          0          0          0           0
Fetch       12     81.56      81.56          0   26025612          0          12
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       25     81.56      81.56          0   26025612          0          12

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 44     (recursive depth: 2)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
1          1          1  COUNT STOPKEY (cr=2168801 pr=0 pw=0 time=6878671 us)
1          1          1   NESTED LOOPS  (cr=2168801 pr=0 pw=0 time=6878653 us cost=9 size=126 card=7)
1072923    1072923    1072923    NESTED LOOPS  (cr=1095878 pr=0 pw=0 time=4041943 us cost=9 size=126 card=7)
1072923    1072923    1072923     TABLE ACCESS FULL SIMP_LINES_STG (cr=23852 pr=0 pw=0 time=535161 us cost=2 size=49 card=7)
1072923    1072923    1072923     INDEX UNIQUE SCAN SIMP_HDR_STG_PK (cr=1072026 pr=0 pw=0 time=2585580 us cost=0 size=0 card=1)(object id 3379354)
1          1          1    TABLE ACCESS BY INDEX ROWID SIMP_HDR_STG (cr=1072923 pr=0 pw=0 time=2309258 us cost=1 size=11 card=1)

You need to dig a little bit with this one. Execution time is 81.56 seconds for 12 executions of this statement, which is not too bad at 6.7 seconds per execution. However, 26 million consistent reads total or 2.1 million per execution for only one row per execution as a result seems excessive. Looking further into the details, there are more scans of the primary key index of the header table than are performed in a full table scan of the lines table. If you assume a one to many relationship between the header and lines tables, then you should be doing fewer scans on the headers table than the lines table. This may be a simple case of having the wrong table driving the query.

Finally, there are times when you see things in the TKPROF output that just make you shake your head:

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
db file sequential read                         1        0.00          0.00
utl_file I/O                                61671        0.00          1.12
PL/SQL lock timer                            2373       10.09      23731.10

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   314346      6.04       6.46          0          0         10           0
Execute 588073    667.85     678.04      35191    4498924     293728       50209
Fetch   496358    102.61     105.00       1768    5489750       6015      492324
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   1398777    776.51     789.51      36959    9988674     299753      542533

Misses in library cache during parse: 346
Misses in library cache during execute: 1331

Elapsed times include waiting on following events:
Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
db file sequential read                      7713        0.06         10.85
Disk file operations I/O                       93        0.00          0.00
db file scattered read                       2067        0.07          2.26
enq: TM - contention                            9        0.17          0.96
latch: cache buffers chains                     1        0.00          0.00
latch: In memory undo latch                     1        0.00          0.00

24039  user  SQL statements in session.
138  internal SQL statements in session.
24177  SQL statements in session.
********************************************************************************
Trace file: DUMMY_ora_22860.trc
Trace file compatibility: 11.1.0.7
Sort options: exeela  fchela
1  session in tracefile.
24039  user  SQL statements in trace file.
138  internal SQL statements in trace file.
24177  SQL statements in trace file.
357  unique SQL statements in trace file.
14449283  lines in trace file.
29448  elapsed seconds in trace file.
 

This is only the bottom portion of a TKPROF output file, but what is interesting here is the presence of the PL/SQL lock timer waits under the non-recursive section. The only cause of these waits are calls to the dbms_lock.sleep procedure. To summarize, there are 29448 total seconds in this TKPROF output and 23731 seconds or 80% of the total time is taken up by code forcing the database to do nothing or “sleep”.

I hope you find this as useful as I did when it was first revealed to me. There is a wealth of information that the Oracle database provides automatically. Sometimes we have to put on our Indiana Jones hats to dig it up.

Update 1/10/2017

I recently had a situation where I was only given a raw trace file with no means to process it through TKPROF.  I this situation, I only had a restricted access virtual machine (VM) with which to investigate its contents.

Knowing that I could install basic tools on this VM, I installed Cygwin64 Terminal (cygwin.com) which is a set of Unix-like tools for Windows environments.  After installation, I was able to use the following commands to help me process the wait events out of the trace file.

(Tested on Oracle version 11.2.0.4.0)

Use this command to group waits in a raw trace file:

cat PROD1_ora_24787.trc | grep WAIT | awk -F”ela=”‘{a[$3];}END{for (i in a)print i;}’

cat PROD1_ora_24787.trc | grep WAIT | awk ‘{a[$3″ “$4” “$5];}END{for (i in a)print i;}’

Note – Since the fields of a wait category are often separated by spaces, it may be
necessary to grab multiple fields ($3, $4, $5) to get the entire wait event name

To count the number of waits per category;
cat PROD1_ora_24787.trc | grep WAIT | awk ‘{a[$3]++;}END{for (i in a)print i, a[i];}’

To summarize elapsed microseconds for a particular wait:
cat PROD1_ora_24787.trc | grep WAIT | grep ‘utl_file I/O’ | awk ‘{sum += $6}END{print sum}’

The above command will summarize all the ‘utl_file I/O’ waits in the example trace file.
Note that the value will be give in microseconds and should be multiplied by .000001 to
produce the summarized value in seconds.