Home » RDBMS Server » Performance Tuning » Time metrics in V$SQL don't add up (Oracle 19c SE2 )
Time metrics in V$SQL don't add up [message #686293] |
Wed, 20 July 2022 18:35 ![Go to next message Go to next message](/forum/theme/orafaq/images/down.png) |
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
|
|
|
Re: Time metrics in V$SQL don't add up [message #686295 is a reply to message #686293] |
Thu, 21 July 2022 01:54 ![Go to previous message Go to previous message](/forum/theme/orafaq/images/up.png) ![Go to next message Go to next message](/forum/theme/orafaq/images/down.png) |
John Watson
Messages: 8944 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.
|
|
|
Re: Time metrics in V$SQL don't add up [message #686300 is a reply to message #686295] |
Thu, 21 July 2022 10:14 ![Go to previous message Go to previous message](/forum/theme/orafaq/images/up.png) ![Go to next message Go to next message](/forum/theme/orafaq/images/down.png) |
Andrey_R
Messages: 441 Registered: January 2012 Location: Israel
|
Senior Member |
|
|
John Watson wrote on Thu, 21 July 2022 09:54A 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
|
|
|
|
Re: Time metrics in V$SQL don't add up [message #686305 is a reply to message #686301] |
Fri, 22 July 2022 01:15 ![Go to previous message Go to previous message](/forum/theme/orafaq/images/up.png) ![Go to next message Go to next message](/forum/theme/orafaq/images/down.png) |
John Watson
Messages: 8944 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.
|
|
|
Re: Time metrics in V$SQL don't add up [message #686307 is a reply to message #686305] |
Fri, 22 July 2022 16:35 ![Go to previous message Go to previous message](/forum/theme/orafaq/images/up.png) ![Go to next message Go to next message](/forum/theme/orafaq/images/down.png) |
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 )
|
|
|
Re: Time metrics in V$SQL don't add up [message #686309 is a reply to message #686307] |
Sat, 23 July 2022 07:39 ![Go to previous message Go to previous message](/forum/theme/orafaq/images/up.png) ![Go to next message Go to next message](/forum/theme/orafaq/images/down.png) |
John Watson
Messages: 8944 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.
|
|
|
Re: Time metrics in V$SQL don't add up [message #686311 is a reply to message #686309] |
Sat, 23 July 2022 07:52 ![Go to previous message Go to previous message](/forum/theme/orafaq/images/up.png) |
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
|
|
|
Goto Forum:
Current Time: Sat Aug 31 20:46:40 CDT 2024
|