Tracefile automation – simplify your troubleshooting tasks

Posted in: DBA Lounge, Oracle

Here’s a common Oracle troubleshooting scenario when a SQL statement needs tuning and/or troubleshooting:

  • log on to dev server
  • connect to database (on a different server)
  • run the SQL statement with 10046 tracing enabled
  • ssh to the database server
  • copy the trace file back to work environment
  • process the trace file.

 

All of this takes time. Granted, not a great deal of time, but tuning is an iterative process and so these steps will be performed multiple times. Not only are these steps a productivity killer, but they are repetitive and annoying. No one wants to keep running the same manual command over and over.

This task is ripe for some simple automation.

If both the client and database servers are some form of Unix, automating these tasks is straightforward.

Please note that these scripts require an 11g or later version of the Oracle database. These scripts are dependent on the v$diag_info view to retrieve the tracefile name. While these scripts could be made to work on 10g databases, that is left as an exercise for the reader.

Step by Step

To simplify the process it can be broken down into steps.

 

1. Reconnect

The first step is to create a new connection each time the SQL is executed. Doing so ensures the database session gets a new tracefile, as we want each execution to be isolated.

— reconnect.sql
connect jkstill/[email protected]

 

2. Get the Tracefile hostname, owner and filename

Oracle provides all the information needed.

In addition the script will set the 10046 event, run the SQL of interest and then disable the 10046 event.

Following is a snippet from the tracefile_identifier_demo.sql script.

 

— column variables to capture host, owner and tracefile name
col tracehost new_value tracehost noprint
col traceowner new_value traceowner noprint
col tracefile new_value tracefile noprint
set term off head off feed off
— get oracle owner
select username traceowner from v$process where pname = ‘PMON’;
— get host name
select host_name tracehost from v$instance;
— set tracefile identifier
alter session set tracefile_identifier = ‘MYTRACEFILE’;
select value tracefile from v$diag_info where name = ‘Default Trace File’;
set term on head on feed on
— do your tracing here
alter session set events ‘10046 trace name context forever, level 12’;
— run your SQL here
@@sql2trace
alter session set events ‘10046 trace name context off’;

 

In this case sql2trace.sql is a simple SELECT from a test table.  All of the scripts used here appear in Github as mentioned at the end of this article.

 

3. Process the Tracefile

Now that the tracefile has been created, it is time to retrieve it.

The following script scp.sql is called from tracefile_identifier_demo.sql.

 

col scp_src new_value scp_src noprint
col scp_target new_value scp_target noprint
set term off feed off verify off echo off
select ‘&&1’ scp_src from dual;
select ‘&&2’ scp_target from dual;
set feed on term on verify on
–disconnect
host scp &&scp_src &&scp_target

Following is an example putting it all together in tracefile_identifier_demo.sql.

 

SQL> @tracefile_identifier_demo
Connected.
1 row selected.
PRODUCT                        VERSION              STATUS
—————————— ——————– ——————–
NLSRTL                         12.1.0.2.0           Production
Oracle Database 12c Enterprise 12.1.0.2.0           64bit Production
 Edition
PL/SQL                         12.1.0.2.0           Production
TNS for Linux:                 12.1.0.2.0           Production
Data Base
——————————
P1.JKS.COM
INSTANCE_NAME        HOST_NAME                      CURRDATE
——————– —————————— ———————-
js122a1              ora12c102rac01.jks.com         2016-05-23 16:38:11
STARTUP
——————–
04/02/2016 11:22:12
Session altered.
Elapsed: 00:00:00.00
OWNER        OBJECT NAME                     OBJECT_ID OBJECT_TYPE             CREATED
———— —————————— ———- ———————– ——————-
SYS          OLAP_EXPRESSION                     18200 OPERATOR                2016-01-07 21:46:54
SYS          OLAP_EXPRESSION_BOOL                18206 OPERATOR                2016-01-07 21:46:54
SYS          OLAP_EXPRESSION_DATE                18204 OPERATOR                2016-01-07 21:46:54
SYS          OLAP_EXPRESSION_TEXT                18202 OPERATOR                2016-01-07 21:46:54
SYS          XMLSEQUENCE                          6379 OPERATOR                2016-01-07 21:41:25
SYS          XQSEQUENCE                           6380 OPERATOR                2016-01-07 21:41:25
SYS          XQWINDOWSEQUENCE                     6393 OPERATOR                2016-01-07 21:41:25
7 rows selected.
Elapsed: 00:00:00.00
Session altered.
Elapsed: 00:00:00.00
js122a1_ora_1725_MYTRACEFILE.trc                                                                                                                                                            100% 3014     2.9KB/s   00:00
SQL> host ls -l js122a1_ora_1725_MYTRACEFILE.trc
-rw-r—– 1 jkstill dba 3014 May 23 16:38 js122a1_ora_1725_MYTRACEFILE.trc

But Wait, There’s More!

This demo shows you how to automate the retrieval of the trace file. But why stop there?  The processing of the file can be modified as well.

Really, it isn’t even necessary to copy the script over, as the content can be retrieved and piped to your favorite command.  The script mrskew.sql for instance uses ssh to cat the tracefile, and then pipe the contents to the Method R utility, mrskew.  Note: mrskew is a commercial utility, not open source software.

 

— mrskew.sql
col ssh_target new_value ssh_target noprint
col scp_filename new_value scp_filename noprint
set term off feed off verify off echo off
select ‘&&1’ ssh_target from dual;
select ‘&&2’ scp_filename from dual;
set feed on term on verify on
–disconnect
host ssh &&ssh_target ‘cat &&scp_filename’ | mrskew

 

Following is another execution of tracefile_identifier_demo.sql, this time piping output to mrskew. Only the final part of the output is shown following

 

…
Elapsed: 00:00:00.01
CALL-NAME                    DURATION       %  CALLS      MEAN       MIN       MAX
—————————  ——–  ——  —–  ——–  ——–  ——–
PARSE                        0.002000   33.1%      2  0.001000  0.000000  0.002000
db file sequential read      0.001211   20.0%      5  0.000242  0.000056  0.000342
FETCH                        0.001000   16.5%      1  0.001000  0.001000  0.001000
gc cr grant 2-way            0.000999   16.5%      1  0.000999  0.000999  0.000999
SQL*Net message from client  0.000817   13.5%      2  0.000409  0.000254  0.000563
Disk file operations I/O     0.000018    0.3%      2  0.000009  0.000002  0.000016
SQL*Net message to client    0.000002    0.0%      2  0.000001  0.000001  0.000001
CLOSE                        0.000000    0.0%      2  0.000000  0.000000  0.000000
EXEC                         0.000000    0.0%      2  0.000000  0.000000  0.000000
—————————  ——–  ——  —–  ——–  ——–  ——–
TOTAL (9)                    0.006047  100.0%     19  0.000318  0.000000  0.002000

Now we can see where all the db time was consumed for this SQL statement, and there was no need to copy the trace file to the current working directory. The same can be done for tkprof and other operations.  Please see the plan.sql and tkprof.sql scripts in the Github repository.

 

Wrapping It Up

A little bit of automation goes a long way. Commands that are repetitive, boring and error prone can easily be automated.  Both your productivity and your mood will soar when little steps like these are used to improve your workflow.

All files for this demo can be found at https://github.com/jkstill/tracefile_identifier

email

Author

Want to talk with an expert? Schedule a call with our team to get the conversation started.

About the Author

Oracle experience: started with Oracle 7.0.13 Programming Experience: Perl, PL/SQL, Shell, SQL Also some other odds and ends that are no longer useful Systems: Networking, Storage, OS to varying degrees. Have fond memories of DG/UX

2 Comments. Leave new

John Hallas
May 27, 2016 7:42 am

Excellent note Jared – nicely put together

Reply
Jared Still
May 27, 2016 9:30 am

Thank you John.

Reply

Leave a Reply

Your email address will not be published. Required fields are marked *