一、通过top命令可以看到会话PID19237占用大量的CPU
Tasks: 233 total, 2 running, 231 sleeping, 0 stopped, 0 zombie Cpu0 : 0.0%us, 0.0%sy, 0.0%ni, 99.7%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st Cpu1 :100.0%us, 0.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Mem: 2039644k total, 1929468k used, 110176k free, 149788k buffers Swap: 4095992k total, 43212k used, 4052780k free, 1265044k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19237 oracle 20 0 540m 38m 34m R 100.0 1.9 1:31.45 oracle 1 root 20 0 19396 1204 936 S 0.0 0.1 0:01.18 init 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd 3 root RT 0 0 0 0 S 0.0 0.0 0:00.41 migration/0 4 root 20 0 0 0 0 S 0.0 0.0 0:22.39 ksoftirqd/0 5 root RT 0 0 0 0 S 0.0 0.0 0:00.00 migration/0 6 root RT 0 0 0 0 S 0.0 0.0 0:00.03 watchdog/0 7 root RT 0 0 0 0 S 0.0 0.0 0:00.45 migration/1 8 root RT 0 0 0 0 S 0.0 0.0 0:00.00 migration/1 9 root 20 0 0 0 0 S 0.0 0.0 0:00.44 ksoftirqd/1 10 root RT 0 0 0 0 S 0.0 0.0 0:00.05 watchdog/1 11 root 20 0 0 0 0 S 0.0 0.0 0:13.39 events/0 12 root 20 0 0 0 0 S 0.0 0.0 0:00.45 events/1 13 root 20 0 0 0 0 S 0.0 0.0 0:00.00 cpuset 14 root 20 0 0 0 0 S 0.0 0.0 0:00.00 khelper 15 root 20 0 0 0 0 S 0.0 0.0 0:00.00 netns 16 root 20 0 0 0 0 S 0.0 0.0 0:00.00 async/mgr 17 root 20 0 0 0 0 S 0.0 0.0 0:00.00 pm 18 root 20 0 0 0 0 S 0.0 0.0 0:00.00 sync_supers 19 root 20 0 0 0 0 S 0.0 0.0 0:00.00 bdi-default 20 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kintegrityd/0 21 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kintegrityd/1 22 root 20 0 0 0 0 S 0.0 0.0 0:00.59 kblockd/0 23 root 20 0 0 0 0 S 0.0 0.0 0:00.17 kblockd/1 24 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kacpid 25 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kacpi_notify 26 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kacpi_hotplug 27 root 20 0 0 0 0 S 0.0 0.0 0:00.00 ata/0 28 root 20 0 0 0 0 S 0.0 0.0 0:00.00 ata/1 29 root 20 0 0 0 0 S 0.0 0.0 0:00.00 ata_aux 30 root 20 0 0 0 0 S 0.0 0.0 0:00.00 ksuspend_usbd 31 root 20 0 0 0 0 S 0.0 0.0 0:00.02 khubd 32 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kseriod 33 root 20 0 0 0 0 S 0.0 0.0 0:00.00 md/0 34 root 20 0 0 0 0 S 0.0 0.0 0:00.00 md/1 35 root 20 0 0 0 0 S 0.0 0.0 0:00.00 md_misc/0 36 root 20 0 0 0 0 S 0.0 0.0 0:00.00 md_misc/1 37 root 20 0 0 0 0 S 0.0 0.0 0:00.01 khungtaskd 38 root 20 0 0 0 0 S 0.0 0.0 0:05.43 kswapd0 39 root 25 5 0 0 0 S 0.0 0.0 0:00.00 ksmd
二、根据PID确定对应的SID与SERIAL#
SQL> select s.sid,s.serial# from v$session s,v$process p where s.paddr=p.addr and p.spid='19237'; SID SERIAL# ---------- ---------- 22 79
三、对会话进行开启跟踪 SQL> exec dbms_monitor.session_trace_enable(22,79,TRUE,FALSE); PL/SQL procedure successfully completed. 四、在问题会话端再次执行一条问题sql【会话连接正在执行的sql无法跟踪，只有开启跟踪后产生的新sql才会被跟踪】
SQL> select * from scott.t3 where name=dbms_random.string('u', 10);
no rows selected
五、关闭会话跟踪
SQL> exec dbms_monitor.session_trace_disable(22,79); PL/SQL procedure successfully completed.
六、查看会话跟踪文件位置
SQL> show parameter user NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ license_max_users integer 0 parallel_adaptive_multi_user boolean TRUE redo_transport_user string user_dump_dest string /u01/app/oracle/diag/rdbms/orc l/orcl/trace
七、使用tkprof工具解析产生的跟踪文件，跟踪文件名称为："数据库实例名"_ora_"PID".trc
[oracle@localhost trace]$ tkprof orcl_ora_19237.trc trc_tmp.txt
八、查看解析后的文件内容，通过CPU指标找到消耗最大，以下为消耗cpu最多的消息截取内容 [oracle@localhost trace]$ more trc_tmp.txt ******************************************************************************** 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 ******************************************************************************** SQL ID: gmkaj9nz7vyvw Plan Hash: 4161002650 select * from scott.t3 where name=dbms_random.string('u', 10) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.11 0 1 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 61.27 61.31 12449 12453 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 61.27 61.43 12449 12454 0 0 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: SYS Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 0 0 0 TABLE ACCESS FULL T3 (cr=12453 pr=12449 pw=0 time=61315265 us cost=3632 size=836060 card=24590) 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 direct path read 399 0.00 0.04 SQL*Net message from client 1 12.34 12.34
