By Franck Pachot

.
A question that I had several times: in Enterprise Manager, in the screen about one SQL statement, the ‘statistics’ tab shows the number of executions, elapsed time, etc. Question is: which time window does it cover? There is a one hour chart above, and two timestamps displayed as ‘First Load Time’ and ‘Last load Time’, and we don’t know which one is related with the execution statistics numbers. I’ll explain it clearly on an example.

I’ll check a query I have on my system which has several cursors, with two different execution plans. And I check from V$SQL because here is where is the most detailed information, and columns are well documented.

From the documentation:

  • FIRST_LOAD_TIME is the Timestamp of the parent creation time
  • LAST_LOAD_TIME is the Time at which the query plan was loaded into the library cache

It’s clear that because V$SQL show information about child cursors, the FIRST_LOAD_TIME will be the same for all children.

SQL> select sql_id,plan_hash_value,executions,first_load_time,last_load_time,last_active_time from v$sql where sql_id='dcstr36r0vz0d' order by child_number

SQL_ID        PLAN_HASH_VALUE EXECUTIONS FIRST_LOAD_TIME     LAST_LOAD_TIME      LAST_ACTIVE_TIME
------------- --------------- ---------- ------------------- ------------------- -------------------
dcstr36r0vz0d        17720163         60 2014-10-29/07:01:59 2014-10-29/07:01:59 2014-10-29/13:01:25
dcstr36r0vz0d      3798950322        102 2014-10-29/07:01:59 2014-10-29/07:03:49 2014-10-29/13:05:54
dcstr36r0vz0d      3798950322         24 2014-10-29/07:01:59 2014-10-29/07:05:55 2014-10-29/13:05:54
dcstr36r0vz0d      3798950322          1 2014-10-29/07:01:59 2014-10-29/08:11:19 2014-10-29/08:11:19
dcstr36r0vz0d      3798950322          1 2014-10-29/07:01:59 2014-10-29/08:29:34 2014-10-29/08:29:34

The plan with hash value 17720163 has been executed 60 times since 07:01:59. It was the first child cursor (child_number=0) for that parent, so this is why FIRST_LOAD_TIME=LAST_LOAD_TIME

And, the plan with hash value 3798950322 has been executed 128 times since 07:03:49 by cursors that are not shared but have come to the same plan anyway

Two remarks:

  • FIRST_LOAD_TIME is the same for all children because it is a parent information
  • LAST_LOAD_TIME is different for each child and that’s important because Enterprise Manager don’t show that detail, aggregating together the children with same execution plan.
Time to look at the Enterprise Manager screen.
I’m talking about the ‘Real Time’  statistics:
EMLastLoadTime1.png
and I’ve selected the plan hash value 17720163:
EMLastLoadTime2.png
Ok. So we have 60 executions here. This matches the line in V$SQL. And we know that is it 60 executions since 07:01:59 because both timestamps are the same. No doubt here.
Then, let’s select the other plan hash value from the popup:
EMLastLoadTime3.png
128 executions for this plan. This is what we had when summing the lines from V$SQL. And look at the Shared Cursor Statistics. The number of ‘Child Cursors’ is 4 which is what we know. The ‘First Load Time’ is the one of the parent.
However, what is the ‘Last Load Time’ when we know that there are 4 different values in V$SQL for it? Look, they choose the latest one, 08:29:34, and that’s a good choice according to the name. It’s the last load time.
But what I want to know is the time from which the 128 executions are counted. And that should be the earliest one. In my example, we know from V$SQL what we had 128 executions since 07:03:49 but that timestamp is not displayed here.
If you want a date, you should take the ‘First Load time’ because it’s true that there were 128 executions of cursors with that plan hash value since 07:01:59
Sometimes the first load time is very old and it would be better to have the MIN(LAST_LOAD_TIME). But anyway if we want better time detail, we can choose the ‘Historical’ view instead of the ‘Real Time’ one and we have the numbers related with the AWR snapshots.
Here is an example for the cursor with plan hash value 17720163:
EMLastLoadTime4.png
From the historical view, we select a timestamp, we see the begin and end timestamps. Here I have 10 executions per hour.
Everything looks good there, except that ‘Child Cursors’ is 5, which is for the whole statement and not only for the cursors selected by the plan hash value.
Then I’ve two conclusions:
  • ‘Last Load Time’ is not useful to know the time window covered by the Real Time statistics. Use First ‘Load time instead’
  • In case of any doubt, fall back to V$ views which are much more documented, and give more detail.
Post Views: 1,693
Thumbnail [60x60]
by
Oracle Team