OraFAQ Forum: Performance Tuning » Time metrics in V$SQL don't add up

Home » RDBMS Server » Performance Tuning » Time metrics in V$SQL don't add up (Oracle 19c SE2 )

Show: Today's Messages :: Polls :: Message Navigator
E-mail to friend

Time metrics in V$SQL don't add up [message #686293]

Wed, 20 July 2022 18:35

Andrey_R
Messages: 441
Registered: January 2012
Location: Israel

Senior Member

Hi all,
I'm trying to figure out all the activities on which the execution time in V$SQL is spent.

I'm working with totals.

So I've conducted this short query, to try to see where the time is spent.

SQL> --TIME RELEVANT METRICS only V$SQL (1)
SQL> SET LINES 900
SQL> with q as (
  2  select
  3       to_char(sum( v.APPLICATION_WAIT_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_APPLICATION_WT_s,
  4       to_char(sum( v.CONCURRENCY_WAIT_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_CONCURRENCY_WT_s,
  5       to_char(sum( v.CLUSTER_WAIT_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_CLUSTER_WT_s,
  6       to_char(sum( v.CPU_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_CPU_time_S,
  7       to_char(sum( v.USER_IO_WAIT_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_USER_IO_WT_s,
  8       to_char(sum( v.ELAPSED_TIME /1000000 ) ,'999,999,999,990.99') as total_execution_time_S
  9  --
 10    from gv$sql v
 11  )
 12  select
 13  --
 14  total_APPLICATION_WT_s ,
 15  total_CONCURRENCY_WT_s ,
 16  total_CLUSTER_WT_s ,
 17  total_CPU_time_S ,
 18  total_USER_IO_WT_s ,
 19  total_execution_time_S as total_execution_time_S
 20   from q;

TOTAL_APPLICATION_WT_S      TOTAL_CONCURRENCY_WT_S      TOTAL_CLUSTER_WT_S          TOTAL_CPU_TIME_S            TOTAL_USER_IO_WT_S          TOTAL_EXECUTION_TIM
--------------------------- --------------------------- --------------------------- --------------------------- --------------------------- -------------------
                      12.22                       34.00                        0.00                   40,989.48                    4,643.79           60,504.37

Seems like I'm falling ~25% short of the full picture

What am I missing here ?
Where can I find the "lost" time ?

Thanks
Andrey

Report message to a moderator

Re: Time metrics in V$SQL don't add up [message #686295 is a reply to message #686293]

Thu, 21 July 2022 01:54

John Watson
Messages: 8960
Registered: January 2010
Location: Global Village

Senior Member

Often, the arithmetic goes wrong because of CPU starvation. If you are running with hyperthreaded cores, you may think that you have plenty of spare CPU when in fact you have none. A Statspack report might help to work out what is actually happening, can you post one?

I was working on a SPARC system recently with what looked like 64 CPUs, average CPU usage shown by sar was only 10% to 15%. But the chip was 8 cores with 8 threads each. So that usage level actually meant it was running at maximum capacity, which causes all sorts of problems with the time accounting.

Report message to a moderator

Re: Time metrics in V$SQL don't add up [message #686300 is a reply to message #686295]

Thu, 21 July 2022 10:14

Andrey_R
Messages: 441
Registered: January 2012
Location: Israel

Senior Member

John Watson wrote on Thu, 21 July 2022 09:54

A Statspack report might help to work out what is actually happening, can you post one?

First of all thank you very much for the reply.

And sure. I've went to a different instance so I can do further testing there.
It's a "private" Oracle instance that nobody is connected to.

And just in case, I've flushed shared pool on it

SQL> EXEC rdsadmin.rdsadmin_util.flush_shared_pool;

PL/SQL procedure successfully completed.

And created a Statspack snapshot + run it hourly right after.
That was at 15:35 local time:

SQL> conn perfstat/mypassword@mydb
Connected.
SQL> VARIABLE jn NUMBER;
SQL> exec dbms_job.submit(:jn, 'statspack.snap;',SYSDATE,'TRUNC(SYSDATE+1/24,''HH24'')');

PL/SQL procedure successfully completed.

SQL> COMMIT;

Commit complete.

SQL> SELECT SNAP_ID, SNAP_TIME FROM STATS$SNAPSHOT ORDER BY 1;

   SNAP_ID SNAP_TIME
---------- ---------
         1 21-JUL-22

SQL> alter session set nls_date_format='dd.mm.yyyy hh24:mi:ss';

Session altered.

SQL> SELECT SNAP_ID, SNAP_TIME FROM STATS$SNAPSHOT ORDER BY 1;

   SNAP_ID SNAP_TIME
---------- -------------------
         1 21.07.2022 15:35:37

At 16:05 I got bored and created another snapshot to close the interval with:

SQL> EXECUTE statspack.snap;

PL/SQL procedure successfully completed.

SQL> SELECT SNAP_ID, SNAP_TIME FROM STATS$SNAPSHOT ORDER BY 1;

   SNAP_ID SNAP_TIME
---------- -------------------
         1 21.07.2022 15:35:37
         2 21.07.2022 16:00:00
         3 21.07.2022 16:05:13

Not sure why I got a snapshot at 16:00 too, but I'll use 1 and 3 as a 0.5 hour interval for my statspack report:

SQL> exec rdsadmin.rds_run_spreport(1,3);

PL/SQL procedure successfully completed.

SQL>

So here's my query on V$SQL ( with Java and plsql exec timings which still don't make the picture whole):

SQL>
SQL> set autot off
SQL> --TIME RELEVANT METRICS only V$SQL (1)
SQL> --SET LINES 1000
SQL> with q as (
  2  select
  3       to_char(sum( v.APPLICATION_WAIT_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_APPLICATION_WT_s,
  4       to_char(sum( v.CONCURRENCY_WAIT_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_CONCURRENCY_WT_s,
  5       to_char(sum( v.CLUSTER_WAIT_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_CLUSTER_WT_s,
  6       to_char(sum( v.CPU_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_CPU_time_S,
  7       to_char(sum( v.USER_IO_WAIT_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_USER_IO_WT_s,
  8       to_char(sum( v.PLSQL_EXEC_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_PLSQL_EXEC_TIME_s,
  9       to_char(sum( v.JAVA_EXEC_TIME /1000000 ) ,'999,999,999,999,999,990.99') as total_JAVA_EXEC_TIME_s,
 10  --
 11            to_char(sum( v.ELAPSED_TIME /1000000 ) ,'999,999,999,990.99') as total_execution_time_S
 12  --
 13    from gv$sql v
 14  )
 15  select
 16  --
 17  total_APPLICATION_WT_s ,
 18  total_CONCURRENCY_WT_s ,
 19  total_CLUSTER_WT_s ,
 20  total_CPU_time_S ,
 21  total_USER_IO_WT_s ,
 22  total_PLSQL_EXEC_TIME_s,
 23  total_JAVA_EXEC_TIME_s,
 24  total_execution_time_S as total_execution_time_S
 25   from q;

TOTAL_APPLICATION_WT_S      TOTAL_CONCURRENCY_WT_S      TOTAL_CLUSTER_WT_S          TOTAL_CPU_TIME_S            TOTAL_USER_IO_WT_S          TOTAL_PLSQL_EXEC_TIME_S     TOTAL_JAVA_EXEC_TIME_S      TOTAL_EXECUTION_TIM
--------------------------- --------------------------- --------------------------- --------------------------- --------------------------- --------------------------- --------------------------- -------------------
                       0.00                        0.00                        0.00                       21.59                        1.36                        0.22                        0.00               46.86

Attached the statspack report

What do you think ?

Andrey

Attachment: MYDB_spreport_1_3.lst
(Size: 155.70KB, Downloaded 5189 times)

Report message to a moderator

Re: Time metrics in V$SQL don't add up [message #686301 is a reply to message #686300]

Thu, 21 July 2022 10:52

Andrey_R
Messages: 441
Registered: January 2012
Location: Israel

Senior Member

They seem to be asking for the same thing here in 2010 https://community.oracle.com/tech/developers/discussion/1120738/the-meaning-of-elapsed-time-in-sql

Yet I've seen no good answer.
In one of them, some folks point out to this article https://www.databasejournal.com/oracle/oracle-too-much-time-on-your-hands/ in which, if I understand correctly,
It is said that there could be a gap in the metrics due to a different measurement for parallel execution.
Nevertheless, it's SE2 so no parallelism is supposed to occur for SQLs ( well , and not much SQL happening at all )

I tried to review the statspack but I suspect I admin I couldn't make too much sense out of it as I'm not familiar with it to the point where I can see some parallels with the V$SQL metrics..

Anyone has an idea how to test this, or what it might be ?
Maybe it's like the Recursive SQLs in a trace file, which in V$SQL included in the ELAPSED but not in all the particles that should sum up to it ? hmm..

Andrey

Report message to a moderator

Re: Time metrics in V$SQL don't add up [message #686305 is a reply to message #686301]

Fri, 22 July 2022 01:15

John Watson
Messages: 8960
Registered: January 2010
Location: Global Village

Senior Member

Looking at your statspack report, there is really nothing happening in your database. It is reporting effectively no activity other than its own snapshots. In these circumstances, all the figures are meaningless.

Report message to a moderator

Re: Time metrics in V$SQL don't add up [message #686307 is a reply to message #686305]

Fri, 22 July 2022 16:35

Andrey_R
Messages: 441
Registered: January 2012
Location: Israel

Senior Member

I think I got closer to the answer, and please feel free to comment and argue:

Fetching. The time it takes for the data to be fetched over to the user process and displayed in the session.
I do not see it adding up to some understandable factor or such, but I do seem to recognize some consistency in some indications in my test:

So here it goes. First I'm preparing a clean user, a fresh table TT1 and some rows in it:

SQL> 
SQL> ho cls

SQL> set timing on
SQL> alter session set "_ORACLE_SCRIPT"=true;

Session altered.

Elapsed: 00:00:00.00
SQL> drop tablespace ATBS INCLUDING CONTENTS AND DATAFILES;

Tablespace dropped.

Elapsed: 00:00:00.70
SQL> drop user A cascade;

User dropped.

Elapsed: 00:00:00.44
SQL> 
SQL> 
SQL> 
SQL> CREATE TABLESPACE ATBS DATAFILE 'F:\ORACLE\DATABASE\ORADATA\XE\ATBS.DBF' SIZE 100M AUTOEXTEND ON NEXT 100 MAXSIZE UNLIMITED;

Tablespace created.

Elapsed: 00:00:00.95
SQL> CREATE USER A IDENTIFIED BY a default tablespace ATBS QUOTA UNLIMITED on ATBS;

User created.

Elapsed: 00:00:00.01
SQL> grant dba to a;

Grant succeeded.

Elapsed: 00:00:00.00
SQL> 
SQL> conn a/a
Connected.
SQL> 
SQL> create table TT1 as select DATA_TYPE,DATA_LENGTH from DBA_TAB_COLUMNS where rownum< 100001;

Table created.

Elapsed: 00:00:00.96
SQL> 
SQL> spool off

I prepared a RUN_QUERY.CMD with contents

[b]set termout off [/b]


SELECT ROWID FROM TT1; 



exit

I executed it and checked my analytic query on V$SQL:

SQL> set lines 1000 pages 1000
SQL> col UNAME for A8
SQL> col sql_text for a25
SQL> set num 15
SQL> select * from (
  2  SELECT
  3  PARSING_SCHEMA_NAME AS UNAME,SQL_ID,SQL_TEXT,rows_processed,
  4  to_char((
  5  total_APPLICATION_WT_s +
  6  total_CONCURRENCY_WT_s +
  7  total_CLUSTER_WT_s +
  8  total_CPU_time_S +
  9  total_USER_IO_WT_s ),'999,999.999') as all_wait_times_s,
 10  to_char(total_execution_time_S,'999,999.999') as total_execution_time_S,executions
 11   FROM (
 12  select
 13       V.PARSING_SCHEMA_NAME,V.SQL_ID,SQL_TEXT, executions,rows_processed,
 14       sum( v.APPLICATION_WAIT_TIME /1000000 ) as total_APPLICATION_WT_s,
 15       sum( v.CONCURRENCY_WAIT_TIME /1000000 ) as total_CONCURRENCY_WT_s,
 16       sum( v.CLUSTER_WAIT_TIME /1000000 )     as total_CLUSTER_WT_s,
 17       sum( v.CPU_TIME /1000000 )   as total_CPU_time_S,
 18       sum( v.USER_IO_WAIT_TIME /1000000 ) as total_USER_IO_WT_s,
 19       sum( v.ELAPSED_TIME /1000000 )  as total_execution_time_S
 20       --
 21    from gv$sql v
 22    where
 23  sql_text like '%SELECT ROWID FROM TT1%'
 24  and sql_text not like '%sql_text%'
 25    GROUP BY V.PARSING_SCHEMA_NAME,V.SQL_ID,SQL_TEXT,executions,rows_processed
 26  ) q
 27   );

UNAME    SQL_ID        SQL_TEXT                   ROWS_PROCESSED ALL_WAIT_TIM TOTAL_EXECUT      EXECUTIONS
-------- ------------- ------------------------- --------------- ------------ ------------ ---------------
A        g4uw599nftft5 SELECT ROWID FROM TT1              100000         .114         .127               1

Elapsed: 00:00:00.02
SQL>
SQL>
SQL>
SQL>

I already see a difference for ELAPSED_TIME (TOTAL_EXECUTE_TIME_S).
So I run it 9 more times and check again:

SQL> /

UNAME    SQL_ID        SQL_TEXT                   ROWS_PROCESSED ALL_WAIT_TIM TOTAL_EXECUT      EXECUTIONS
-------- ------------- ------------------------- --------------- ------------ ------------ ---------------
A        g4uw599nftft5 SELECT ROWID FROM TT1             1000000         .473         .502              10

Elapsed: 00:00:00.01

Observation1: ALL_WAIT_TIM/TOTAL_EXECUTION seems to be around 94%. We're missing some 0.029s

Now I am repeating my test ( dropping user, table et.c )
and re-performing it with one difference: I set termout on in my "SELECT_FROM_TT1.sql" .

I run for 10 times ( and it takes time because all the rows are displayed as they're fetched to the screen ) and measure with the V$SQL Query:

SQL> /

UNAME    SQL_ID        SQL_TEXT                   ROWS_PROCESSED ALL_WAIT_TIM TOTAL_EXECUT      EXECUTIONS
-------- ------------- ------------------------- --------------- ------------ ------------ ---------------
A        g4uw599nftft5 SELECT ROWID FROM TT1              998275         .976        1.280              10

Elapsed: 00:00:00.00
SQL>

Observation 2: The ratio between the two now shows as if we "lost" some 24%..

But I it also show twice the execution time ( also for the ALL_WAIT_TIME_S), even though the query didn't run with a different execution plan.

So seems like

A. The fetch of the rows to display on screen is accounted
B. The more it is happening - the more the symmetry between ALL_WAIT_TIME_S and ELAPSED_TIME_S breaks.

So it seems like the handover of data for display between the server process and the user process has an effect on the way the time is documented in V$SQL

Maybe it's related to the "CPU Starvation" idea that John suggested ( even though I can assume that on my clean machine it would be negligible )

Report message to a moderator

Re: Time metrics in V$SQL don't add up [message #686309 is a reply to message #686307]

Sat, 23 July 2022 07:39

John Watson
Messages: 8960
Registered: January 2010
Location: Global Village

Senior Member

I've used this test:

alter system flush buffer_cache;
alter system flush shared_pool;
set feedback on sql_id
alter session set tracefile_identifier=jw;
exec dbms_monitor.session_trace_enable(waits=>true)
select sum(amount_sold) from sh.sales;
exec dbms_monitor.session_trace_disable;

select application_wait_time,
concurrency_wait_time,
cluster_wait_time,
cpu_time,
user_io_wait_time,elapsed_time
from v$sql where sql_id='&sqlid';

and the figures don't balance in the way you think they should. From v$sql:

APPLICATION_WAIT_TIME CONCURRENCY_WAIT_TIME CLUSTER_WAIT_TIME        CPU_TIME USER_IO_WAIT_TIME    ELAPSED_TIME
--------------------- --------------------- ----------------- --------------- ----------------- ---------------
                    0                     0                 0          444089             44903          560795

1 row selected.

Which suggests that 13% of elapsed time is not accounted for. My first thought was that there are many wait events that wouldn't fit into app waits, concurrency waits, cluster waits or IO waits. You'll see all the wait classes in v$system_wait_class, "Other" is often worryingly high. So I extracted the relevant information from the trace, which should show all waits:

********************************************************************************

SQL ID: 6gppc767uqbv6 Plan Hash: 3519235612

select sum(amount_sold)
from
 sh.sales


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.09       0.12          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.11       0.18       1517       1544          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.20       0.31       1517       1544          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 160
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=1544 pr=1517 pw=0 time=188769 us starts=1)
    918843     918843     918843   PARTITION RANGE ALL PARTITION: 1 28 (cr=1544 pr=1517 pw=0 time=166070 us starts=1 cost=530 size=4594215 card=918843)
    918843     918843     918843    TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1544 pr=1517 pw=0 time=165384 us starts=28 cost=530 size=4594215 card=918843)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00
  db file sequential read                        32        0.00          0.00
  direct path read                              131        0.00          0.02
  PGA memory operation                            1        0.00          0.00
  SQL*Net message from client                     2        0.02          0.02
********************************************************************************

This doesn't balance either: elapsed time 0.31s, CPU time 0.2s, total wait time 0.04s. It does highlight one thing: the parse time. I don't know if parse is included in the v$sql figures.
My conclusion is that the instrumentation and the time accounting is not perfect. Perhaps it can't be: there will always be an "observer" effect in that the monitoring of activity will impact on the activity. The necessary information for tuning is there: which step of a plan is the slowest, and what wait events are occurring.

Report message to a moderator

Re: Time metrics in V$SQL don't add up [message #686311 is a reply to message #686309]

Sat, 23 July 2022 07:52

Andrey_R
Messages: 441
Registered: January 2012
Location: Israel

Senior Member

Thanks John.

No clear answer but definitely a bit more sense in the context of things now.
And if I'll check a systems "SQL Health" ( or maybe more correct would be "SQL Illness"... ) I'll just measure SEPARATELY the V$SQL [APP/PLSQL/JAVA/CONC/IO.. waits] , the [ELAPSED_TIME], and the parses.

I might give this topic another visit with some new benchmark and observations, once I get a bit more knowledgeable on behavior and specifics of parsing and their metrics.

Andrey

Report message to a moderator

Previous Topic:	Percentage of CPU utilization per instance
Next Topic:	any option for this query

Goto Forum:

-=] Back to Top [=-

[ Syndicate this forum (XML) ] [

]

Current Time: Sat Nov 23 03:33:28 CST 2024