Using awk to extract bind variable values from a trace file

While troubleshooting a high CPU utilization problem recently, I found that half the sessions using a given database service were using a high amount of CPU, while the other were using a normal amount. Since I knew they were each running the exact same code, the logical conclusion was that the data differed. I ended up enabling a 10046 event trace on each session, and reviewing the trace files to see if the data was different. It turned out that it was, but it was a a painful process to go through each raw trace file and try to line up the bind variables to see if there were any repeating patterns, or differences. As such, I wrote the following awk script to assist with this.

All it does is take a SQL statement in which you are interested, and then searches each BIND section each time one is encountered for only that statement (or cursor#, more specifically). It then totals the number of times a given variable was used.

In this case, I wanted the SQL statement that began with “SELECT WORK_ID,”, and I was looking for bind variables for this statement that had the value 0362-4331.

#!/bin/awk -f

BEGIN {
  SQL="^SELECT WORK_ID,"
  BIND="0362-4331"
}

{
  if ($0 ~ "^PARSING") {
    B=$4;
    sub("#","",B);
    getline;
    if ($0 ~ SQL) {
      C=B;
    }
  }
  else if ($0 ~ "BINDS #" && $0 !~ "BINDS #"C) {
    looking = 0;
  }
  else if (length(C) > 0 && $0 ~ "BINDS #"C) {
    looking = 1;
  }
  else if ($0 ~ "value=" && looking == 1 && $0 ~ BIND) {
    s[$0]+=1;
  }
}

END {
  for (i in s) {
    print i,s[i];
  }
}

You can also use what is below to extract the values and a count of each in a given BIND position for a given SQL statement. All you need to do is pass the SQL statement for which to search, and the position in the bind list. To get the “BIND” awk variable value, you will need to look at the raw tracefile.

#!/bin/awk -f
#----------------------------------------------------------------------------------
#Author:        Steve Howard
#Date:          November 16, 2011
#Purpose:       Extract bind variable values from a 10046 trace file. 
#----------------------------------------------------------------------------------

BEGIN {
  if (ARGC != 4) {
    print "Usage:",ARGV[0]," -f script_name tracefile_name \"query_for_which_to_search\" \"BindNumber\""
    exit(1)
  }
  start = systime()
  SQL=ARGV[2]
  BIND=ARGV[3]
  ARGC=2
}

{
  if ($0 ~ "^PARSING") {
    B=$4;
    sub("#","",B);
    getline;
    if ($0 ~ SQL) {
      C=B;
    }
    else if (C == B && $0 !~ SQL) {
      C=-1;
    }
  }
  else if ($0 ~ "BINDS #" && $0 !~ "BINDS #"C) {
    looking = 0;
  }
  else if (length(C) > 0 && $0 ~ "BINDS #"C) {
    looking = 1;
  }
  else if ($0 ~ BIND && looking == 1) {
    looking=2;
  }
  else if ($0 ~ "value=" && looking == 2) {
    sub("value=","",$0)
    s[$0]++;
    looking=0;
  }
}
 
END {
  for (i in s) {
    printf ("%-50s %d\n", i,s[i])
  }
  printf("\nProcessed %d lines in %d seconds.\n",NR,systime() - start)
}

After making the script executable, you can call what is above with the command line shown below (changing the trace file, SQL for which to search, and Bind#, of course).

./binds.awk OATEST_ora_17563710.trc "select longname from javasnm" "Bind#0"