Poor man’s way to calculate query time from app server

I wanted to understand where an app was spending time. I couldn’t get the granularity I needed from New Relic, and SSMS aggregated the data so I couldn’t see it. I came up with what is below, admittedly, somewhat obtuse, but it works.

1. Start strace against the JVM (in this case, could be any client software)

strace -f -p 15078 -e trace=sendto,recvfrom,write -tt -s 8192 -o t.txt &

2. After waiting a couple of minutes, detach strace from the parent process by issuing CTRL-C
3. The SQL Server JDBC driver inserts null characters between each character in a SQL string, so we can’t simply search for SELECT. To resolve this, edit the output file to convert this to empty spaces

sed -i 's/\\0//g' t.txt

4. Create the following awk script file

{
  if ($0 ~ "sendto.*SELECT") {
    split($3,t,"(")
    split(t[2],s,",")
    socket=s[1]
    if (socket in sockets) {
    }
    else {
      sockets[socket]=substr($2,1,length($2)-3)
    }
  }
  else if ($3 ~ "recvfrom" && $4 !~ "unfinished") {
    split($3,t,"(")
    split(t[2],s,",")
    socket=s[1]
    if (socket in sockets) {
      split(sockets[socket],r,".")
      split($2,q,".")

      time=substr(sockets[socket],1,length($2)-3)
      split(time,time_arr,/:|\./ )
      time_ms = (time_arr[1] * 3600 + time_arr[2] * 60 + time_arr[3]) * 1000 + time_arr[4]

      time=substr($2,1,length($2)-3)
      split(time,time_arr,/:|\./ )
      time_now = (time_arr[1] * 3600 + time_arr[2] * 60 + time_arr[3]) * 1000 + time_arr[4]
      print sockets[socket],$2,time_now-time_ms
      delete sockets[socket]
    }
  }
}

5. Run it against the strace output file noted above. What is below simply counts those statements that took less than eight seconds, and those that took more. You could create a histogram or graph it any way you like. The SQL statements are also in the strace output file, although a little hard to parse programmatically. This is probably sufficient for most people, though.

[cmhlpstorapi01 tomcat]# awk -f parseSQL.awk t.txt | awk '$3 > 8000' | wc -l
604
[cmhlpstorapi01 tomcat]# awk -f parseSQL.awk t.txt | awk '$3 <= 8000' | wc -l
2296
[cmhlpstorapi01 tomcat]#

6. Below is the raw output if interested…

[cmhlpstorapi01 tomcat]# awk -f parseSQL.awk t.txt | tail -10
09:47:06.204 09:47:06.253117 49
09:46:51.294 09:47:06.297883 15003
09:47:00.512 09:47:06.313016 5801
09:47:06.174 09:47:06.313589 139
09:47:05.883 09:47:06.373515 490
09:47:06.253 09:47:06.397725 144
09:46:50.200 09:47:06.430130 16230
09:47:06.467 09:47:06.468071 1
09:47:06.492 09:47:06.570720 78
09:47:06.572 09:47:06.572948 0
[cmhlpstorapi01 tomcat]#