5、结果分析——执行过程日志
首先是查看脚本执行过程，在prw_SimpleLinux.log中，可以看到脚本监控执行全过程。说明：下面是日志文件的全文，在其中以红字标注关键问题点。
################################################################################
Wed Apr 30 09:32:21 CST 2014: Procwatcher Version 12.1.13.11.1 starting on Linux
################################################################################
Wed Apr 30 09:32:21 CST 2014: Thank you for using Procwatcher. :-)
Wed Apr 30 09:32:21 CST 2014: Please add a comment to Oracle Support Note 459694.1
Wed Apr 30 09:32:22 CST 2014: if you have any comments, suggestions, or issues with this tool.
################################################################################
Wed Apr 30 09:32:22 CST 2014: Procwatcher running as user oracle–执行用户声明
Wed Apr 30 09:32:22 CST 2014: ### Parameters ###--参数列表
Wed Apr 30 09:32:22 CST 2014: EXAMINE_CLUSTER=false
Wed Apr 30 09:32:22 CST 2014: EXAMINE_BG=true
Wed Apr 30 09:32:22 CST 2014: PRWPERM=777
Wed Apr 30 09:32:22 CST 2014: RETENTION=7
Wed Apr 30 09:32:22 CST 2014: WARNINGEMAIL=
Wed Apr 30 09:32:22 CST 2014: INTERVAL=60
Wed Apr 30 09:32:22 CST 2014: THROTTLE=5
Wed Apr 30 09:32:22 CST 2014: IDLECPU=3
Wed Apr 30 09:32:22 CST 2014: SIDLIST=ora11g–注意是list
Wed Apr 30 09:32:22 CST 2014: ### Advanced Parameters (non-default) ###
Wed Apr 30 09:32:22 CST 2014: ### End Parameters ###
Wed Apr 30 09:32:23 CST 2014: Checking DB version for SID ora11g
Wed Apr 30 09:32:24 CST 2014: ..SQL: Running SQLvinstance.sql on SID ora11g
Wed Apr 30 09:32:25 CST 2014: DB Version for SID ora11g is 11.2.0.4.0–检查出的版本
Wed Apr 30 09:32:25 CST 2014: ..SQL: Running SQLdrop_procwatcher_pids.sql on SID ora11g
Wed Apr 30 09:32:26 CST 2014: Created /prw/PRW_DB_ora11g directory
Wed Apr 30 09:32:26 CST 2014: Using oradebug short_stack to speed up DB stack times...
Wed Apr 30 09:32:27 CST 2014: ..SQL: Running SQLprocwatcher_pids.sql on SID ora11g
Wed Apr 30 09:32:29 CST 2014: Collecting SQL Data for SID ora11g–SQL数据
Wed Apr 30 09:32:30 CST 2014: ..SQL: Running SQLvwaitchains.sql on SID ora11g
Wed Apr 30 09:32:32 CST 2014: ..SQL: Running SQLvsessionwait.sql on SID ora11g
Wed Apr 30 09:32:33 CST 2014: ..SQL: Running SQLvlock.sql on SID ora11g
Wed Apr 30 09:32:33 CST 2014: ..SQL: Running SQLvlatchholder.sql on SID ora11g
Wed Apr 30 09:32:36 CST 2014: Saving SQL report data for SID ora11g
Wed Apr 30 09:32:41 CST 2014: Instance ora11g Suspected final blocker is: Process: 1988 SID: 35 SER#: 45 INST ora11g INST #: 1–定位到blocker
Wed Apr 30 09:32:41 CST 2014: ora11g Waitchains SessionCount:2-Instance:1
Wed Apr 30 09:32:41 CST 2014: Adding these processes to the process list for SID ora11g if they are not there already: --列出怀疑的进程
UID PID PPID C STIME TTY TIME CMD
oracle 1988 1 0 09:29 ? 00:00:00 oracleora11g (LOCAL=NO)
oracle 2012 1 0 09:31 ? 00:00:00 oracleora11g (LOCAL=NO)
Wed Apr 30 09:32:42 CST 2014: Collecting process specific SQLs for SID ora11g
Wed Apr 30 09:32:44 CST 2014: ..SQL: Running SQLsqltext.sql on SID ora11g
Wed Apr 30 09:32:44 CST 2014: ..SQL: Running SQLash.sql on SID ora11g
Wed Apr 30 09:32:48 CST 2014: SQL collection complete after 26 seconds (9 SQLs - average seconds: 2)
--对后台进程的导出
Wed Apr 30 09:32:49 CST 2014: Getting stack for ora_pmon_ora11g 1582 using short_stack in /prw/PRW_DB_ora11g/prw_ora_pmon_ora11g_1582_04-30-14.out
Wed Apr 30 09:32:51 CST 2014: Getting stack for ora_dbw0_ora11g 1600 using short_stack in /prw/PRW_DB_ora11g/prw_ora_dbw0_ora11g_1600_04-30-14.out
Wed Apr 30 09:32:53 CST 2014: Getting stack for ora_lgwr_ora11g 1602 using short_stack in /prw/PRW_DB_ora11g/prw_ora_lgwr_ora11g_1602_04-30-14.out
Wed Apr 30 09:32:56 CST 2014: Getting stack for ora_ckpt_ora11g 1604 using short_stack in /prw/PRW_DB_ora11g/prw_ora_ckpt_ora11g_1604_04-30-14.out
Wed Apr 30 09:32:57 CST 2014: Getting stack for ora_smon_ora11g 1606 using short_stack in /prw/PRW_DB_ora11g/prw_ora_smon_ora11g_1606_04-30-14.out
Wed Apr 30 09:32:59 CST 2014: Getting stack for ora_rvwr_ora11g 1623 using short_stack in /prw/PRW_DB_ora11g/prw_ora_rvwr_ora11g_1623_04-30-14.out
Wed Apr 30 09:33:02 CST 2014: Getting stack for ora_arc0_ora11g 1626 using short_stack in /prw/PRW_DB_ora11g/prw_ora_arc0_ora11g_1626_04-30-14.out
Wed Apr 30 09:33:03 CST 2014: Getting stack for ora_arc1_ora11g 1629 using short_stack in /prw/PRW_DB_ora11g/prw_ora_arc1_ora11g_1629_04-30-14.out
Wed Apr 30 09:33:05 CST 2014: Getting stack for ora_arc2_ora11g 1631 using short_stack in /prw/PRW_DB_ora11g/prw_ora_arc2_ora11g_1631_04-30-14.out
Wed Apr 30 09:33:08 CST 2014: Getting stack for ora_arc3_ora11g 1633 using short_stack in /prw/PRW_DB_ora11g/prw_ora_arc3_ora11g_1633_04-30-14.out
Wed Apr 30 09:33:09 CST 2014: Getting stack for ora_fg_ora11g 1988 using short_stack in /prw/PRW_DB_ora11g/prw_ora_fg_ora11g_1988_04-30-14.out
Wed Apr 30 09:33:11 CST 2014: Getting stack for ora_fg_ora11g 2012 using short_stack in /prw/PRW_DB_ora11g/prw_ora_fg_ora11g_2012_04-30-14.out
Wed Apr 30 09:33:14 CST 2014: Stacks complete after 26 seconds (12 stacks - average seconds: 2)
Wed Apr 30 09:33:14 CST 2014: Cycle complete after 52 seconds
Wed Apr 30 09:33:14 CST 2014: Sleeping 8 seconds until time to run again per the INTERVAL setting (60 seconds)
################################################################################
Wed Apr 30 09:33:22 CST 2014: Collecting SQL Data for SID ora11g
Wed Apr 30 09:33:24 CST 2014: ..SQL: Running SQLvwaitchains.sql on SID ora11g
Wed Apr 30 09:33:27 CST 2014: ..SQL: Running SQLvsessionwait.sql on SID ora11g
Wed Apr 30 09:33:27 CST 2014: ..SQL: Running SQLvlock.sql on SID ora11g
Wed Apr 30 09:33:28 CST 2014: ..SQL: Running SQLvlatchholder.sql on SID ora11g
Wed Apr 30 09:33:31 CST 2014: Saving SQL report data for SID ora11g
Wed Apr 30 09:33:35 CST 2014: Instance ora11g Suspected final blocker is: Process: 1988 SID: 35 SER#: 45 INST ora11g INST #: 1
Wed Apr 30 09:33:35 CST 2014: ora11g Waitchains SessionCount:2-Instance:1
Wed Apr 30 09:33:35 CST 2014: Adding these processes to the process list for SID ora11g if they are not there already:
UID PID PPID C STIME TTY TIME CMD
oracle 1988 1 0 09:29 ? 00:00:00 oracleora11g (LOCAL=NO)
oracle 2012 1 0 09:31 ? 00:00:00 oracleora11g (LOCAL=NO)
Wed Apr 30 09:33:36 CST 2014: Collecting process specific SQLs for SID ora11g
Wed Apr 30 09:33:38 CST 2014: ..SQL: Running SQLsqltext.sql on SID ora11g
Wed Apr 30 09:33:39 CST 2014: ..SQL: Running SQLash.sql on SID ora11g
Wed Apr 30 09:33:41 CST 2014: SQL collection complete after 19 seconds (6 SQLs - average seconds: 3)
Wed Apr 30 09:33:42 CST 2014: Getting stack for ora_pmon_ora11g 1582 using short_stack in /prw/PRW_DB_ora11g/prw_ora_pmon_ora11g_1582_04-30-14.out
Wed Apr 30 09:33:44 CST 2014: Getting stack for ora_dbw0_ora11g 1600 using short_stack in /prw/PRW_DB_ora11g/prw_ora_dbw0_ora11g_1600_04-30-14.out
Wed Apr 30 09:33:45 CST 2014: Getting stack for ora_lgwr_ora11g 1602 using short_stack in /prw/PRW_DB_ora11g/prw_ora_lgwr_ora11g_1602_04-30-14.out
Wed Apr 30 09:33:47 CST 2014: Getting stack for ora_ckpt_ora11g 1604 using short_stack in /prw/PRW_DB_ora11g/prw_ora_ckpt_ora11g_1604_04-30-14.out
Wed Apr 30 09:33:49 CST 2014: Getting stack for ora_smon_ora11g 1606 using short_stack in /prw/PRW_DB_ora11g/prw_ora_smon_ora11g_1606_04-30-14.out
Wed Apr 30 09:33:52 CST 2014: Getting stack for ora_rvwr_ora11g 1623 using short_stack in /prw/PRW_DB_ora11g/prw_ora_rvwr_ora11g_1623_04-30-14.out
Wed Apr 30 09:33:53 CST 2014: Getting stack for ora_arc0_ora11g 1626 using short_stack in /prw/PRW_DB_ora11g/prw_ora_arc0_ora11g_1626_04-30-14.out
Wed Apr 30 09:33:54 CST 2014: Getting stack for ora_arc1_ora11g 1629 using short_stack in /prw/PRW_DB_ora11g/prw_ora_arc1_ora11g_1629_04-30-14.out
Wed Apr 30 09:33:57 CST 2014: Getting stack for ora_arc2_ora11g 1631 using short_stack in /prw/PRW_DB_ora11g/prw_ora_arc2_ora11g_1631_04-30-14.out
Wed Apr 30 09:33:59 CST 2014: Getting stack for ora_arc3_ora11g 1633 using short_stack in /prw/PRW_DB_ora11g/prw_ora_arc3_ora11g_1633_04-30-14.out
Wed Apr 30 09:34:00 CST 2014: Getting stack for ora_fg_ora11g 1988 using short_stack in /prw/PRW_DB_ora11g/prw_ora_fg_ora11g_1988_04-30-14.out
Wed Apr 30 09:34:03 CST 2014: Getting stack for ora_fg_ora11g 2012 using short_stack in /prw/PRW_DB_ora11g/prw_ora_fg_ora11g_2012_04-30-14.out
Wed Apr 30 09:34:07 CST 2014: Stacks complete after 26 seconds (12 stacks - average seconds: 2)
Wed Apr 30 09:34:07 CST 2014: Cycle complete after 45 seconds
Wed Apr 30 09:34:07 CST 2014: Sleeping 15 seconds until time to run again per the INTERVAL setting (60 seconds)
################################################################################
Wed Apr 30 09:34:22 CST 2014: Collecting SQL Data for SID ora11g
Wed Apr 30 09:34:24 CST 2014: ..SQL: Running SQLvwaitchains.sql on SID ora11g
Wed Apr 30 09:34:26 CST 2014: ..SQL: Running SQLvsessionwait.sql on SID ora11g
Wed Apr 30 09:34:27 CST 2014: ..SQL: Running SQLvlock.sql on SID ora11g
Wed Apr 30 09:34:28 CST 2014: ..SQL: Running SQLvlatchholder.sql on SID ora11g
Wed Apr 30 09:34:28 CST 2014: Housekeeper: Cleaning up old files and directories > 7 days old
Wed Apr 30 09:34:31 CST 2014: Saving SQL report data for SID ora11g
Wed Apr 30 09:34:35 CST 2014: Instance ora11g Suspected final blocker is: Process: 1988 SID: 35 SER#: 45 INST ora11g INST #: 1
Wed Apr 30 09:34:36 CST 2014: ora11g Waitchains SessionCount:2-Instance:1
Wed Apr 30 09:34:36 CST 2014: Adding these processes to the process list for SID ora11g if they are not there already:
UID PID PPID C STIME TTY TIME CMD
oracle 1988 1 0 09:29 ? 00:00:00 oracleora11g (LOCAL=NO)
oracle 2012 1 0 09:31 ? 00:00:00 oracleora11g (LOCAL=NO)
在上面日志中，Procwatcher脚本进行了几项工作：首先是对后台Instance进行分析，确定当前服务器或者Cluster中有哪些需要处理。第二是定位Server Process中存在等待阻塞的进程。第三是通过几个时间段的分析Sampling，而不是一次性的确定。若干次的Dump都会存放在相同的结果文件中。