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]#