Drilling into Session Detail from the Operating System – On the Windows Platform 2

9 01 2010

January 9, 2010

In the earlier post, you saw a script output that looked something like the following:

1/8/2010 12:57:56 PM Processes: 73 Threads: 861 C. Switches: 35972 Q. Length: 6
Instance: c:\oracle\product\10.2.0\db_1\bin\ORACLE.EXE OR10
 User Time: 9.33S Sys  Time: 25.19S Memory: 141.11MB Page File: 0.63MB
  Handle: 1444 User Time: 9.34S Sys  Time: 25.5S ElapsedTime: 70S Priority: 8 ThreadState: In Run Queue

Instance: c:\oracle\product\11.1.0\db_1\bin\ORACLE.EXE OR11
 User Time: 103.9S Sys  Time: 0.13S Memory: 442.42MB Page File: 0.67MB
  Handle: 3520 User Time: 34.13S Sys  Time: 0.02S ElapsedTime: 69S Priority: 8 ThreadState: Running
   PID:18 SPID:3520 SID:146 SERIAL#:4 USERNAME:TESTUSER MACHINE:HOME.NET\AIRFORCE-3 PROGRAM:sqlplus.exe
   DECLARE   i NUMBER := 0;   STime DATE := SYSDATE; BEGIN   WHILE (SYSDATE - STime) < 0.006945 LOOP     i := i + + 0.000001;   End Loop; End;

    SQL_ID  cujkdbu2npk0x, child number 0

    DECLARE   i NUMBER := 0;   STime DATE := SYSDATE; BEGIN   WHILE
    (SYSDATE - STime) < 0.006945 LOOP     i := i + + 0.000001;   End Loop;
    End;

    NOTE: cannot fetch plan for SQL_ID: cujkdbu2npk0x, CHILD_NUMBER: 0
          Please verify value of SQL_ID and CHILD_NUMBER;
          It could also be that the plan is no longer in cursor cache (check v$sql_plan)

  Handle: 2152 User Time: 34.04S Sys  Time: 0S ElapsedTime: 69S Priority: 8 ThreadState: In Run Queue
   PID:19 SPID:2152 SID:145 SERIAL#:12 USERNAME:TESTUSER MACHINE:HOME.NET\AIRFORCE-3 PROGRAM:sqlplus.exe
   INSERT INTO T1 SELECT   CEIL(ABS(SIN(ROWNUM/9.9999)*10000)),   'This is the long description for this number '|| TO_CHAR(CEIL(ABS(SIN(ROWNUM/9.9999)*10000)))...

    SQL_ID  6hxcgpp1rd1ag, child number 0
    -------------------------------------
    INSERT INTO T1 SELECT   CEIL(ABS(SIN(ROWNUM/9.9999)*10000)),   'This is
    the long description for this number '||
    TO_CHAR(CEIL(ABS(SIN(ROWNUM/9.9999)*10000))) FROM   (SELECT     ROWNUM
    RN   FROM     DUAL   CONNECT BY     LEVEL<=10000),   (SELECT     ROWNUM
    RN   FROM     DUAL   CONNECT BY     LEVEL<=10000)

    Plan hash value: 643243249

    -----------------------------------------------------------------------------------
    | Id  | Operation                          | Name | Rows  | Cost (%CPU)| Time     |
    -----------------------------------------------------------------------------------
    |   0 | INSERT STATEMENT                   |      |       |     4 (100)|          |
    |   1 |  LOAD TABLE CONVENTIONAL           |      |       |            |          |
    |   2 |   COUNT                            |      |       |            |          |
    |   3 |    MERGE JOIN CARTESIAN            |      |     1 |     4   (0)| 00:00:01 |
    |   4 |     VIEW                           |      |     1 |     2   (0)| 00:00:01 |
    |   5 |      COUNT                         |      |       |            |          |
    |   6 |       CONNECT BY WITHOUT FILTERING |      |       |            |          |
    |   7 |        FAST DUAL                   |      |     1 |     2   (0)| 00:00:01 |
    |   8 |     BUFFER SORT                    |      |     1 |     4   (0)| 00:00:01 |
    |   9 |      VIEW                          |      |     1 |     2   (0)| 00:00:01 |
    |  10 |       COUNT                        |      |       |            |          |
    |  11 |        CONNECT BY WITHOUT FILTERING|      |       |            |          |
    |  12 |         FAST DUAL                  |      |     1 |     2   (0)| 00:00:01 |
    -----------------------------------------------------------------------------------

The above was echoed to the command line window and also written to a logging file.  So, how do we create this output?  Save the following on the root of the C:\ drive as CPUHighLoadProcesses.vbs:

Const adNumeric=131
Const adParamInput=1
Const adCmdText=1
Const adVarChar=200

Dim i                       'Loop counter for iterations
Dim j                       'Loop counter to find the previous stats for the thread
Dim intInstance             'Index to the instance statistics
Dim IntOldCSPerSec          'Previous value for Context Switches Per Second
Dim intOldProcesses         'Previous value for the number of processes
Dim intOldThreads           'Previous value for the number of threads
Dim strSQL                  'SQL to check WMI Win32_PerfRawData_PerfOS_System
Dim strSQL2                 'SQL to find the Oracle processes using WMI Win32_Process
Dim strSQL3                 'SQL to drill into the threads in the Oracle processes using WMI Win32_Thread
Dim strSQL4                 'SQL to find the Oracle session, SQL statement, and execution plan
Dim strOut                  'Data to be written to the text file
Dim strComputer             'Oracle database server name, or . for the current computer
Dim sglUMTime(20)           'User mode time in seconds for the Oracle instance
Dim sglKMTime(20)           'Kernel mode time in seconds for the Oracle instance
Dim sglWorkingSet(20)       'Working set memory size for the Oracle instance
Dim sglPageFileUsage(20)    'Page/swap file usage for the Oracle instance
Dim sglOUMTime(20)          'Previous user mode time in seconds for the Oracle instance
Dim sglOKMTime(20)          'Previous kernel mode time in seconds for the Oracle instance
Dim sglOldWorkingSet(20)    'Previous working set memory size for the Oracle instance
Dim sglOldPageFileUsage(20) 'Previous page/swap file usage for the Oracle instance
Dim objWMIService           'An object used to pass in the WMI calls
Dim colItems                'Collection of processes running on the server
Dim objItem                 'An individual process running on the server
Dim colThreads              'Collection of threads running in a process
Dim objThread               'An individual thread running in a process
Dim intThread               'Index to the previous values for the thread's statistics
Dim intThreadCount(20)      'Maximum previous thread index for the instance
Dim intThreadH(20,600)      'Thread handle
Dim sglTUMTime(20,600)      'User mode time in seconds for the thread
Dim sglTKMTime(20,600)      'Kernel mode time in seconds for the thread
Dim sglTETime(20,600)       'Elapsed time in seconds for the thread
Dim adsFile                 'ADO stream object used to write out the log file
Dim snpData                 'ADO recordset used to query V$SESSION/V$SQL
Dim comData                 'ADO command object used to permit passing in bind variables for the V$SESSION/V$SQL query
Dim snpDataPlan             'ADO recordset used to retrieve the execution plan for the session's SQL statement
dim comDataPlan             'ADO command object used to permit passing in bind variables for the execution plan
Dim dbDatabase              'ADO database connection object
Dim intCheckIterations      'Number of times to check the instances
Dim intDelayIterations      'Number of seconds to delay between iterations
Dim sglThreadBusyPercent    'Percentage of the seconds in the iteration delay does a session need to consume to be examined

Set snpData = CreateObject("ADODB.Recordset")
Set comData = CreateObject("ADODB.Command")
Set snpDataPlan = CreateObject("ADODB.Recordset")
Set comDataPlan = CreateObject("ADODB.Command")
Set dbDatabase = CreateObject("ADODB.Connection")

strUsername = "MyUsername"
strPassword = "MyPassword"
strDatabase = "MyDB"

intCheckIterations = 10
intDelayIterations = 60
sglThreadBusyPercent = 0.50  '50%

dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";"
dbDatabase.Open

'Should verify that the connection attempt was successful, but I will leave that for someone else to code
On Error Resume Next  'Allow continuing the script if an error happens

'Prepare the ADO Stream to write the data to the text file
Set adsFile = CreateObject("ADODB.Stream")
adsFile.Type = 2
adsFile.Charset = "iso-8859-1"
adsFile.Open

'Prepare the SQL statements
strSQL = "SELECT * FROM Win32_PerfRawData_PerfOS_System"
strSQL2 = "SELECT * FROM Win32_Process Where Name like 'Oracle%'"
strSQL3 = "SELECT * FROM Win32_Thread Where ProcessHandle="

With comData
  strSQL4 = "SELECT" & VBCrLf
  strSQL4 = strSQL4 & "  P.PID," & VBCrLf
  strSQL4 = strSQL4 & "  P.SPID," & VBCrLf
  strSQL4 = strSQL4 & "  S.SID," & VBCrLf
  strSQL4 = strSQL4 & "  S.SERIAL#," & VBCrLf
  strSQL4 = strSQL4 & "  NVL(S.USERNAME,' ') USERNAME," & VBCrLf
  strSQL4 = strSQL4 & "  NVL(S.MACHINE,' ') MACHINE," & VBCrLf
  strSQL4 = strSQL4 & "  NVL(S.PROGRAM,' ') PROGRAM," & VBCrLf
  strSQL4 = strSQL4 & "  S.SQL_ID," & VBCrLf
  strSQL4 = strSQL4 & "  S.SQL_CHILD_NUMBER," & VBCrLf
  strSQL4 = strSQL4 & "  NVL(SQL.SQL_TEXT,' ') SQL_TEXT" & VBCrLf
  strSQL4 = strSQL4 & "FROM" & VBCrLf
  strSQL4 = strSQL4 & "  V$PROCESS P," & VBCrLf
  strSQL4 = strSQL4 & "  V$SESSION S," & VBCrLf
  strSQL4 = strSQL4 & "  V$SQL SQL" & VBCrLf
  strSQL4 = strSQL4 & "WHERE" & VBCrLf
  strSQL4 = strSQL4 & "  P.SPID=?" & VBCrLf
  strSQL4 = strSQL4 & "  AND P.ADDR=S.PADDR" & VBCrLf
  strSQL4 = strSQL4 & "  AND S.SQL_ID = SQL.SQL_ID(+)" & VBCrLf
  strSQL4 = strSQL4 & "  AND S.SQL_CHILD_NUMBER = SQL.CHILD_NUMBER(+)" & VBCrLf
  strSQL4 = strSQL4 & "ORDER BY" & VBCrLf
  strSQL4 = strSQL4 & "  S.USERNAME," & VBCrLf
  strSQL4 = strSQL4 & "  P.PROGRAM"

  .Parameters.Append .CreateParameter("spid", adNumeric, adParamInput, 12, 0)
  .CommandText = strSQL4
  .CommandType = adCmdText
  .CommandTimeout = 30
  .ActiveConnection = dbDatabase
End With

With comDataPlan
  strSQL4 = "SELECT" & VBCrLf
  strSQL4 = strSQL4 & "  *" & VBCrLf
  strSQL4 = strSQL4 & "FROM" & VBCrLf
  strSQL4 = strSQL4 & "  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(?, ?, 'TYPICAL'))" & VBCrLf

  .Parameters.Append .CreateParameter("sql_id", adVarchar, adParamInput, 20, "")
  .Parameters.Append .CreateParameter("child_number", adNumeric, adParamInput, 12, 0)
  .CommandText = strSQL4
  .CommandType = adCmdText
  .CommandTimeout = 30
  .ActiveConnection = dbDatabase
End With

strComputer = "."  ' the . indicates the local computer
Set objWMIService = GetObject("winmgmts:{impersonationLevel=impersonate}!\\" & strComputer & "\root\CIMV2")

IntOldCSPerSec = 0

For intInstance = 1 to 20
    sglOUMTime(intInstance) = 0
    sglOKMTime(intInstance) = 0
    sglOldWorkingSet(intInstance) = 0
    sglOldPageFileUsage(intInstance) = 0
    intThreadCount(intInstance) = 0
    intThreadH(intInstance,1) = 0
    sglTUMTime(intInstance,1) = 0
    sglTKMTime(intInstance,1) = 0
    sglTETime(intInstance,1) = 0
Next

For i = 1 to intCheckIterations 'Number of iterations
  Set colItems = objWMIService.ExecQuery(strSQL,"WQL",48)

  For Each objItem in colItems
    strOut = Now() & " Processes: " & objItem.Processes
    strOut = strOut & " Threads: " & objItem.Threads
    strOut = strOut & " C. Switches: " & objItem.ContextSwitchesPersec - IntOldCSPerSec
    strOut = strOut & " Q. Length: " & objItem.ProcessorQueueLength

    'Write to screen
    Wscript.Echo strOut

    'Write to log file
    adsFile.WriteText(strOut & vbCrLf)

    IntOldCSPerSec = objItem.ContextSwitchesPersec
    intOldProcesses = objItem.Processes
    intOldThreads = objItem.Threads
  Next

  Set colItems = Nothing
  Set colItems = objWMIService.ExecQuery(strSQL2,"WQL",48)

  intInstance = 0
  For Each objItem in colItems
    intInstance = intInstance + 1
    sglUMTime(intInstance) = Round(objItem.UserModeTime/10000000, 2)
    sglKMTime(intInstance) = Round(objItem.KernelModeTime/10000000, 2)
    sglWorkingSet(intInstance) = Round(objItem.WorkingSetSize/1048576, 2)
    sglPageFileUsage(intInstance) = Round(objItem.PageFileUsage/1048576, 2)

    strOut = "Instance: " & objItem.CommandLine & vbCrLf
    strOut = strOut & " User Time: " & Round(sglUMTime(intInstance) - sglOUMTime(intInstance),2) & "S"
    strOut = strOut & " Sys  Time: " & Round(sglKMTime(intInstance) - sglOKMTime(intInstance),2) & "S"
    strOut = strOut & " Memory: " & sglWorkingSet(intInstance) & "MB"
    strOut = strOut & " Page File: " & sglPageFileUsage(intInstance) & "MB" & vbCrLf

    Set colThreads = Nothing
    Set colThreads = objWMIService.ExecQuery(strSQL3 & cStr(objItem.ProcessID),"WQL",48)

    For Each objThread in colThreads
      'Find the statistics for thread from the previous iteration's statistics
      intThread = intThreadCount(intInstance) + 1
      For j = 1 to intThreadCount(intInstance)
        If intThreadH(intInstance,j) = objThread.Handle Then
          intThread = j
          Exit For
        End If
      Next

      If intThreadH(intInstance,intThread) = 0 Then
        'This is a new thread that was not captured before
        intThreadH(intInstance,intThread) = objThread.Handle
        If intThreadCount(intInstance) < intThread Then
          intThreadCount(intInstance) = intThread
        End If
      End If

      If (cSng(Round(objThread.UserModeTime/1000,2)-sglTUMTime(intInstance,intThread)+ _
          Round(objThread.KernelModeTime/1000,2)-sglTKMTime(intInstance,intThread)) / _
          intDelayIterations) >= sglThreadBusyPercent Then
        strOut = strOut & "  Handle: " & cStr(objThread.Handle)
        strOut = strOut & " User Time: " & Round((Round(objThread.UserModeTime/1000,2)-sglTUMTime(intInstance,intThread)),2) & "S"
        strOut = strOut & " Sys  Time: " & Round((Round(objThread.KernelModeTime/1000,2)-sglTKMTime(intInstance,intThread)),2) & "S"
        strOut = strOut & " ElapsedTime: " & Round((Round(objThread.ElapsedTime/1000,2)-sglTETime(intInstance,intThread)),2) & "S"
        strOut = strOut & " Priority: " & objThread.Priority
        strOut = strOut & " ThreadState:"
        Select Case objThread.ThreadState
          Case 0
            strOut = strOut & " Initialized"
          Case 1
            strOut = strOut & " In Run Queue"
          Case 2
            strOut = strOut & " Running"
          Case 3
            strOut = strOut & " Preparing to Run"
          Case 4
            strOut = strOut & " Terminated"
          Case 5
            strOut = strOut & " Idle"
          Case 6
            strOut = strOut & " Non-CPU Wait Event:"
            'See http://msdn.microsoft.com/en-us/library/aa394494(VS.85).aspx
            Select Case objThread.ThreadWaitReason
              Case 0
                strOut = strOut & "Executive"
              Case 1
                strOut = strOut & "FreePage"
              Case 2
                strOut = strOut & "PageIn"
              Case 3
                strOut = strOut & "PoolAllocation"
              Case 4
                strOut = strOut & "ExecutionDelay"
              Case 5
                strOut = strOut & "FreePage"
              Case 6
                strOut = strOut & "PageIn"
              Case 7
                strOut = strOut & "Executive"
              Case 8
                strOut = strOut & "FreePage"
              Case 9
                strOut = strOut & "PageIn"
              Case 10
                strOut = strOut & "PoolAllocation"
              Case 11
                strOut = strOut & "ExecutionDelay"
              Case 12
                strOut = strOut & "FreePage"
              Case 13
                strOut = strOut & "PageIn"
              Case 14
                strOut = strOut & "EventPairHigh"
              Case 15
                strOut = strOut & "EventPairLow"
              Case 16
                strOut = strOut & "LPCReceive"
              Case 17
                strOut = strOut & "LPCReply"
              Case 18
                strOut = strOut & "VirtualMemory"
              Case 19
                strOut = strOut & "PageOut"
              Case 20
                strOut = strOut & "Unknown"
              Case Else
                strOut = strOut & objThread.ThreadWaitReason
            End Select
          Case 7
            strOut = strOut & " Unknown"
          Case Else
            strOut = strOut & objThread.ThreadState
        End Select       

        strOut = strOut & vbCrLf
        comData("spid") = objThread.Handle
        Set snpData = comData.Execute

        If Not(snpData Is Nothing) Then
          If Not(snpData.EOF) Then
            strOut = strOut & "   PID:" & snpData("pid")
            strOut = strOut & " SPID:" & snpData("spid")
            strOut = strOut & " SID:" & snpData("sid")
            strOut = strOut & " SERIAL#:" & snpData("serial#")
            strOut = strOut & " USERNAME:" & snpData("username")
            strOut = strOut & " MACHINE:" & snpData("machine")
            strOut = strOut & " PROGRAM:" & snpData("program") & vbCrLf
            strOut = strOut & "   " & snpData("sql_text") & vbCrLf

            If Not(IsNull(snpData("sql_id"))) Then
              comDataPlan("sql_id") = snpData("sql_id")
              comDataPlan("child_number") = snpData("sql_child_number")
              Set snpDataPlan = comDataPlan.Execute

              If Not(snpDataPlan Is Nothing) Then
                strOut = strOut & vbCrLf
                Do While Not(snpDataPlan.EOF)
                  strOut = strOut & "    " & snpDataPlan(0) & vbCrLf
                  snpDataPlan.MoveNext
                Loop
                snpDataPlan.Close
              End If
              strOut = strOut & vbCrLf
            End If
          End If
          snpData.Close 
        End If
      End If

      sglTUMTime(intInstance,intThread) = Round(objThread.UserModeTime/1000,2)
      sglTKMTime(intInstance,intThread) = Round(objThread.KernelModeTime/1000,2)
      sglTETime(intInstance,intThread) = Round(objThread.ElapsedTime/1000,2)
    Next
    strOut = strOut & vbCrLf

    'Write to screen
    Wscript.Echo strOut

    'Write to log file
    adsFile.WriteText(strOut & vbCrLf)

    sglOUMTime(intInstance) = Round(objItem.UserModeTime/10000000, 2)
    sglOKMTime(intInstance) = Round(objItem.KernelModeTime/10000000, 2)
    sglOldWorkingSet(intInstance) = Round(objItem.WorkingSetSize/1048576, 2)
    sglOldPageFileUsage(intInstance) = Round(objItem.PageFileUsage/1048576, 2)
  Next

  'Wait intDelayIterations seconds before sampling again
  Wscript.Sleep intDelayIterations * 1000
Next

adsFile.SaveToFile "C:\CPUHighLoadProcesses.txt", 2 
adsFile.Close

dbDatabase.Close

Set snpData = Nothing
Set comData = Nothing
Set snpDataPlan = Nothing
Set comDataPlan = Nothing
Set dbDatabase = Nothing
Set adsFile = Nothing

If you decide to use the above script, test it very carefully.  There may be one or two typos or logic errors.  If you have administrator rights on the server, the script can be executed remotely (it does not need to be run directly on the server).  WMI queries are given a very low priority, so if the CPU run queue is long, the script may appear to hang for a long time.  To run the script, open a command line window and type:

cscript C:\CPUHighLoadProcesses.vbs

WMI queries are very powerful, as demonstrated by the above script.

Update: 1.5 hours before this blog article is scheduled to appear:

{RANT}

After I wrote the above script and this and the previous blog articles I stumbled upon the following very recent news article that states the following:
dba-oracle.com/t_display_background_processes_windows.htm

“In Windows, the ‘thread’ model is used, and Oracle dispatches his own background tasks within the domain of the single process, oracle.exe.  Hence, you cannot see any background processes from the Windows OS (but you can see listener process and parallel query slaves).”

OK, forget about my script, because the quote directly above states that it is not possible.  Someone please call Oracle Corp. and tell them that their Oracle Administration Assistant for Windows needs to be removed from the documentation because what it shows is simply not possible. Did I mention that I dislike being confused?

{/RANT}


Actions

Information

2 responses

12 01 2010
Greg

Very usable info.
Regards
Greg

2 02 2010
Blogroll Report 08/01/2009 – 15/01/2010 « Coskan’s Approach to Oracle

[…] Charles Hooper-Drilling into Session Detail from the Operating System – On the Windows Platform 2 […]

Leave a comment