I wanted to understand where an app was spending time. I couldn\u2019t get the granularity I needed from New Relic, and SSMS aggregated the data so I couldn\u2019t see it. I came up with what is below, admittedly, somewhat obtuse, but it works.<\/p>\n
1.\tStart strace against the JVM (in this case, could be any client software)<\/p>\n
\r\nstrace -f -p 15078 -e trace=sendto,recvfrom,write -tt -s 8192 -o t.txt &\r\n<\/pre>\n2.\tAfter waiting a couple of minutes, detach strace from the parent process by issuing CTRL-C
\n3.\tThe SQL Server JDBC driver inserts null characters between each character in a SQL string, so we can\u2019t simply search for SELECT. To resolve this, edit the output file to convert this to empty spaces<\/p>\n\r\nsed -i 's\/\\\\0\/\/g' t.txt\r\n<\/pre>\n4.\tCreate the following awk script file<\/p>\n
\r\n{\r\n if ($0 ~ \"sendto.*SELECT\") {\r\n split($3,t,\"(\")\r\n split(t[2],s,\",\")\r\n socket=s[1]\r\n if (socket in sockets) {\r\n }\r\n else {\r\n sockets[socket]=substr($2,1,length($2)-3)\r\n }\r\n }\r\n else if ($3 ~ \"recvfrom\" && $4 !~ \"unfinished\") {\r\n split($3,t,\"(\")\r\n split(t[2],s,\",\")\r\n socket=s[1]\r\n if (socket in sockets) {\r\n split(sockets[socket],r,\".\")\r\n split($2,q,\".\")\r\n\r\n time=substr(sockets[socket],1,length($2)-3)\r\n split(time,time_arr,\/:|\\.\/ )\r\n time_ms = (time_arr[1] * 3600 + time_arr[2] * 60 + time_arr[3]) * 1000 + time_arr[4]\r\n\r\n time=substr($2,1,length($2)-3)\r\n split(time,time_arr,\/:|\\.\/ )\r\n time_now = (time_arr[1] * 3600 + time_arr[2] * 60 + time_arr[3]) * 1000 + time_arr[4]\r\n print sockets[socket],$2,time_now-time_ms\r\n delete sockets[socket]\r\n }\r\n }\r\n}\r\n<\/pre>\n5.\tRun 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.<\/p>\n
\r\n[cmhlpstorapi01 tomcat]# awk -f parseSQL.awk t.txt | awk '$3 > 8000' | wc -l\r\n604\r\n[cmhlpstorapi01 tomcat]# awk -f parseSQL.awk t.txt | awk '$3 <= 8000' | wc -l\r\n2296\r\n[cmhlpstorapi01 tomcat]#\r\n<\/pre>\n6.\tBelow is the raw output if interested\u2026<\/p>\n
\r\n[cmhlpstorapi01 tomcat]# awk -f parseSQL.awk t.txt | tail -10\r\n09:47:06.204 09:47:06.253117 49\r\n09:46:51.294 09:47:06.297883 15003\r\n09:47:00.512 09:47:06.313016 5801\r\n09:47:06.174 09:47:06.313589 139\r\n09:47:05.883 09:47:06.373515 490\r\n09:47:06.253 09:47:06.397725 144\r\n09:46:50.200 09:47:06.430130 16230\r\n09:47:06.467 09:47:06.468071 1\r\n09:47:06.492 09:47:06.570720 78\r\n09:47:06.572 09:47:06.572948 0\r\n[cmhlpstorapi01 tomcat]#\r\n<\/pre>\n","protected":false},"excerpt":{"rendered":"I wanted to understand where an app was spending time. I couldn\u2019t get the granularity I needed from New Relic, and SSMS aggregated the data so I couldn\u2019t see it. I came up with what is below, admittedly, somewhat obtuse,…<\/p>\n