{"id":1914,"date":"2012-02-23T18:33:23","date_gmt":"2012-02-23T23:33:23","guid":{"rendered":"http:\/\/appcrawler.com\/wordpress\/?p=1914"},"modified":"2013-04-19T19:39:43","modified_gmt":"2013-04-20T00:39:43","slug":"printing-execution-times-with-associated-bind-variables","status":"publish","type":"post","link":"http:\/\/appcrawler.com\/wordpress\/2012\/02\/23\/printing-execution-times-with-associated-bind-variables\/","title":{"rendered":"Printing execution times with associated bind variables"},"content":{"rendered":"

In a previous post<\/a>, we showed how you can extract the count of executions of a given SQL statement for a given bind variable.<\/p>\n

We recently found a need to print each execution a given SQL statement with the bind variables used for that execution and how many I\/O’s and seconds it required.<\/p>\n

This awk script is shown below…<\/p>\n

\r\n#!\/bin\/awk -f\r\n#----------------------------------------------------------------------------------\r\n#Author:        Steve Howard\r\n#Date:          February 16, 2012\r\n#Purpose:       Extract bind variable values and execution times and I\/O's from a 10046 trace file.\r\n#----------------------------------------------------------------------------------\r\n \r\nBEGIN {\r\n  if (ARGC != 3) {\r\n    print \"Usage:\",ARGV[0],\" -f script_name tracefile_name \\\"query_for_which_to_search\\\"\"\r\n    exit(1)\r\n  }\r\n  start = systime()\r\n  SQL=ARGV[2]\r\n  BIND=ARGV[3]\r\n  ARGC=2\r\n}\r\n \r\n{\r\n  if ($0 ~ \"^PARSING\") {\r\n    B=$4;\r\n    sub(\"#\",\"\",B);\r\n    getline;\r\n    if ($0 ~ SQL) {\r\n      C=B;\r\n    }\r\n    else if (C == B && $0 !~ SQL) {\r\n      C=-1;\r\n    }\r\n  }\r\n  else if (length(C) > 0 && $0 ~ \"BINDS #\"C) {\r\n    looking = 1;\r\n  }\r\n  else if ($0 ~ \"value=\" && looking == 1) {\r\n    sub(\"value=\",\"\",$0)\r\n    tmp=tmp $0;\r\n  }\r\n  else if (length(C) > 0 && $0 ~ \"FETCH #\"C && length(tmp) > 0) {\r\n    split($0,t,\",\")\r\n    sub(\"e=\",\"\",t[2])\r\n    sub(\"cr=\",\"\",t[4])\r\n    printf(\"Variable value list (in order):%s Seconds for this execution: %'.2f Number of IO's %'.0f\\n\",tmp,t[2]\/1000000,t[4])\r\n    tmp = \"\"\r\n    looking = 0\r\n  }\r\n}\r\n<\/pre>\n
…and sample output is also shown below…<\/p>\n
\r\n[FN9DMO]-CMHLDEVPSOFT01:\/home\/oracle >.\/allbinds.awk fn9dev_ora_17068.trc \"SELECT JLN.JOURNAL_LINE, JLN.LINE_DESCR\"\r\nVariable value list (in order):  \"EXCAN\"  \"0000000064\"  \"09-FEB-2011\" Seconds for this execution: 0.05 Number of IO's 1,602\r\nVariable value list (in order):  \"EXCAN\"  \"0000000089\"  \"09-FEB-2011\" Seconds for this execution: 0.04 Number of IO's 1,998\r\nVariable value list (in order):  \"EXCAN\"  \"0000000114\"  \"09-FEB-2011\" Seconds for this execution: 0.04 Number of IO's 2,196\r\nVariable value list (in order):  \"EXCAN\"  \"0000000139\"  \"09-FEB-2011\" Seconds for this execution: 0.05 Number of IO's 1,998\r\nVariable value list (in order):  \"EXCAN\"  \"0000000164\"  \"09-FEB-2011\" Seconds for this execution: 0.04 Number of IO's 2,431\r\nVariable value list (in order):  \"EXCAN\"  \"0000000046\"  \"21-FEB-2012\" Seconds for this execution: 1.91 Number of IO's 74,209\r\nVariable value list (in order):  \"EXCAN\"  \"0000000049\"  \"24-FEB-2012\" Seconds for this execution: 861.94 Number of IO's 27,389,474\r\nVariable value list (in order):  \"EXCAN\"  \"0000000054\"  \"18-FEB-2012\" Seconds for this execution: 0.05 Number of IO's 2,460\r\nVariable value list (in order):  \"EXCAN\"  \"0000000056\"  \"16-FEB-2012\" Seconds for this execution: 0.03 Number of IO's 1,106\r\nVariable value list (in order):  \"EXCAN\"  \"0000000059\"  \"12-FEB-2012\" Seconds for this execution: 0.05 Number of IO's 1,745\r\nVariable value list (in order):  \"EXCAN\"  \"0000000060\"  \"11-FEB-2012\" Seconds for this execution: 0.05 Number of IO's 1,908\r\nVariable value list (in order):  \"EXCAN\"  \"0000000066\"  \"06-FEB-2012\" Seconds for this execution: 0.50 Number of IO's 20,033\r\nVariable value list (in order):  \"EXCAN\"  \"0000000067\"  \"05-FEB-2012\" Seconds for this execution: 1.33 Number of IO's 46,878\r\nVariable value list (in order):  \"EXCAN\"  \"0000000068\"  \"04-FEB-2012\" Seconds for this execution: 0.40 Number of IO's 15,334\r\nVariable value list (in order):  \"EXCAN\"  \"0000000069\"  \"20-FEB-2012\" Seconds for this execution: 2,782.37 Number of IO's 90,354,396\r\nVariable value list (in order):  \"EXCAN\"  \"0000000071\"  \"21-FEB-2012\" Seconds for this execution: 1.98 Number of IO's 79,072\r\nVariable value list (in order):  \"EXCAN\"  \"0000000074\"  \"24-FEB-2012\" Seconds for this execution: 1,292.16 Number of IO's 28,825,091\r\nVariable value list (in order):  \"EXCAN\"  \"0000000079\"  \"18-FEB-2012\" Seconds for this execution: 0.21 Number of IO's 2,460\r\nVariable value list (in order):  \"EXCAN\"  \"0000000081\"  \"16-FEB-2012\" Seconds for this execution: 0.08 Number of IO's 1,378\r\nVariable value list (in order):  \"EXCAN\"  \"0000000084\"  \"12-FEB-2012\" Seconds for this execution: 0.13 Number of IO's 2,178\r\nVariable value list (in order):  \"EXCAN\"  \"0000000085\"  \"11-FEB-2012\" Seconds for this execution: 0.12 Number of IO's 2,118\r\nVariable value list (in order):  \"EXCAN\"  \"0000000091\"  \"06-FEB-2012\" Seconds for this execution: 0.69 Number of IO's 18,767\r\nVariable value list (in order):  \"EXCAN\"  \"0000000092\"  \"05-FEB-2012\" Seconds for this execution: 1.57 Number of IO's 50,783\r\nVariable value list (in order):  \"EXCAN\"  \"0000000093\"  \"04-FEB-2012\" Seconds for this execution: 0.44 Number of IO's 16,919\r\n[FN9DMO]-CMHLDEVPSOFT01:\/home\/oracle >\r\n<\/pre>\n
As you can see above, three variables took 99% of the total execution time in the trace.  This is a perfect example of the raw trace data being so much more usable than just tkprof alone.   tkprof, while enormously useful, would average the results of each execution and hide the fact that most of them were OK.<\/p>\n","protected":false},"excerpt":{"rendered":"
In a previous post, we showed how you can extract the count of executions of a given SQL statement for a given bind variable. We recently found a need to print each execution a given SQL statement with the bind…<\/p>\n
Read more →<\/a><\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_mi_skip_tracking":false,"footnotes":""},"categories":[19,28,27,22],"tags":[],"_links":{"self":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/1914"}],"collection":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/comments?post=1914"}],"version-history":[{"count":7,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/1914\/revisions"}],"predecessor-version":[{"id":2745,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/1914\/revisions\/2745"}],"wp:attachment":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/media?parent=1914"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/categories?post=1914"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/tags?post=1914"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}