Trace File Manager: Managing Distributed Trace Files with Oracle and PHP

This tool combines the power of PHP and the ease-of-use of PL/SQL for managing distributed trace files in a browser.
 

Downloads for this Article · Source code · Apache Version 2.0.49 or later · PHP Version 4.3.6 or later · Oracle Database Enterprise Edition Version 9.2.04 (for Windows) or Version 10.1.0.2 (for Linux) · JDK 1.4

If you're a DBA or a developer using Oracle-compliant tools, you almost certainly on occasion apply tracing to active database sessions, usually in the hunt for rogue SQL or some other coding misdemeanour.

Initiating the trace is easy and can be applied to a session using the standard dbms_system.set_sql_trace_in_session call spec or alternately by invoking the "deeper" trace utility dbms_support.start_trace_in_session, which in addition detects bind variable values and wait events.

However, getting access to the generated trace file is sometimes a little bit more difficult; you have to ensure that you have access to the USER_DUMP_DIRECTORY on the server where the database lives. When connections to the database are generally client based, this database server may not always be readily accessible. If you also want to issue a TKPROF instruction to convert your raw trace file into something more readable, you generally have to secure command line access to the database server. If you are a DBA supporting lots of different databases on lots of different servers, the job of accessing generated trace files and using TKPROF to format them becomes even more difficult.

In this article, I will describe a solution to this problem, known as the Trace File Manager (TFM), that we have developed in my own shop. Using a combination of the external calls interface available within the Oracle server to initiate TKPROF commands and the UTL_FILE utility to read in files that reside on the operating system, it can be surprisingly easy to bring your trace file data back into the database that generated the information in the first place.

Using a simple PHP front-end to make OCI calls into any or all of your databases where trace data is generated, you can easily retrieve trace files and issue TKPROF commands without the need to make direct connections to the servers where the databases reside.

Although the utility has been developed for use in the local environment here, it has been written relatively generically and should be deployable in any Windows or Unix/Linux environment without too much trouble. It has been deployed successfully here on Windows NT/Windows 2000 using Oracle 9.2.0.4 and Red Hat Enterprise Linux 3 using Oracle 10.1.0.2.

Usage

This TFM utility has three core functions:

• To display Alert, Background and User trace files from one or more databases
• To allow for archiving of Alert files and the deletion of Background and User trace files
• To provide a GUI dialogue for initiating TKPROF calls.

Deployment

For full deployment instructions, see the source code in TFMdeployment.zip. It contains all the necessary PHP, PL/SQL, Java source code, and grants and environmental settings required here; it also contains a comprehensive Readme.txt.

Security

Although this utility is designed primarily to display distributed trace files, the fact that it also offers the ability to delete unwanted files means that at least a basic degree of access control should be considered.

Consequently we have opted for a simple HTTP-server based access protection. (See this Apache tutorial.) This approach involves a htpasswd file and a .htaccess file pointing to it, enforcing all the necessary restrictions.

To avoid packet sniffing one could also further protect the installation using HTTPS or even a login component (for audit trails and so on.). However, with respect to the environment where the utility is currently deployed, simple HTTP-server based protection is sufficient.

I also recommend that you disable directory browsing on the directory where the user.conf lives, and possibly even apply a degree of operating system protection to it.

Workflow

The home page of the utility is the Targets Screen. This screen contains a list of the databases into which you have deployed the TFDADMIN (see the "Deployment" section) account and loaded the relevant objects.

This screen offers you the choice of looking at the Alert file, the Background Trace Files, or the User Trace Files. If you choose "Show Background Trace Files," you will be presented with a list of the contents of the directory specified in the BACKGROUND_DUMP_DEST parameter. The Alert Log will not be shown in this list.  

If you choose "Show User Trace Files," you will be presented with a list of the contents of the directory specified in the USER_DUMP_DEST parameter.

As you can see on this screen, for each .trc file there are two options, SRT and TKP. The SRT option means "Show Raw Trace file" and will retrieve the contents of the file for you and display it on the browser screen.

The other option, TKP, means "TKPROF" and results in a dialog screen for calling the TKPROF utility, the standard method of converting the contents of a .trc into a more user-friendly format. (See Figure 5.) This dialog screen allows you to switch off the display of recursive SQL, to specify a user for generating explain plans in the trace files, and to set any of the sort parameters that TKPROF accepts, purposes of which are many and varied and will depend on what you are actually tracing and what it is that you are looking for.

When the required TKPROF parameters have been entered (or the defaults used), the utility will generate and fire a command line instruction to run tkprof on the server where the database resides. It will then re-show you the user trace file screen and will align the new .prf on the display with its parent .trc file.

You also then have another option, SFT, which means "Show Formatted Trace File." This screen will show you the post-TKPROF formatted contents.  

You will also see the option to delete any or all the files. Choosing this option, you will be presented with a further "Are You Sure?" screen showing the chosen files and the choice to confirm or cancel. After choosing Confirm you will be presented back with a list of the remaining files. Formatted trace files are deleted along with their parent raw trace files. This delete functionality works in the same way on the SFT screen.

If from the Targets screen you choose "Show Alert File," you will be presented with the contents of the current alert file.

An additional option at the top left of this screen is "Archive this file." If you choose this option, the entire contents of the current alert file are copied to a backup and a new, fresh alert file is generated.

If you look at the "Background Trace Files" screen, you will see an already archived alert file called 0040527144418_alert_berlindev01.log. This "Archive Alert File" functionality may or may not be useful to you (depending on how clean you like to keep your alert log).

Select the Oracle.DataAccess.dll from the list, then click the Select button, and finally click the OK button to make the ODP.NET data provider known to your project.

Limitations

This utility assumes that the remote database has read access to the directories specified in the parameters USER_DUMP_DEST and BACKGROUND_DUMP_DEST. It also needs these two directories to be specified as UTL_FILE directives in the init.ora. If these two conditions cannot be guaranteed in your environment, you will need to find an alternative way of reading the trace file data into the database.

As the utility uses the database itself as the transfer mechanism for reading trace files on the remote server(s) and serving the data up centrally, the remote database must be active—that is, the utility cannot show you trace files from databases that are crashed or down for any other reason.

Conclusion

One of the main reasons for the development of TFM is the proliferation of Oracle databases, both production and development/test, that the team here at Skandia is being asked to support. The session trace utility can very easily be applied remotely to any session via SQL*Plus, but the subsequent viewing of the trace file generated requires at least a disk-map to the server where the database resides. With 10 or 15 databases to manage, this approach has become something of a chore. The task is made even more difficult when we want to issue a TKPROF against the trace file, as command-line access to the appropriate server is generally then required.

Used in combination, the ease of use of PL/SQL and the power of PHP make it easy to access Oracle databases and then render the retrieved data in a browser. This capability gives you the opportunity to build a central "command post" from which to expose and control all your distributed trace information. By harnessing the power of PHP and Oracle we have been able to put together a tasty little labour-saving device, useful to DBAs and developers alike.

Thanks to Karsten Gresch, also of Skandia, for his contribution in developing this tool.

References

Trace File Manager: Managing Distributed Trace Files with Oracle and PHP by Paul Gallagher

Tracing SQL in Oracle Database 10g

New tools help you better understand the performance of your applications.

In a busy production environment with many active users, tracing a SQL session is time-consuming and complicated, because processing SQL statements in any multitier system that uses a connection pool can span multiple processes, or even different instances.

With Oracle Database 10g, Oracle rationalizes SQL tracing through a new built-in package, DBMS_MONITOR, which encompasses the functionality of previously undocumented trace tools, such as the DBMS_SUPPORT package. Now you can easily trace any user's session from beginning to end—from client machine to middle tier to back end—and generate trace files based on specific client ID, module, or action.

In addition, Oracle Database 10g includes a new utility, trcsess, that lets you selectively extract trace data from numerous trace files and save them into a single file, based on criteria such as session ID or module name. This utility is especially useful in a shared server configuration, since a dispatcher may route each user request to a different shared server process, resulting in multiple trace files for any given session. Rather than digging through numerous trace files, Oracle Database 10g's trcsess lets you obtain consolidated trace information pertaining to a single user session.

Getting Started

As with prior Oracle database releases, trace files are output to the directory specified by the user_dump_dest parameter of the server's initialization file (or spfile). The default location depends on the operating system; for example, for Microsoft Windows platforms using DBCA, the default is $ORACLE_BASE\instance_name\admin\udump, where instance_ name is the name of the Oracle instance. You can dynamically change this parameter by using the alter system command:

alter system set user_dump_dest="c:\kflosstrace";

You can also add your own marker to the trace file names so you can more easily find the generated files. To do so, set the tracefile_identifier initialization parameter before starting a trace:

alter session set 

tracefile_identifier ="kfloss_test";

Trace files generated by this command have the string value you set appended to the filenames. Although neither of these alter commands is necessary, both make it easier to find the results of a tracing session.

Now that we've set these parameters, let's look at the new tracing package and the Oracle Enterprise Manager interface. 

Let's set up a trace by module name and client name, using the new DBMS_MONITOR package.

Setting Up Tracing with DBMS_MONITOR

The DBMS_MONITOR package has routines for enabling and disabling statistics aggregation as well as for tracing by session ID, or tracing based upon a combination of service name, module name, and action name. (These three are associated hierarchically: you can't specify an action without specifying the module and the service name, but you can specify only the service name, or only the service name and module name.) The module and action names, if available, come from within the application code. For example, Oracle E-Business Suite applications provide module and action names in the code, so you can identify these by name in any of the Oracle Enterprise Manager pages. (PL/SQL developers can embed calls into their applications by using the DBMS_APPLICATION_INFO package to set module and action names.)

Note that setting the module, action, and other paramters such as client_id no longer causes a round-trip to the database—these routines now piggyback on all calls from the application.

The service name is determined by the connect string used to connect to a service. User sessions not associated with a specific service are handled by sys$users (sys$background is the default service for the background processes). Since we have a service and a module name, we can turn on tracing for this module as follows:

SQL> exec dbms_monitor.serv_mod_act_trace_enable

(service_name=>'testenv', module_name=>'product_update');

PL/SQL procedure successfully completed.

We can turn on tracing for the client:

SQL> exec dbms_monitor.client_id_trace_enable

(client_id=>'kimberly');

PL/SQL procedure successfully completed.

Note that all of these settings are persistent—all sessions associated with the service and module will be traced, not just the current sessions.

To trace the SQL based on the session ID, look at the Oracle Enter-prise Manager Top Sessions page, or query the V$SESSION view as you likely currently do.

SQL> select sid, serial#, username 

from v$session;

       SID     SERIAL#  USERNAME

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

       133       4152  SYS

       137       2418  SYSMAN

       139         53  KIMBERLY

       140        561  DBSNMP

       141          4  DBSNMP

. . .

       168          1

       169          1

       170          1

28 rows selected.

With the session ID (SID) and serial number, you can use DBMS_MONITOR to enable tracing for just this session:

SQL> exec dbms_monitor.session_trace_enable(139); 

PL/SQL procedure successfully completed.

The serial number defaults to the current serial number for the SID (unless otherwise specified), so if that's the session and serial number you want to trace, you need not look any further. Also, by default, WAITS are set to true and BINDS to false, so the syntax above is effectively the same as the following:

SQL> exec dbms_monitor.session_trace_enable

(session_id=>139, serial_num=>53, waits=>true, binds=>false);

Note that WAITS and BINDS are the same parameters that you might have set in the past using DBMS_SUPPORT and the 10046 event.

If you're working in a production environment, at this point you'd rerun the errant SQL or application, and the trace files would be created accordingly.

Setting Up Tracing with Enterprise Manager

Setting up tracing through Oracle Enterprise Manager starts on the Top Consumers page (available from the Performance page in the Additional Monitoring Links section.  This page shows the system's current resource usage by service, module, client, and action.

You can click on the Top Services, Top Modules, Top Actions, Top Clients, or Top Sessions tabs to see the detail for each of these categories of top consumers, and then you can easily enable (or disable) SQL tracing from each of these pages. Simply select the item from the list on the page and then click on Enable SQL Trace to begin the trace (and click on 

Disable when you're finished).

You can enable (or disable) statistics aggregation for any items listed on these pages as well. (DBMS_MONITOR also provides routines for enabling and disabling aggregation.)

Analyzing Trace Results

Whether you use DBMS_MONITOR or Oracle Enterprise Manager to set up tracing, you'll use the trcsess command line tool to consolidate trace files. Click on the View SQL Trace button in Oracle Enterprise Manager to display a page that shows the syntax you'll use to consolidate all trace files.

Be sure to double-quote the strings, and add a ".trc" extension to the filename; otherwise, TKPROF won't accept it as a filename. Before executing the command, navigate to the directory specified in the user_dump_dest (or \udump, if you didn't change this parameter name).

C:\...\udump> trcsess output="kfloss.trc" service="testenv" 

module="product update" 

action="batch insert"

You can then run TKPROF against the consolidated trace file to generate a report.

C:\...\udump> tkprof kfloss.trc 

output=kfloss_trace_report SORT=(EXEELA, PRSELA, FCHELA)

If you don't disable tracing, every session that runs that service and module will be traced. Thus, when you're finished, be sure to disable tracing by using either Oracle Enterprise Manager or the DBMS_MONITOR package.

REFERENCES

Tracing SQL in Oracle Database 10g By Kimberly Floss

Oracle Parse to Execute Ratio

All Oracle SQL statements must be parsed the first time that they execute, and parsing involves a syntax check, a semantic check (against the dictionary), the creation of a decision tree, and the generation of the lowest cost execution plan. Once the execution plan is created, it is stored in the library cache (part of the shared_pool_size) to facilitate re-execution. There are two types of parses:

• Hard parse - A new SQL statement must be parsed from scratch. (See hard parse ratio, comparing hard parses to executes). If the database is parsing every statement that is executing, the parse to execute ratio will be close to 1% (high hard parses), often indicating non-reentrant SQL that does not use host variables (see cursor_sharing=force).
  
• Soft parse - A reentrant SQL statement where the only unique feature are host variables. (See soft parse ratio, comparing soft parses to executes). The best-case scenario is a parse to execute ratio of 100% which would indicate an application with fully reentrant SQL that "parses SQL once and executes many times" (also see your setting for session_cached_cursors, as this effects the reentrancy of an SQL statement).

In a real database, some SQL statements will be fully reentrant (execute to parse = 100%), while others must be re-parsed for every execution (execute to parse = 1%). You can see this is the instance efficiency of any STATSPACK and AWR report:

Instance Efficiency Percentages (Target 100%)

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Buffer Nowait %: 99.99 Redo NoWait %: 100.00

Buffer Hit %: 97.97 In-memory Sort %: 100.00

Library Hit %: 98.30 Soft Parse %: 97.05

Execute to Parse %: 0.91 Latch Hit %: 99.73

Parse CPU to Parse Elapsd %: 72.59 % Non-Parse CPU: 95.52

High parses suggests that your system has many incoming unique SQL statements, or that your SQL is not reentrant (i.e. literal values in the WHERE clause, not using bind variables), and consider setting cursor_sharing=force can cause dramatic performance improvements for systems with ad-hoc query tools such as Crystal Reports or Business Objects.

A hard parse is expensive because each incoming SQL statement must be re-loaded into the shared pool; with the associated overhead involved in shared pool RAM allocation and memory management. Once loaded, the SQL must then be completely re-checked for syntax & semantics and an executable generated. Excessive hard parsing can occur when your shared_pool_size is too small (and reentrant SQL is paged out), or when you have non-reusable SQL statements without host variables. See the cursor_sharing parameter for an easy way to make SQL reentrant and remember that you should always use host variables in you SQL so that they can be reentrant.

Note that the "soft parse ratio" and the "hard parse ratio" are totally independent metrics, and it's possible to see all combinations:

Soft Parse Ratio	Hard parse Ratio
low	low
high	high
low	high
high	low

You can see these ratio's in any STATSPACK or AWR report, in the load profile and instance efficiency sections. You can also paste-in your STATSPACK or AWR reports into www.statspackanalyzer.com for a detailed analysis:

Load Profile

~~~~~~~~~~~~ Per Second Per Transaction

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

Redo size: 26,032.63 2,148.01

Logical reads: 4,943.63 407.91

Block changes: 158.17 13.05

Physical reads: 14.52 1.20

Physical writes: 26.77 2.21

User calls: 86.37 7.13

Parses: 148.80 12.28

Hard parses: 9.81 0.81

Sorts: 134.58 11.10

Logons: 12.18 1.01

Executes: 149.96 12.37

Instance Efficiency Percentages (Target 100%)

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Buffer Nowait %: 99.99 Redo NoWait %: 100.00

Buffer Hit %: 97.97 In-memory Sort %: 100.00

Library Hit %: 98.30 Soft Parse %: 97.05

Execute to Parse %: 0.91 Latch Hit %: 99.73

Parse CPU to Parse Elapsd %: 72.59 % Non-Parse CPU: 95.52

If the execute to parse ratio is too low, it is possible that the application is not using shareable SQL, or the database has sub-optimal parameters that are reducing the effectiveness of cursor sharing. A problem like excessive parsing is likely to manifest itself as additional network traffic between the application server and clients. The additional parse activity may also show up as a marked increase in CPU consumption on the database server.

REFERENCES

Oracle Tips by Burleson Consulting