{"id":73272,"date":"2012-12-04T15:30:17","date_gmt":"2012-12-04T15:30:17","guid":{"rendered":"https:\/\/www.red-gate.com\/simple-talk\/uncategorized\/code-instrumentation\/"},"modified":"2021-07-14T13:07:47","modified_gmt":"2021-07-14T13:07:47","slug":"code-instrumentation","status":"publish","type":"post","link":"https:\/\/www.red-gate.com\/simple-talk\/databases\/oracle-databases\/code-instrumentation\/","title":{"rendered":"Code Instrumentation"},"content":{"rendered":"<p>Whenever we execute a procedure, it\u2019s out of our hands. We expect it to do what it was designed to do, but what if it doesn&#8217;t? What if it takes a lot more time then expected? All kind of questions start to arise:<\/p>\n<ul>\n<li>Is it almost finished, should I wait just a few more minutes?<\/li>\n<li>Is it trapped in an infinitive loop? Or are my queries running slow?<\/li>\n<li>Can I safely kill it? Or did it already commit some changes and should I reverse them?<\/li>\n<li>Which job should I kill, is this mine?<\/li>\n<\/ul>\n<p>We want some kind of feedback from our program, but since programs just do what we ask them to do, it\u2019s up to us to find a way of getting the information we need. So how can you instrument your code? It\u2019s not that difficult, you just have to add some lines of codes that tell you what it\u2019s doing. When developing a procedure, and it\u2019s not immediately doing what you expect, you might add some lines of code using DBMS_OUTPUT. That\u2019s code instrumentation, by adding this you\u2019re able to locate the problem and correct it. But DBMS_OUTPUT is very limited and you should create, or find, a proper logging mechanism. You really should! But the aim of this article is to show you what\u2019s already present in the database and how we can get the most out of it.<\/p>\n<h3>Setting your identifier<\/h3>\n<p>Luckily for us, Oracle has already put a lot of effort in instrumenting the database. When you need an answer to the question: \u201cWhich session do I need to kill?\u201d you can query the performance view \u201cV$SESSION\u201d, and most of the time you\u2019ll able to pinpoint the badly behaving session. It shows you what it\u2019s doing, which SQL-statement it last executed, or what it is waiting for. But when looking at the data in V$SESSION, you also see a lot of empty fields like client_identifier, client_info, module and action.<\/p>\n<p><a href=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/looking-at-the-data-in-VSESSION.png\" title=\"Looking at the data in V$SESSION\"> <img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/looking-at-the-data-in-VSESSION.png\" alt=\"\" title=\"looking at the data in V$SESSION\" width=\"595\" height=\"356\" class=\"alignnone size-full wp-image-3270\" style=\"border:1px solid #999\" srcset=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/looking-at-the-data-in-VSESSION.png 595w, https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/looking-at-the-data-in-VSESSION-300x179.png 300w\" sizes=\"auto, (max-width: 595px) 100vw, 595px\" \/><\/a><\/p>\n<p>These fields are free for you to use. If your DBA will allow grants on DBMS_SESSION and DBMS_APPLICATION_INFO you will be able to monitor your programs easily with the V$SESSION view:<\/p>\n<pre>BEGIN\r\ndbms_session.set_identifier(client_id=&gt;'BB');\r\ndbms_application_info.set_client_info(client_info=&gt;'Billy Bragg')\r\n--\r\ndbms_application_info.set_module(module_name=&gt;'CREATE SONG', action_name=&gt;'1.Write Melody');\r\nwrite_melody;\r\n--\r\ndbms_application_info.set_action(action_name=&gt;'2.Write text');\r\nwrite_text;\r\n--...\r\ndbms_application_info.set_module(module_name=&gt;'',action_name=&gt;'');\r\nEND;<\/pre>\n<p>Querying the V$SESSION view again, it will provide you with much more detailed information. Your DBA would love you for this! <\/p>\n<p><a href=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/Querying-the-VSESSION-view-again.png\" title=\"Querying the V$SESSION view again\"><img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/Querying-the-VSESSION-view-again.png\" alt=\"\" title=\"Querying the V$SESSION view again\" width=\"595\" height=\"283\" class=\"alignnone size-full wp-image-3280\" style=\"border:1px solid #999\" srcset=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/Querying-the-VSESSION-view-again.png 684w, https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/Querying-the-VSESSION-view-again-300x142.png 300w\" sizes=\"auto, (max-width: 595px) 100vw, 595px\" \/><\/a><\/p>\n<h3>Tracing<\/h3>\n<p>Setting these identifiers makes enabling tracing these programs a breeze. Using DBMS_MONITOR you can trace a session by using SESSION_TRACE_ENABLE and specifying a sessions SID and serial number. However, it might by more useful not to trace a single session, but to trace a single module or action:<\/p>\n<pre>BEGIN\r\ndbms_monitor.serv_mod_act_trace_enable(service_name \u00a0=&gt; 'SYS$USERS'\r\n,module_name \u00a0\u00a0=&gt; 'PLAY GIG'\r\n,waits \u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0=&gt; TRUE\r\n,binds\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 \u00a0=&gt; TRUE\r\n,instance_name =&gt; NULL);\r\nEND;<\/pre>\n<p>Now you can take a look at the trace files. Most of us have heard of TKPROF, a little command line tool that comes with the database. Have you also heard of TRCSESS? Ever wondered what all those extra parameters in TRCSESS mean? TRCSESS is another little command line tool allowing you to take the input from one or more trace files and apply filters to get the set of SQL statements you\u2019re interested in. Since these trace files also contain the module and action information you can easily create a trace file for the part that needs some investigation. In the raw data you can find the different actions in your module: <\/p>\n<p><a href=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/different-actions-in-your-module.png\" title=\"Different actions in your module\"><img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/different-actions-in-your-module.png\" alt=\"\" title=\"different actions in your module\" width=\"595\" height=\"481\" class=\"alignnone size-full wp-image-3283\" style=\"border:1px solid #999\" srcset=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/different-actions-in-your-module.png 698w, https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/different-actions-in-your-module-300x242.png 300w, https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/different-actions-in-your-module-310x250.png 310w\" sizes=\"auto, (max-width: 595px) 100vw, 595px\" \/><\/a><\/p>\n<p>After filtering it for only one action, you have removed the statements that don\u2019t belong to this criterion:<\/p>\n<pre>trcsess output=mytrace.trc action=\"1.Soundcheck\" \u00a0\u00a0\u00a0\u00a0 dev11g_ora_3788.trc<\/pre>\n<p><a href=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/filtering-removes-statements.png\" title=\"Filtering removes statements that don\u2019t belong to this criterion\"><img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/filtering-removes-statements.png\" alt=\"\" title=\"filtering removes statements that don\u2019t belong to this criterion\" width=\"595\" height=\"498\" class=\"alignnone size-full wp-image-3284\" style=\"border:1px solid #999\" srcset=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/filtering-removes-statements.png 698w, https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/filtering-removes-statements-300x251.png 300w\" sizes=\"auto, (max-width: 595px) 100vw, 595px\" \/><\/a><\/p>\n<p>This allows you to create a report using TKPROF which contains only the statements you&#8217;re interested in. This makies it easier to tune your applications.<\/p>\n<pre>tkprof mytrace.trc mytrace.txt sys=no sort=prsela,exeela,fchela<\/pre>\n<p><a href=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/report-using-TKPROF.png\" title=\"Report using TKPROF\"><img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/report-using-TKPROF.png\" alt=\"\" title=\"report using TKPROF\" width=\"595\" height=\"398\" class=\"alignnone size-full wp-image-3285\" style=\"border:1px solid #999\" srcset=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/report-using-TKPROF.png 653w, https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/report-using-TKPROF-300x200.png 300w\" sizes=\"auto, (max-width: 595px) 100vw, 595px\" \/><\/a><\/p>\n<h3>Enterprise Manager<\/h3>\n<p>What can be found in the performance views, can also be found in Enterprise Manager. Filter, aggregate, drill down and get all information you want with some simple clicks.<\/p>\n<p><a href=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/looking-at-this-in-Enterprise-Manager.png\" title=\"Looking at this in Enterprise Manager\"><img loading=\"lazy\" decoding=\"async\" src=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/looking-at-this-in-Enterprise-Manager.png\" alt=\"\" title=\"looking at this in Enterprise Manager\" width=\"595\" height=\"337\" class=\"alignnone size-full wp-image-3286\" srcset=\"https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/looking-at-this-in-Enterprise-Manager.png 983w, https:\/\/www.red-gate.com\/simple-talk\/wp-content\/uploads\/oracle\/2012\/12\/looking-at-this-in-Enterprise-Manager-300x169.png 300w\" sizes=\"auto, (max-width: 595px) 100vw, 595px\" \/><\/a><\/p>\n<h3>Summary<\/h3>\n<p>As you can see you can add some lines of code to set your identifier, module and action. It won&#8217;t take much time to implement but it will optimize the traceability of your programs. It might be a lifesaver when things go wrong.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>Whenever we execute a procedure, it\u2019s out of our hands. We expect it to do what it was designed to do, but what if it doesn&#8217;t? What if it takes a lot more time then expected? All kind of questions start to arise: Is it almost finished, should I wait just a few more minutes? Is it trapped in an&hellip;<\/p>\n","protected":false},"author":316205,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[143533],"tags":[],"coauthors":[],"class_list":["post-73272","post","type-post","status-publish","format-standard","hentry","category-oracle-databases"],"acf":[],"_links":{"self":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73272","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/users\/316205"}],"replies":[{"embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/comments?post=73272"}],"version-history":[{"count":1,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73272\/revisions"}],"predecessor-version":[{"id":91742,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73272\/revisions\/91742"}],"wp:attachment":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/media?parent=73272"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/categories?post=73272"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/tags?post=73272"},{"taxonomy":"author","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/coauthors?post=73272"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}