如何使用oracle提供的SQL_TRACE来跟踪sql的执行情况

Sql性能非常差的时候,oracle提供了SQL_TRACE来跟踪sql的执行情况。

　　注：分析sql的方式比较多，还有根据优化器、sql执行计划来分析。

　　SQL_TRACE能够将sql执行的过程输出到一个trace文件里面。

　　首先设置自己定义的trace文件的标识方便查找。

　　alter session set tracefile_identifier='mytest';

　　然后对当前会话启动SQL_TRACE，最好不要一直打开该开关，代价比较大。

　　alter session set sql_trace=true;

　　然后我们执行一条sql语句。

　　最后关闭该开关的状态。

　　alter session set sql_trace=false;

　　我们可以从目录%ORACLE_BASE%/diag/rdbms/orcl/orcl/trace(11g版本的路径，如果是10g的应该不一样)中

　　找到自己定义的trace文件。

　　原始的trace文件的可读性不高，我们一般使用oracle自带的工具，tkprof来处理这个trace文件。我们可以查看tkprof的帮助。

　　tkprof orcl_ora_3820_mytest.trc out.txt

　　我们来看刚才生成的trace文件，头部信息描述了tkprof 的版本以及报告中一些列的含义，对于任何一条sql语句，都应该包含Parse—sql分析阶段，Execute—sql执行阶段，Fetch—数据提取阶段，横向的列如图所示，包含消耗cpu时间0.00秒，操作总耗时0.04秒，物理读取了0个数据块，没有发生current方式的读取(一般在update会发生)，一共提取记录1条。

　　Misses in library cache during parse: 0表示这是一次软分析(关于硬分析和软分析下面会接着谈到)

　　Optimizer mode: ALL_ROWS表示oracle的优化器模式为ALL_ROWS。这也就是前面提到的另外的分析方式优化器。

　　下面是sql执行的具体计划，可以看到执行计划选择的是全表扫描。

　　经过处理以后的trace文件的确比较容易看明白，它有助于我们分析sql的性能问题。

　　下面我通过一个trace实例来解释一下，为什么OLTP系统中需要变量绑定机制。

　　当用户和数据库建立连接，并发送一条sql语句以后，oracle会对该sql进行hash函数运算(hash算法提供了一种快速存取数据的方法，它用一种算法建立键值与真实值之间的对应关系,每一个真实值只能有一个键值，但是一个键值可以对应多个真实值，以方便存取)，得到一个hash值，然后到共享池中寻找是否有匹配的hash值的sql存在，如果有，就直接使用该sql的执行计划去执行sql。如果没有，oracle就会认为这是一条新的sql语句，然后按照语法分析，语义分析，生成执行计划，执行sql这些步骤来执行最终把结果返回给用户。这些步骤也被成为硬分析，可以想象，如果减少硬分析，能够大大降低数据库花费在sql解析上的资源开销。

　　我们先执行一条sql 1000次，比较绑定变量和不绑定变量的差异。得到结果以后，要计算实际的消耗，我们需要把OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS以及OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS的时间累计起来，前者表示数据字典表的相关的信息，包含权限控制等，后者表示sql所衍生出的递归sql语句的信息。可以看到绑定变量的，整条语句执行时间为0.22+0.02=0.24秒，CPU时间0.18+0.03=0.21秒，分析次数3次，执行次数1003次。而不绑定变量的时候，整条语句执行时间为0.28+1.29=1.57秒，CPU时间0.31+1.26=1.57秒，分析次数1002次，执行次数1003次。可见绑定变量的确能够带来更低的开销。(如何设计数据库中使用绑定变量也是和系统息息相关的，很多数据库问题都是在设计以后就已经存在的)

　　应用级调优分析:

　　就通常所说的三层架构来说，中间件这一层能够起到一个缓冲池的作用，如果并发用户数到3000这个数量级的时候，中间件能够控制不是所有的用户都能直接连接到数据库，当然这里的程序会快速响应用户请求，保证缓冲池的队列等待不会很久。

　　对应用这一级别的调优，主要集中在app程序，中间件的监控，集群配置等方面。如果是发现应用级别的问题，首先要分析是配置问题，还是程序本身的问题。如果并发用户数很大，中间件的线程池最大值配置过小，会导致在请求队列堆积，表现就是线程监控视图中，请求的队列堆积比较多，一般可以调整线程池最大值来解决。我们来看看weblogic的监控视图。

　　考虑到如果为每一个请求都创建一个新线程来处理的话，那么我们难以在系统中实现足够数量的线程。不受限制的创建线程可能耗尽系统资源，因此引入了线程池。线程池的思想是在进程开始时创建一定数量的线程并将它们置入一个池(pool)中，线程在这个池中等待工作。当服务器接收到一个请求时，它就从池中唤醒一个线程(如果有可用的线程)，由它来处理请求。一旦线程服务完毕，它就返回线程池等待后面的工作。

　　线程池利用已存在的线程服务请求要比等待创建一个线程要快，并且线程池限制了线程的数量。

　　如果怀疑是程序的问题，我们一般可以通过java自带的工具来帮助分析，工具很多。这里我主要提到一个jdk1.6以后附带的jvisualvm。

　　我们打开jdk1.6，找到并运行jvisualvm.exe。

　　我们发现应用程序分为本地，远程两部分。本地包含本地运行的java进程，远程能够通过配置连接到远程服务器上的java进程。我们先启动一个tomcat。可以看到本地应用程序已经打开了一个带有tomcat以及进程标识id的菜单。双击打开。这里我们一般关心2个视图。监视、线程。

　　其中监视视图比较关心垃圾回收活动(顾名思义，回收那些在程序里面不再使用到的内存空间)，堆内存变化。如果在压力测试过程中，堆内存变化是一个逐渐上涨的趋势，并且经过多次手动gc回收，还是保持这个趋势，说明内存泄漏的可能性很大。如果猜测有内存泄漏，可以通过分析java的heap dump。JVM (java虚拟机)记录下问题发生时系统的运行状态并将其存储在转储(dump)文件中。Heap dump就是这样一种文件形式。

　　线程视图比较关心线程的当前执行状态，这里可以生成另一种转储文件 Java dump。Java dump，也叫做 Thread dump，是 JVM 故障诊断中最重要的转储文件之一。JVM 的许多问题都可以使用这个文件进行诊断，其中比较典型的包括线程阻塞，CPU 使用率过高，JVM Crash，堆内存不足，和类装载等问题。其中线程阻塞更加常见。

线程阻塞是我们在 java 多线程编程中经常遇到的问题。由于对后端有限资源的争用以及过度同步等问题，经常会发现 Java dump 中某个资源(锁对象)下有太多的线程处于等待状态，这时候我们通常需要从以下三个方面去诊断这个问题：

　　这个锁存在的目的是什么?有没有可能去掉这个锁或者缩小这个锁保护的范围，从而减少线程等待问题发生的几率。

　　有哪些线程需要用到这个锁，有没有可能改用其它更好的替代方案。

　　当前哪个线程正在持有这个锁，持有的时间是多长，有没有可能缩短持有的时间。

　　下面通过实际测试中的dump文件来谈谈如何读懂一个dump文件。

　　可以看到一共有4种线程的状态，WAITING，RUNNABLE，TIMED_WAITING (sleeping)，BLOCKED。线程阻塞就是BLOCKED。搜索文件中BLOCKED的部分，我们可以看到其中一个：

　　"[ACTIVE] ExecuteThread: '91' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaae8181000 nid=0x4849 waiting for monitor entry [0x0000000047d4d000]

　　java.lang.Thread.State: BLOCKED (on object monitor)

　　* 线程名称：

　　* 线程类型：daemon

　　* 优先级：10，默认是5

　　* jvm线程id：jvm内部线程的唯一标识,0x00002aaae8181000

　　* 对应系统线程id：和top命令查看的pid对应，不过一个是10进制，一个是16 进制。0x4849

　　* 线程状态：BLOCKED

　　* 起始栈地址：

　　可以看到很多线程状态都是BLOCKED，表示当前线程A正要进入一个同步块，但是被另外一个线程B持有该锁，于是需要等待B，释放锁才有机会重新获取。

　　用一种轻松的方式来思考锁，其实挺简单的。数据库中也存在这样的锁。为什么会有锁，打个比喻，一个java对象就像一个大房子，大门永远打开。房子里有很多房间(方法)。这些房间有上锁的和不上锁之分。房门口只放着一把钥匙，这把钥匙可以打开所有上锁的房间。把所有想调用该对象方法的线程比喻成想进入这房子某个房间的人。试想如果只有一个人，肯定是不存在等待别人使用完钥匙归还的时候。如果要是很多人，势必会需要等这把钥匙归还，等钥匙还回来以后，就会有一个人优先得到钥匙。

　　由此可以看到，锁是不可避免的，要想正确获取对象的状态，或者修改对象的状态，必须存在这样一种lock。也就意味着，锁的持有时间越久，对性能的影响也就越大，直接结果是大并发情况下，响应时间的延长。回到以前的thread dump，如果通过工具我们发现，线程阻塞比较频繁，并且持续时间很久，不妨多次收集这种转储文件，可以有效的帮助我们分析问题。

　　我们刚才看到的转储文件就是XXX测试中捕获到的，通过这些地方，我们发现了一些性能方面的问题。除了线程阻塞，我们分析dump文件还可以找到消耗CPU最多的地方。如果不是windows操作系统，可以通过top(top –H)或者topas命令来查看应用程序的线程信息及占用CPU的情况。找到排序第一位的pid值，按照我们前面解释的，换算成16进制，然后在thread dump日志中搜索该数值nid就能找到耗费CPU的源代码的具体位置，可以精确到行号。

　　另外还可以分析是否有很多thread struck在了I/O，例如：

　　"New I/O server worker #1-1" prio=10 tid=0x00000000423e0800 nid=0x5bfd runnable [0x00007f7d0a2f4000]

　　java.lang.Thread.State: RUNNABLE

　　at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)

　　at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:215)

　　或者是thread struck在数据库，例如：

　　"[ACTIVE] ExecuteThread: '99' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00002aaae8190800 nid=0x4857 runnable [0x0000000048554000]

　　java.lang.Thread.State: RUNNABLE

　　at java.net.SocketInputStream.socketRead0(Native Method)

　　at java.net.SocketInputStream.read(SocketInputStream.java:129)

　　at oracle.net.ns.Packet.receive(Packet.java:293)

　　at oracle.net.ns.DataPacket.receive(DataPacket.java:92)

　　等地方，便于我们定位瓶颈原因。