{"id":73082,"date":"2017-01-24T11:39:19","date_gmt":"2017-01-24T11:39:19","guid":{"rendered":"https:\/\/www.red-gate.com\/simple-talk\/uncategorized\/snapshots\/"},"modified":"2021-07-14T13:06:57","modified_gmt":"2021-07-14T13:06:57","slug":"snapshots","status":"publish","type":"post","link":"https:\/\/www.red-gate.com\/simple-talk\/databases\/oracle-databases\/snapshots\/","title":{"rendered":"Snapshots"},"content":{"rendered":"

While looking at the results from a query against the dynamic performance view v$active_session_history<\/em><\/strong> during a recent trouble-shooting assignment I noticed a result that was so unusual that I decided I needed to get some information from the v$ash_info<\/strong><\/em> view over an interval of about 3 minutes – and it didn’t matter which three minutes in particular, any three (consecutive) minutes would do.<\/p>\n

The drawback, of course, is that v$ash_info<\/strong><\/em> is one of those views that shows a summary since instance startup, so I needed to take a couple of snapshots and find changes in values. Just to make the task a little more awkward, I didn’t have access to the system so I needed to send in a script for someone else to run.<\/p>\n

Luckily this was 12c and there’s a feature in 12c that makes it easy to write code that takes timed deltas of any particular dataset so, as a first step, I wrote a little bit code that took 20 consecutive snapshots with a 10 seconds gap between snapshots; this is what it looked like:<\/p>\n

rem\r\nrem     Script:         ash_info.sql\r\nrem     Author:         Jonathan Lewis\r\nrem     Dated:          Jan 2017\r\nrem\r\n\r\ndefine m_snapshot_time  = 10\r\ndefine m_snapshot_count = 20\r\n\r\nset linesize 180\r\nset pagesize 60\r\nset trimspool on\r\n\r\nset arraysize 60\r\n\r\nprompt  ===========================================\r\nprompt  Reporting v$ash_info &m_snapshot_count times\r\nprompt  with a snapshot every &m_snapshot_time seconds\r\nprompt  Please wait\r\nprompt  ===========================================\r\n\r\nwith\r\n        function wait_row_n (\r\n                i_secs          number,\r\n                i_return        number default -1\r\n        ) return number\r\n        is\r\n        begin\r\n                dbms_lock.sleep(i_secs);\r\n                return i_return;\r\n        end wait_row_n;\r\nselect\r\n        \/*+\r\n                leading(looper aio)\r\n                use_nl(aio)\r\n        *\/\r\n        wait_row_n(&m_snapshot_time, looper.ct) sleeper,\r\n        aio.*\r\nfrom\r\n        (\r\n        select\r\n                rownum  ct\r\n        from\r\n                dual\r\n        connect by\r\n                level <= &m_snapshot_count\r\n        )       looper,\r\n        v$ash_info aio\r\n\/\r\n\r\n<\/pre>\n
There are a few details worth noting in this query but the important 12c one<\/strong><\/em> is the feature of creating a PL\/SQL function in a “WITH” clause of an SQL statement. Historically if you wanted to create and use a PL\/SQL function from SQL the function had to be a standalone object (possibly packaged) that you called from SQL. One of the drawbacks to this was that you could run into privilege problems. In the above example my function calls the dbms_lock<\/strong><\/em> package. I have received all my privileges from a role (called test_role<\/strong><\/em>) that has been granted execute on the dbms_lock<\/strong><\/em> package, and the SQL above works (note: the role test_role<\/strong><\/em> has also been granted select on v_$ash_info<\/strong><\/em>). Look what happens, though, if I try to create a standalone PL\/SQL function to replace the “factored subquery” function:<\/p>\n
SQL> create or replace procedure my_sleep(n in number) as\r\n  2  begin\r\n  3          sys.dbms_lock.sleep(n);\r\n  4  end;\r\n  5  \/\r\n\r\nWarning: Procedure created with compilation errors.\r\n\r\nSQL> show errors\r\nErrors for PROCEDURE MY_SLEEP:\r\n\r\nLINE\/COL ERROR\r\n-------- -----------------------------------------------------------------\r\n3\/9      PL\/SQL: Statement ignored\r\n3\/9      PLS-00201: identifier 'SYS.DBMS_LOCK' must be declared\r\n\r\n<\/pre>\n
I can’t use the dbms_lock<\/strong><\/em> package in a permanent object in my schema if I’ve only got the privilege to execute it granted through a role. If I connect as SYS<\/strong><\/em> and grant execute on dbms_lock<\/strong><\/em> to my schema (called test_user<\/strong><\/em>) I can reconnect as test_user<\/strong><\/em> and the create procedure<\/strong><\/em> call will succeed.<\/p>\n
Inevitably\u00a0there are pros and cons to embedding PL\/SQL functions withing SQL so don’t take this note as a suggestion that you should always inline any PL\/SQL functions you want to use – it just happens to be very convenient in this particular case.<\/p>\n
The other details worth a little mention in this script are the hinting and the use of the slash character to execute the statement.<\/p>\n
The basic reason the script does what I want is because the dynamic performance views don’t<\/strong><\/span> produce read-consistent results. My query against dual produces N rows, one every M seconds; if v$ashinfo<\/strong><\/em> were a normal Oracle table (or view) it would produce the same result for every one of those N rows if I used it as the second table in a nested loop join, but because it’s a dynamic performance view what I actually get is a different result each time I visit it. In the absence of the two hints Oracle could take an path that scanned v$ashinfo<\/strong><\/em> once and did a merge join with the N rows I get from dual<\/strong><\/em>, giving me N copies of the same values. Both the leading()<\/strong><\/em> hint and the use_nl()<\/strong><\/em> hint are critical to getting the results I want.<\/p>\n
I’ve used the “\/” to execute the query – a semi-colon doesn’t work. Technically a semi-colon is a separator, but historically SQL*Plus has used it as an alternative “run” command; once you introduce a “with function”<\/em> clause – which will contain semi-colons for the PL\/SQL component of the text – the alternative meaning of the semi-colon ceases to be used and you have to use the “\/” to run the statement. If you change the “\/” to a semi-colon you’ll find that SQL*Plus treats the next bit of text as if it were part of the statement (and you’ll probably see error “ORA-00933: SQL command not properly ended”<\/em> as Oracle tries to interpret it).<\/p>\n
Interestingly, but unsurprisingly, blank lines in the SQL are automatically acceptable once you’ve introduced the “with function”<\/em> clause irrespective of the setting the SQL*Plus environment variable SQLBLANKLINES.<\/p>\n
Deltas<\/h3>\n
My first cut of the script simply lists all the absolute values from the view. As a starting point that’s probably good enough for what I wanted. (In fact, if I had had open access to the system I wouldn’t have bothered with the script, I’d simply have run “select * from V$ash_info”<\/em> a few times while spooling to a file – after setting a suitable linesize and a few column formats, of course.) From the viewpoint of future convenience, though, it would be nice to have a script that got the data but showed the change from snapshot to snapshot. I had to increase the complexity of the SQL a little bit by using one of the simplest analytic functions<\/strong><\/em> to achieve this then, after a little stress testing, I decided to add a few enhancements to the first version of the code so currently my code looks like this:<\/p>\n
column delta_seconds format 999.999\r\ncolumn snap_time     format a19\r\ncolumn sample_time   format a19\r\n\r\n\r\nalter session set statistics_level = all;\r\n\r\nwith\r\n        function wait_row(\r\n                i_secs          number,\r\n                i_counter       number default -1\r\n        ) return timestamp\r\n        is\r\n                m_time  timestamp;\r\n        begin\r\n                m_time := systimestamp;\r\n                dbms_lock.sleep(i_secs);\r\n                return m_time;\r\n        end wait_row;\r\n\r\nbase_data as (\r\n        select\r\n                \/*+\r\n                        leading(looper aio)\r\n                        use_nl(aio)\r\n                        materialize\r\n                *\/\r\n                wait_row(&m_snapshot_time, looper.ct)   timer,\r\n                aio.*\r\n        from\r\n                (\r\n                select\r\n                        rownum  ct\r\n                from\r\n                        dual\r\n                connect by\r\n                        level <= &m_snapshot_count\r\n                )       looper,\r\n                v$ash_info aio\r\n)\r\nselect\r\n        to_char(timer,'hh24:mi:ssxff')                                  snap_time,\r\n        extract(second from\r\n                        (timer - lag(timer,1,timer) over (order by timer))\r\n        )                                                               delta_seconds,\r\n        latest_sample_id                                                sample_id,\r\n        latest_sample_id -\r\n                lag(latest_sample_id,1,latest_sample_id) over (order by timer)  delta,\r\n        to_char(latest_sample_time,'hh24:mi:ssxff')                     sample_time,\r\n        extract(second from\r\n                        (\r\n                        latest_sample_time -\r\n                                lag(latest_sample_time,1,latest_sample_time) over (order by timer)\r\n                        )\r\n        )                                                               delta_seconds,\r\n        sample_count -\r\n                lag(sample_count,1,0) over (order by timer)             samples,\r\n        dropped_sample_count -\r\n                lag(dropped_sample_count,1,0) over (order by timer)     dropped_samples,\r\n        sampled_bytes -\r\n                lag(sampled_bytes,1,0) over (order by timer)            sampled_bytes,\r\n        sampler_elapsed_time -\r\n                lag(sampler_elapsed_time,1,0) over (order by timer)     sampling_musec\r\nfrom\r\n        base_data\r\norder by\r\n        1\r\n\/\r\n\r\n\r\n<\/pre>\n
Again there are a couple of little details to note. For demonstration purposes I’ve left a few blank lines in the middle of the code just to demonstrate the principle. More importantly I’ve got a “with function”<\/em> and a “with subquery”<\/em> in the same statement – you’ll notice that the function bit ends with a semi-colon (though technically that should be “is separated from the next block by”<\/em> rather than “ends with”<\/em>. If I wanted another function I could\u00a0start it’s definition immediately before the definition of base_data<\/strong><\/em> factored subquery. It’s a quirky little detail but multiple functions are separated by semi-colons while multiple subqueries are separated by commas.<\/p>\n
You can also see a less well-known detail of the lag()<\/strong><\/em> analytic function:\u00a0I’ve set the 2nd (i.e. offset) parameter explicitly to 1 (the default) in each case and the third parameter to the value I want Oracle to supply if the offset takes Oracle outside the current window. I’ve supplied zero for most of the columns and this conveniently means that the first row of output shows the absolute starting values, but I’ve repeated the original column name in two places so that the output for the first row shows zeros.<\/p>\n
An important enhancement to the output from the query is the time at which each query against v$ash_info<\/strong><\/em> was actually executed. You’ll see why I did this when we review the results. I’ve changed my function to return systimestamp<\/strong><\/em> as at the moment the function was called then included both the time of the call and the change in time since the previous call in my output.\u00a0After including this detail I had to materialize the subquery because Oracle seemed to be copying the function call into the select list rather than calling the function once per row and then re-using the result – which may be a change in behaviour that could affect some other pieces of SQL that I’ve written in the past.<\/p>\n
Here’s an example of the output:<\/p>\n
===========================================\r\nReporting v$ash_info 20 times\r\nwith a snapshot every 10 seconds\r\nPlease wait\r\n===========================================\r\n\r\nSNAP_TIME           DELTA_SECONDS  SAMPLE_ID      DELTA SAMPLE_TIME         DELTA_SECONDS    SAMPLES DROPPED_SAMPLES SAMPLED_BYTES SAMPLING_MUSEC\r\n------------------- ------------- ---------- ---------- ------------------- ------------- ---------- --------------- ------------- --------------\r\n12:14:58.556150000           .000    4745434          0 12:14:57.825000000           .000      16432               3       7016168        4963931\r\n12:15:08.593213000         10.037    4745444         10 12:15:08.215000000         10.390         10               0         14024           1327\r\n12:15:18.619130000         10.026    4745454         10 12:15:18.605000000         10.390         10               0         15712           1393\r\n12:15:28.634358000         10.015    4745463          9 12:15:27.885000000          9.280          9               0         14368           1552\r\n12:15:38.722004000         10.088    4745473         10 12:15:38.255000000         10.370         10               0         20240           1408\r\n12:15:48.725934000         10.004    4745483         10 12:15:48.676000000         10.421         10               0         20280           1185\r\n12:15:58.768118000         10.042    4745492          9 12:15:58.036000000          9.360          9               0         18280            653\r\n12:16:08.774180000         10.006    4745502         10 12:16:08.436000000         10.400         10               0         20432            959\r\n12:16:18.776470000         10.002    4745511          9 12:16:17.796000000          9.360          9               0         15208            954\r\n12:16:28.824398000         10.048    4745521         10 12:16:28.196000000         10.400         10               0         20832           1229\r\n12:16:38.828178000         10.004    4745531         10 12:16:38.596000000         10.400         10               0         16816           1021\r\n12:16:48.833060000         10.005    4745540          9 12:16:47.956000000          9.360          9               0         16112           1179\r\n12:16:58.880889000         10.048    4745550         10 12:16:58.346000000         10.390         10               0         17888           1274\r\n12:17:08.884090000         10.003    4745560         10 12:17:08.736000000         10.390         10               0         17904           1085\r\n12:17:18.888500000         10.004    4745569          9 12:17:18.096000000          9.360          9               0         16128           1207\r\n12:17:28.938052000         10.050    4745579         10 12:17:28.496000000         10.400         10               0         16224           1294\r\n12:17:38.940824000         10.003    4745588          9 12:17:37.896000000          9.400          9               0         10544            830\r\n12:17:49.009051000         10.068    4745598         10 12:17:48.292000000         10.396         10               0         10584           1136\r\n12:17:59.030062000         10.021    4745608         10 12:17:58.612000000         10.320         10               0          8888           1286\r\n12:18:09.039469000         10.009    4745618         10 12:18:08.822000000         10.210         10               0          6976           1065\r\n\r\n20 rows selected.\r\n\r\n<\/pre>\n
I was trying to overload the CPUs by running up a set of CPU intensive queries on a small instance running on a VM when I ran this report. This introduced two problems for my report; the first is that when the CPU is overloaded (by about 400% in my case) my session might find it hard to get onto the CPU in a timely fashion, so the time between lines of the report might be more than the 10 seconds I requested. The second problem is the same problem – but for mmnl<\/strong><\/em>, the process that constructs the ASH data; it’s supposed to take a snapshot once per second but it, too, might not get onto the CPU when it needs to.<\/p>\n
Looking at the output above we can see that my session had less of a problem than mmnl<\/strong><\/em>. My snapshot time is drifting by a few hundredths of a second on each sleep; on the other hand we know that mmnl<\/strong><\/em> should be taking samples once per second so with our 10 second snapshot we should see the sample count going up by 10 and the sample time going up by 10 seconds on each snapshot – but when we see 10 samples we see the sample time going up by around 10.4 seconds, and there’s a “self-correcting” element in place that means we sometimes see only 9 samples taken in our 10 second window.\u00a0<\/p>\n
On the plus side, even though the system is under some pressure due to excess CPU utilisation we can see that we have no “dropped samples”. The column name is a little misleading – it’s not a count of been dropped samples, it’s a count of the number active sessions for a sample that were omitted because the sampler couldn’t get a self-consistent image of that session. Ironically, when the CPU is overloaded it’s probably the sessions that can’t be captured that are the most interesting and important sessions.<\/p>\n
Conclusion<\/h3>\n
I’ve demonstrated a method of using a new 12c feature to report change over time from a dynamic performance view that holds only information accumulated since instance startup. A key point of the new feature is that it allows a user with role-based privileges to do things that were previously only possible to a user with schema-based privileges.<\/p>\n
The method is generic, but the specific example I chose also allowed me to make a couple of points about performance monitoring, effects of CPU overload, and the need for care in cross-checking figures.<\/p>\n
 <\/p>\n","protected":false},"excerpt":{"rendered":"
While looking at the results from a query against the dynamic performance view v$active_session_history during a recent trouble-shooting assignment I noticed a result that was so unusual that I decided I needed to get some information from the v$ash_info view over an interval of about 3 minutes – and it didn’t matter which three minutes in particular, any three (consecutive)…<\/p>\n","protected":false},"author":101205,"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-73082","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\/73082","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\/101205"}],"replies":[{"embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/comments?post=73082"}],"version-history":[{"count":1,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73082\/revisions"}],"predecessor-version":[{"id":91587,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/73082\/revisions\/91587"}],"wp:attachment":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/media?parent=73082"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/categories?post=73082"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/tags?post=73082"},{"taxonomy":"author","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/coauthors?post=73082"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}