stapora.stp

#! /usr/bin/env stap
#
# stapora.stp
#
# This script monitor the cpu and wait event of an oracle session
# Usage:  stap -v stapora.stp  --all-modules -x  "spid"  "refresh_time(sec)" "wait_event_snap_time(msec)"
#
# Add the following line to translate wait event# to event_name (code developed by Luca Canali ): | sed -f eventsname.sed
# To generate "eventsname.sed" run http://canali.web.cern.ch/canali/res/All_Files/stap_scripts/eventsname.sql
#
#
# This script contains excerpt of code developed by : 
#   Jason Baron  and  Josh Stone :  https://sourceware.org/systemtap/examples/process/schedtimes.stp
#   Luca Canali  : http://externaltable.blogspot.com/2014/09/systemtap-into-oracle-for-fun-and-profit.html
#
# Author : Hatem Mahmoud <h.mahmoud87@gmail.com>
# BLOG 	 : https://mahmoudhatem.wordpress.com
#
# Version stapora 1.0 BETA
# Note: this is an experimental script, use at your own risk
#
# Functionality :
#    -Top wait events
#    -Wait events histograms
#    -Time spent on the run queue
#    -IO wait time
#    -Top kernel function
#    -Top user function
#    -Consistent Read by object
#    -Consistent Read elapsed time and cpu time
#    -Number of context switches



global DEAD=-1, RUNNING=1, QUEUED=2, SLEEPING=3
global kernel_func_call,user_func_call, pcount,sch_switch
global run_time, queued_time, sleep_time, iowait_time
global pid_state
global sys_time ,user_time
global previous_timestamp,prev_sys_time,prev_user_time
global obj_cr,previous_cr_timestamp,dur_cr,in_cr_function,dur_cr_not_cpu,previous_cr_not_cpu_timestamp
global pid_in_iowait
global pid_iowait_count
global session_addr = 0
global session_id
global session_waits
global total_samples
global event_num
global eventlatency[2000]



/*
* Replace by the output of the folowing query to capture the precise offset
* set linesize 190 pagesize 0;
* select 'global ' ||  c.kqfconam ||' = ' || c.kqfcooff  from x$kqfco c, x$kqfta t
* where t.indx = c.kqfcotab
* and t.kqftanam='X$KSUSECST'
* and c.kqfconam in ('KSUSSTIM','KSUSENUM','KSUSSOPC')
* order by c.kqfcooff;
*/

global KSUSSOPC = 5826
global KSUSSTIM = 5856
global KSUSENUM = 5920

/*
* You have to use the following query to determine interesting where location to probe for and replace them in 
* "( s64_arg(4) == 95 )":
* SELECT indx 
*   FROM x$ksllw
*  WHERE     KSLLWLBL = 'session ptr'
*       AND KSLLWNAM like '%set busy%'
*        AND indx IN (SELECT indx
*                       FROM x$kslwsc
*                      WHERE KSLLASNAM = 'session idle bit');
*/

probe process("oracle").function("ksl_get_shared_latch") {
  if (pid() == target() && session_addr == 0 && ( s64_arg(4) == 95 ) ) {
    session_addr =  s64_arg(3)
    printf("Session initialized %d\n",pointer_arg(3))
  }
}


@define in_iowait(task) %(
  @choose_defined(@task->in_iowait,
    (pid_in_iowait ? pid_in_iowait-- : 0))
%)

@define clear_iowait(rq, task) %(
    if (!@defined(@task->in_iowait))
      pid_iowait_count = @nr_iowait(@rq)
%)

@define set_iowait(rq, task) %(
    if (!@defined(@task->in_iowait))
      pid_in_iowait = (@nr_iowait(@rq) > pid_iowait_count)
%)

@define nr_iowait(rq) %(
    atomic_read(&@cast(@rq, "rq")->nr_iowait)
%)


function timestamp()
{
  return gettimeofday_us()
}

probe process("oracle").function("kcbgtcr")
	 {
	if (pid() == target()) {  
		in_cr_function=1		
		obj_cr[user_int32(u64_arg(1)+8)/1] <<< 1
		previous_cr_timestamp = timestamp()
				
   }
}


%(kernel_v>="3.10" %?
probe process("oracle").function("kcbgtcr").return
	 {
   if (pid() == target()) {  
        in_cr_function=0
		dur_cr <<< timestamp() - previous_cr_timestamp
   }
}
%)

function update_times(now)
{
  delta = now - previous_timestamp
  previous_timestamp = now

  if ((state = pid_state) > 0) {
    if (state == SLEEPING)
      sleep_time += delta
    else if (state == QUEUED)
      queued_time += delta
    else if (state == RUNNING)
      run_time += delta
  }

  return delta
}

probe timer.profile { 
if (target() == pid())
{
  pcount <<< 1
  if ( user_mode() == 1) 
  {
	user_func_call[usymname(ustack(0))] <<< 1	
  }
  else
  {
	kernel_func_call[symname(stack(0))] <<< 1	
  }
 }
 }
 
probe timer.ms($2) { 
 
# Profiling wait events
if ( session_addr > 0 )
{   
   if (pid_state == RUNNING) //If session is in the runqueue then it'is the same wait event
   {
   sess_id = user_uint16(session_addr + KSUSENUM)
   wait_time = user_uint32(session_addr + KSUSSTIM)
   event_num = user_uint32(session_addr + KSUSSOPC)
   //If succefuly captured wait event number 
   if (event_num != 0 )
   {
   total_samples <<< 1

       session_id = sess_id
       if (wait_time == 0 )
       {
        session_waits[event_num] <<< 1
       }
       else
       {
        session_waits[-1] <<< 1
       }
    }	   
   } 
   else 
   {  
      session_waits[event_num] <<< 1
	  total_samples <<< 1
   }
}

}

probe process("oracle").function("kskthewt") {
   # Wait events histogram
	if ( session_addr > 0 )
	{   

	ksuseopc = user_uint32(session_addr + KSUSSOPC)
	ksusetim = user_uint32(session_addr + KSUSSTIM)
	eventlatency[ksuseopc] <<< ksusetim
   
   }
}

probe scheduler.ctxswitch
{
  // Task $prev is scheduled off this cpu
  if ($prev->pid == target()) { 
  
   if (in_cr_function == 1)
   {
      previous_cr_not_cpu_timestamp=timestamp()
   }
    //check the last wait event before going to the runqueue
   if ( session_addr > 0 )
   {
     event_num = user_uint32(session_addr + KSUSSOPC)
   }
  
    sch_switch <<< cpu()
	
    state = $prev->state
    update_times(timestamp())

	if(@defined($prev->utime)) {
	
	//Calculate user_time and cpu_time delta using cpu clock tick
	user_time <<< ($prev->utime - prev_user_time)
    prev_user_time=$prev->utime
	sys_time <<< ($prev->stime - prev_sys_time)
    prev_sys_time=$prev->stime
	}
	
    if (state > 0) {
      @set_iowait($rq, $prev)
      pid_state = SLEEPING
    } else if (state == 0) {
      pid_state = QUEUED
    } else {
      pid_state = DEAD
    }
  }

  // Task $next is scheduled onto this cpu
  if ($next->pid == target() ) {
    
	 if (in_cr_function == 1)
   {
      dur_cr_not_cpu = (timestamp() - previous_cr_not_cpu_timestamp ) + dur_cr_not_cpu    
   }
    
	sch_switch <<< cpu()  
    
	update_times(timestamp())
    @clear_iowait($rq, $next)
    pid_state = RUNNING
  }
}

probe scheduler.wakeup
{
  // Task $p is awakened
  if ($p->pid == target()) {  
    delta = update_times(timestamp())
    if (pid_state == SLEEPING && @in_iowait($p)) {
      iowait_time += delta
    }
    pid_state = QUEUED
  }
}


probe timer.s($1)
{
	printf ("\n====================================================================================\n")	
	printf ("================================= StapOra V1.0 BETA ================================")	
	printf ("\n====================================================================================\n")	
    	printf ("\n%6s : %16s %16s %20s %16s %16s %10s %10s \n\n",
         "pid", "run(us)", "sleep(us)", "iowait(us)",
         "queued(us)", "total(us)","user_time(%)","sys_time(%)")
	update_times(timestamp())
	
	
	ratio_sys=10000 * @sum(sys_time) /  ( @sum(user_time) + @sum(sys_time) +1 )
	ratio_user=10000 * @sum(user_time) /  ( @sum(user_time) + @sum(sys_time) +1 )
	ratio_run_time=10000 * run_time /(run_time + sleep_time + queued_time +1)
	ratio_sleep_time=10000 * sleep_time /(run_time + sleep_time + queued_time +1)
	ratio_iowait_time=10000 *  iowait_time/(run_time + sleep_time + queued_time +1)
	ratio_queued_time=10000 * queued_time /(run_time + sleep_time + queued_time +1)
    
	printf("%6d : %10d(%2d.%02d %s) %10d(%2d.%02d %s) %5d(%2d.%02d %s) %10d(%2d.%02d %s) %10d %8d.%02d %8d.%02d \n",target(),
           run_time,ratio_run_time/100,ratio_run_time%100,"%",sleep_time,ratio_sleep_time/100,ratio_sleep_time%100,"%", iowait_time,ratio_iowait_time/100,ratio_iowait_time%100,"%",queued_time,
          ratio_queued_time/100,ratio_queued_time%100,"%", (run_time + sleep_time + queued_time),ratio_user/100,ratio_user%100,ratio_sys/100,ratio_sys%100)
		  
    
	
      printf ("\n---------------------------------------------------------\n")
      printf ("------- Oracle wait events/CPU (CPU WAIT)----------------\n")
      printf ("---------------------------------------------------------\n")
	  if ( session_addr > 0 )
       {
	   printf("Total samples : %d\n",@count(total_samples))
       foreach ([w] in session_waits- limit 5) {
              event_ratio = 10000 * @count(session_waits[w]) / @count(total_samples)
              if ( w == -1 ) {
                printf ("%2d.%02d %s samples CPU/CPU WAIT   \n",event_ratio/100,event_ratio%100,"%")
              } else {
                printf ("%2d.%02d %s samples  event#=%ld  \n",event_ratio/100,event_ratio%100,"%",w)
              }
        }
        delete session_waits
        delete total_samples
      }
      else
      {
        printf("No wait events captured (Session not initialized yet)\n");
      }
    printf ("\n---------------------------------------------------------\n")
    printf ("------- Oracle wait events histograms (microsec)-----------\n")
    printf ("---------------------------------------------------------\n")
	
	foreach ([event] in eventlatency) {
       printf("Latency histogram for event#=%d\n",event)
       print(@hist_log(eventlatency[event]))
    }

	
	printf ("\n--- %d samples recorded:\n", @count(pcount))

	printf ("---------------------------------------------------------\n")	
	printf ("------- Top 5 Kernel space Functions --------------------\n")	
	printf ("---------------------------------------------------------\n")	
	foreach ([p] in kernel_func_call- limit 5) {
		printf ("%d hits : %s \n\n", @count(kernel_func_call[p]),p)
	}
	
	printf ("---------------------------------------------------------\n")	
	printf ("------- Top 5 user space Functions ----------------------\n")
	printf ("---------------------------------------------------------\n")	
	foreach ([p] in user_func_call- limit 5) {
		printf ("%d hits : %s \n\n", @count(user_func_call[p]),  p)
	} 
	printf ("---------------------------------------------------------\n")	
	printf ("------- Scheduler Switches per CPU ----------------------\n")
  	printf ("---------------------------------------------------------\n")	
	if( @count(sch_switch) > 0 ) {
	print(@hist_linear(sch_switch, 0, 10, 1))
	}
	
	
	printf ("\n---------------------------------------------------------\n")	

	cr_ratio_run_time=10000 * (@sum(dur_cr)-dur_cr_not_cpu) /(run_time + 1 )
	cr_ratio_elapsed_time=10000 * @sum(dur_cr) /(run_time + sleep_time + queued_time +1) 
	
	printf("Total cr elapsed time : %6d (%2d.%02d %s from Total elapsed time) \n",@sum(dur_cr),cr_ratio_elapsed_time/100,cr_ratio_elapsed_time%100,"%")
	printf("Total cr cpu time     : %6d (%2d.%02d %s from Total cpu time)  \n",(@sum(dur_cr)-dur_cr_not_cpu),cr_ratio_run_time/100,cr_ratio_run_time%100,"%")
	
	printf ("---------------------------------------------------------\n")	
	printf ("------- Object number and cr I/O count ------------------\n")
	printf ("---------------------------------------------------------\n")
 	
	foreach ([m] in obj_cr+ ) {
		printf ("cr=%d obj_n=%d \n", @count(obj_cr[m]),  m)
	} 

	printf ("---------------------------------------------------------\n")	
	printf ("------- CR I/O duration hist(us) ------------------------\n")
	printf ("---------------------------------------------------------\n")	
    %(kernel_v>="3.10" %?
	if( @count(dur_cr) > 0 ) {
	print(@hist_log(dur_cr))
	}
	%:
	printf ("------- You need at least kernel version >= 3.10 --------\n")
	%)
  
	delete kernel_func_call
	delete user_func_call
	delete pcount
	delete sch_switch
	delete run_time 
	delete queued_time 
	delete sleep_time 
	delete iowait_time 
	delete sys_time 
	delete user_time 
	delete obj_cr
	delete dur_cr
	delete dur_cr_not_cpu
	delete eventlatency

}