Wednesday, March 5, 2014

Trace Oracle In Web Applications



It is a typical 3-tier web application with Oracle as the database and you’d like to find out what sqls the application issues for serving each page, and how well or badly these sqls perform. 


The solution involves two parts.

The first part contains these steps:


  •   Many connections might be fetched from the connection pool to serve a single page. Mark these connections with the same identify. In Oracle, one can use dbms_session.set_identifier.
  •  Trace the connections with the given identify.
dbms_monitor.client_id_trace_enable(?,true,true).
 
Traced connections will generate trace file for the sqls they performed. There might be multiple trace files. So the second part involves consolidate trace files into one trace file. In Oracle, one can use the command trcsess. Trace files contains raw information which is hard to read, one can further use tkprof or trca: TKPROF on steroids.


The following code shows how it works:

public class TraceWebApplication {

        private static String identifyClient = "{call dbms_session.set_identifier(?)}";
        private static String traceClient = "{call dbms_monitor.client_id_trace_enable(?,true,true)}";
        private static String unTraceClient = "{call dbms_monitor.client_id_trace_disable(?)}";
        private static String findUserDumpFolder = "{?=call DBMS_UTILITY.GET_PARAMETER_VALUE(?,?,?)}";
        private static String identifier = "apple1";
        private static String findServerModel = "select server from v$session";

        public static void main(String[] args) throws Exception {

                //identify the 1st connection
                Connection conn1 = null;
                CallableStatement call = null;
                PreparedStatement stat = null;
                try {
                        conn1 = DriverManager.getConnection("jdbc:oracle:thin:@127.0.0.1:1521:orcl", "test",        "test");

                        //find out where the trace files are located
                        System.out.println(findUserDumpFolder(conn1));

                        call = conn1.prepareCall(identifyClient);
                        call.setString(1, identifier);
                        call.execute();

                        //set trace on
                        call = conn1.prepareCall(traceClient);
                        call.setString(1, identifier);
                        call.execute();

                        //this statement will be traced
                        stat = conn1.prepareStatement("select /*+connection1*/ 1 from dual");
                        stat.execute();

                } finally {
                        if (stat != null) {
                                stat.close();
                        }
                        if (call != null) {
                                call.close();
                        }
                        if (conn1 != null) {
                                conn1.close();
                        }
                }

                Connection conn2 = null;
                try {
                        conn2 = DriverManager.getConnection("jdbc:oracle:thin:@127.0.0.1:1521:orcl", "test",        "test");
                        //identify the 2nd connection
                        call = conn2.prepareCall(identifyClient);
                        call.setString(1, identifier);
                        call.execute();
                        //this statement will be traced
                        stat = conn2.prepareStatement("select /*+connection2*/ 1 from dual");
                        stat.execute();

                        //set trace off
                        call = conn2.prepareCall(unTraceClient);
                        call.setString(1, identifier);
                        call.execute();
                        //this statement will not be traced, because the connection is un-identified
                        stat = conn2.prepareStatement("select /*+connection2 not traced*/ 1 from dual");
                        stat.execute();
                } finally {
                        if (stat != null) {
                                stat.close();
                        }
                        if (call != null) {
                                call.close();
                        }
                        if (conn2 != null) {
                                conn2.close();
                        }
                }

        }

        /**
         * find out where the trace files are located
         */
        private static String findUserDumpFolder(Connection con) throws Exception {

                CallableStatement call = null;
                try {
                        /*
                         * Dedicated Server, trace file on:
                         * select value from  v_$parameter where name='user_dump_dest';
                         * Shared Server, trace file on:
                         * select value from  v_$parameter where name='background_dump_dest';
                         */
                        String parameter = "user_dump_dest";
                        PreparedStatement pStat = con.prepareStatement(findServerModel);
                        ResultSet resultSet = pStat.executeQuery();
                        if (resultSet.next()) {
                                String serverModel = resultSet.getString(1);
                                if (!"DEDICATED".equalsIgnoreCase(serverModel)) {
                                        parameter = "background_dump_dest";
                                }
                        }

                        call = con.prepareCall(findUserDumpFolder);
                        call.registerOutParameter(1, java.sql.Types.INTEGER);
                        call.setString(2, parameter);
                        call.registerOutParameter(3, java.sql.Types.INTEGER);
                        call.registerOutParameter(4, java.sql.Types.VARCHAR);
                        call.execute();
                        return call.getString(4);
                } finally {
                        if (call != null) {
                                call.close();
                        }
                }
        }
}


In this test case, these two sqls should be traced under the identifier apple1:

 
select /*+connection1*/ 1 from dual
select /*+connection2*/ 1 from dual

While this sql shouldn’t :

select /*+connection2 not traced*/ 1 from dual
 
Because when it was executed, connection2 was not under trace anymore. 


Method findUserDumpFolder() finds out where the trace files are located, in my test, it returns c:\oracle\diag\rdbms\orcl\orcl\trace. So navigate to this location, and do the second part:

 
c:\oracle\diag\rdbms\orcl\orcl\trace>trcsess clientid=apple1 output=apple1.trc
c:\oracle\diag\rdbms\orcl\orcl\trace>tkprof apple1.trc sys=no output=apple1.prof


trcsess consolidates the traces under the identifier apple1 into a single trace file apple1.trc.
trprof takes on the above generated trc file and generate a readable file. 

From here, it is just one step away from implementing the solution in a web application.


  • I If a user ticks off “trace this page”:
  •  A filter captures the trace identifier, and stores it in a ThreadLocal.
  • When a connection is fetched from the connection pool, intercept “getConnection()” method, and identify and trace it. 
  • When the connection is returned to the connection pool, intercept “closeConnection()” method and un-identify and un-trace it.











2 comments: