[20221023]v$session_longops.txt
[20221023]v$session_longops.txt
--//重複測試,連結:
--//To demonstrate the principle that the "working time" for an operation and the elapsed time to completion can be
--//dramatically different I'll set up a two-table join and show that a "small tablescan" can (apparently) take a long time
--//and get into v$session_longops because of "the other" table. As a quick and dirty trick I'll create a function that
--//calls dbms_session.sleep() – the function that should be used to replace calls to dbms_lock.sleep()– to sleep for
--//1/100 second.
--//為了證明操作的工作時間和完成時間可能有顯著不同的原理,我將設定一個雙表連線,並顯示一個小表可以(顯然)需要很長時間並進
--//入v$session_longops,因為另一個表。作為一個快速而糟糕的技巧,我將建立一個呼叫dbms_session.sleep()的函式——這個應該
--//用於替換呼叫dbms_lock.sleep()的函式——以睡眠1/100秒。
1.環境:
SCOTT@book> @ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
2.指令碼建立:
create table t1
as
with generator as (
select
rownum id
from dual
connect by
level <= 1e4 -- > comment to avoid WordPress format issue
)
select
rownum id,
rownum n1,
lpad(rownum,10,'0') v1,
lpad('x',100,'x') padding
from
generator v1,
generator v2
where
rownum <= 1e6 -- > comment to avoid WordPress format issue
;
create table t2 as select * from t1;
alter table t2 add constraint t2_pk primary key(id);
create or replace function waste_time(i_in number) return number
as
begin
--dbms_session.sleep(0.01);
dbms_lock.sleep(0.01);
return i_in;
end;
/
--//注我分析了表T1,T2.
--//With the data and function in place I'll code (and hint) a nested loop join that starts with a full tablescan of t1
--//and probes t2 by primary key 1,000 times.
--//有了資料和函式,我將編碼(並提示)一個巢狀的迴圈連線,它從t1的完整表掃描開始,並透過主鍵探測t2 1000次。
3.執行:
SCOTT@book> @ sl all
alter session set statistics_level = all;
Session altered.
set timing on
select
/*+ leading(t1 t2) full(t1) use_nl_with_index(t2) */
sum(t1.id)
from
t1, t2
where
mod(t1.id,1000) = 0
and t2.id = t1.id
and t2.n1 != 0
/
SUM(T1.ID)
----------
500500000
Elapsed: 00:00:00.41
select
/*+ leading(t1 t2) full(t1) use_nl_with_index(t2) */
sum(t1.id)
from
t1, t2
where
mod(t1.id,1000) = 0
and t2.id = t1.id
and waste_time(t2.n1) != 0
/
SUM(T1.ID)
----------
500500000
Elapsed: 00:00:11.06
set timing off
--//Of course, thanks to the call to waste_time() passing in t2.n1 I expect the second version of the query to take at least
--//10 seconds longer than the first (given 1,000 waits of 0.01 seconds spent in the call).
--//當然,由於呼叫t2中的wase_time()。我預計第二個版本的查詢比第一個版本至少長10秒(給定在呼叫中花費1000次等待0.01秒)。
--//以下是作者的測試結果.
SUM(T1.ID)
----------
500500000
1 row selected.
Elapsed: 00:00:00.26
SUM(T1.ID)
----------
500500000
1 row selected.
Elapsed: 00:00:14.39
--//我的測試11秒.與他的測試結果不同, 但是不影響問題說明.
--//So the question is – what does v$session_longops say about any "long operations" for my session? Query and result:
--//所以問題是,v$session_longops對我的長期操作有何看法?查詢及結果:
select
sql_id,
sql_plan_line_id,
to_char(vsl.start_time,'dd hh24:mi:ss') start_time,
to_char(vsl.last_update_time,'dd hh24:mi:ss') last_time,
vsl.elapsed_seconds,
vsl.message
from
V$session_Longops vsl
where
vsl.sid = (select ms.sid from v$mystat ms where rownum = 1)
/
SQL_ID SQL_PLAN_LINE_ID START_TIME LAST_TIME ELAPSED_SECONDS MESSAGE
------------- ---------------- ----------- ----------- --------------- -----------------------------------------------------
4sjt90h0tsr3q 4 23 08:54:16 23 08:54:27 11 Table Scan: SCOTT.T1: 18028 out of 18028 Blocks done
--//So that looks like 14 seconds to do a tablescan of just 18,020 blocks. The number is very similar to the elapsed time
--//reported for the second of my two queries – but just to make sure let's use the reported SQL ID to pull the query and
--//plan from memory and check operation 4 for a tablescan of t1.
--//做一個只有18020個塊的表掃描看起來需要14秒。這個數字與我的兩個查詢中第二個報告的時間非常相似——但只是為了確保我們使用報
--//告的SQL ID從記憶體中提取查詢和計劃,並檢查t1的表掃描操作4。
SCOTT@book> @ dpc 4sjt90h0tsr3q '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID 4sjt90h0tsr3q, child number 0
-------------------------------------
select /*+ leading(t1 t2) full(t1) use_nl_with_index(t2) */
sum(t1.id) from t1, t2 where mod(t1.id,1000) = 0
and t2.id = t1.id and waste_time(t2.n1) != 0
Plan hash value: 1846150233
------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | Reads |
------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 24904 (100)| | 1 |00:00:11.01 | 20941 | 17853 |
| 1 | SORT AGGREGATE | | 1 | 1 | 15 | | | 1 |00:00:11.01 | 20941 | 17853 |
| 2 | NESTED LOOPS | | 1 | 10000 | 146K| 24904 (1)| 00:04:59 | 1000 |00:00:11.01 | 20941 | 17853 |
| 3 | NESTED LOOPS | | 1 | 10000 | 146K| 24904 (1)| 00:04:59 | 1000 |00:00:00.56 | 19858 | 17853 |
|* 4 | TABLE ACCESS FULL | T1 | 1 | 10000 | 50000 | 4898 (1)| 00:00:59 | 1000 |00:00:00.54 | 17856 | 17853 |
|* 5 | INDEX UNIQUE SCAN | T2_PK | 1000 | 1 | | 1 (0)| 00:00:01 | 1000 |00:00:00.02 | 2002 | 0 |
|* 6 | TABLE ACCESS BY INDEX ROWID| T2 | 1000 | 1 | 10 | 2 (0)| 00:00:01 | 1000 |00:00:10.44 | 1083 | 0 |
------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
4 - SEL$1 / T1@SEL$1
5 - SEL$1 / T2@SEL$1
6 - SEL$1 / T2@SEL$1
Predicate Information (identified by operation id):
---------------------------------------------------
4 - filter(MOD("T1"."ID",1000)=0)
5 - access("T2"."ID"="T1"."ID")
6 - filter("WASTE_TIME"("T2"."N1")<>0)
35 rows selected.
--//結合上面看,實際上消耗最大的還是在id=6上而不是id=4.也就是不是V$session_Longops上顯示的Table Scan: SCOTT.T1: 18028
--//out of 18028 Blocks done.很容易出現歧義.
--//作者在註解處加入註解:
--//v$session_longops (Oct 2022): how to interpret the information. It's not the answer, it's a clue. […]
--//如果修改建立函式索引如下:
SCOTT@book> create index if_t1_id on t1(mod(id,1000)) ;
Index created.
select
/*+ leading(t1 t2) index(t1) use_nl_with_index(t2) */
sum(t1.id)
from
t1, t2
where
mod(t1.id,1000) = 0
and t2.id = t1.id
and waste_time(t2.n1) != 0
/
SUM(T1.ID)
----------
500500000
Elapsed: 00:00:11.03
SCOTT@book> @ dpc '' '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID bquvd2kv3ugkd, child number 0
-------------------------------------
select /*+ leading(t1 t2) index(t1) use_nl_with_index(t2) */
sum(t1.id) from t1, t2 where mod(t1.id,1000) = 0
and t2.id = t1.id and waste_time(t2.n1) != 0
Plan hash value: 1272872847
----------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | Reads |
----------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 24010 (100)| | 1 |00:00:11.00 | 4006 | 991 |
| 1 | SORT AGGREGATE | | 1 | 1 | 28 | | | 1 |00:00:11.00 | 4006 | 991 |
| 2 | NESTED LOOPS | | 1 | 10000 | 273K| 24010 (1)| 00:04:49 | 1000 |00:00:11.00 | 4006 | 991 |
| 3 | NESTED LOOPS | | 1 | 10000 | 273K| 24010 (1)| 00:04:49 | 1000 |00:00:00.08 | 3006 | 991 |
| 4 | TABLE ACCESS BY INDEX ROWID| T1 | 1 | 10000 | 175K| 4005 (1)| 00:00:49 | 1000 |00:00:00.06 | 1004 | 991 |
|* 5 | INDEX RANGE SCAN | IF_T1_ID | 1 | 4000 | | 4 (0)| 00:00:01 | 1000 |00:00:00.01 | 4 | 3 |
|* 6 | INDEX UNIQUE SCAN | T2_PK | 1000 | 1 | | 1 (0)| 00:00:01 | 1000 |00:00:00.02 | 2002 | 0 |
|* 7 | TABLE ACCESS BY INDEX ROWID | T2 | 1000 | 1 | 10 | 2 (0)| 00:00:01 | 1000 |00:00:10.91 | 1000 | 0 |
----------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
4 - SEL$1 / T1@SEL$1
5 - SEL$1 / T1@SEL$1
6 - SEL$1 / T2@SEL$1
7 - SEL$1 / T2@SEL$1
Predicate Information (identified by operation id):
---------------------------------------------------
5 - access("T1"."SYS_NC00005$"=0)
6 - access("T2"."ID"="T1"."ID")
7 - filter("WASTE_TIME"("T2"."N1")<>0)
37 rows selected.
select
sql_id,
sql_plan_line_id,
to_char(vsl.start_time,'dd hh24:mi:ss') start_time,
to_char(vsl.last_update_time,'dd hh24:mi:ss') last_time,
vsl.elapsed_seconds,
vsl.message
from
V$session_Longops vsl
where
vsl.sid = (select ms.sid from v$mystat ms where rownum = 1)
/
SQL_ID SQL_PLAN_LINE_ID START_TIME LAST_TIME ELAPSED_SECONDS MESSAGE
------------- ---------------- ----------- ----------- --------------- -----------------------------------------------------
4sjt90h0tsr3q 4 23 08:58:12 23 08:58:23 11 Table Scan: SCOTT.T1: 18028 out of 18028 Blocks done
bquvd2kv3ugkd 4 23 09:04:26 23 09:04:37 11 Table Scan: SCOTT.T1: 18028 out of 18028 Blocks done
--//還是提示Table Scan: SCOTT.T1: 18028 out of 18028 Blocks done.
SCOTT@book> @ sosiz scott t1
**********************************
Table Level 引數 schema tablename
**********************************
Table Number Empty Average Chain Average Global User Sample
Name of Rows Blocks Blocks Space Count Row Len Stats Stats Size LAST_ANALYZED
--------------- -------------- ------------ ------------ -------- -------- -------- ------ ------ -------------- -------------------
T1 1,000,000 18,028 0 0 0 122 YES NO 1,000,000 2022-11-23 08:57:35
Column Column Distinct Number Number Global User Sample
Name Details Values Density Buckets Nulls Stats Stats Size LAST_ANALYZED HISTOGRAM
------------------------- ------------------------ ------------ ----------- ------- ---------- ------ ------ -------------- ------------------- ---------------
ID NUMBER(22) 1,000,000 0.00000100 1 0 YES NO 1,000,000 2022-11-23 08:57:35 NONE
N1 NUMBER(22) 1,000,000 0.00000100 1 0 YES NO 1,000,000 2022-11-23 08:57:35 NONE
V1 VARCHAR2(20) 1,000,000 0.00000100 1 0 YES NO 1,000,000 2022-11-23 08:57:35 NONE
PADDING VARCHAR2(100) 1 1.00000000 1 0 YES NO 1,000,000 2022-11-23 08:57:35 NONE
B Average Average
Index Tree Leaf Distinct Number Leaf Blocks Data Blocks Cluster Global User Sample
Name Unique Level Blks Keys of Rows Per Key Per Key Factor Stats Stats Size LAST_ANALYZED
------------------------- --------- ----- ------ -------------- -------------- ----------- ----------- ------------ ------ ------ -------------- -------------------
IF_T1_ID NONUNIQUE 2 2077 1,000 1,000,000 2 1,000 1,000,000 YES NO 1,000,000 2022-11-23 09:07:34
--//這個更加容易理解錯誤,我不掃描表T1,T1表的Blocks=18028,走的是索引IF_T1_ID.而執行計劃sql_id=bquvd2kv3ugkd,提示還是
--//Table Scan: SCOTT.T1: 18028 out of 18028 Blocks done.
Summary
When you see an entry in v$session_longops it is an indicator to an operation that took a "long" time to complete; but
"completion" of the operation and "work done" by the operation are not the same thing. The operation may be the victim
of a problem, not the cause. If the problem query is still in memory then v$session_long_ops gives you enough
information to find the query (and check you're looking at the right plan) so that you have a better chance of
identifying the real offender.
當您在v$session_longops中看到一個條目時,它是一個操作的指示器,需要長時間來完成操作和已完成的工作透過操作不是一回事。這
次手術可能是問題的受害者,而不是原因。如果問題查詢仍然在記憶體中,那麼v$session_long_ops將給您足夠的資訊來找到查詢(並檢查
您是否檢視正確的計劃),這樣您就有更好的機會識別真正的違規者。
--//也就是 v$session_longops提示有一條語句執行很慢,不能依靠MESSAGE提示資訊解決定位問題.
來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/267265/viewspace-2924661/,如需轉載,請註明出處,否則將追究法律責任。
相關文章
- 前端【VUE】02-vue指令【v-html 、v-show、 v-if 、v-else、v-on、v-bind、v-for、v-model】前端VueHTML
- v$sql,v$sqlarea,v$sqltext區別SQL
- vue v-text,v-html,v-once,v-pre,v-cloak的使用VueHTML
- vue_o6_v-once、v-html、v-text、v-pre、v-cloak指令的使用VueHTML
- EMQ 文件 V1.0 V2.0 V3.0MQ
- v-if和v-show
- CANoe C-V2X Demo(V2I+V2V)演示視訊
- 維數定理(手推!):證明dim(v1)+dim(v2) = dim(v1+v2) + dim(v1∩v2)
- 1V升壓3V,1V升壓3.3V晶片,1V升壓5V升壓IC晶片
- v-html 、v-text({{}}) 、v-model的區別HTML
- v
- 1V升3V,1V升3.3V,1V升5V高電流,低功耗升壓晶片晶片
- 24v轉120v,24V轉150v/350v隔離變壓電源模組
- vue 的v-on與v-bindVue
- v-for,v-bink,綜合案例
- 1V升5V晶片,1V升5V電路圖規格書晶片
- Oracle9i中v$sql、v$sqlarea、v$sqltext、v$sql_plan的聯絡與區別OracleSQL
- android之support-v4、v7、v13的區別Android
- v-for
- (精華2020年5月4日更新) vue教程篇 v-text,v-html,v-once,v-pre,v-cloak的使用VueHTML
- Vue v-if以及 v-else 的使用Vue
- v-if和v-show的區別
- [vue] 常見用法之 v-html、v-text、v-model區別VueHTML
- React Router從V2/V3到V4的變化React
- v-if/v-show 條件渲染指令
- ESXI 遷移至KVM (V2V遷移)
- 12V轉80V/150V/350V電容充電隔離電源升壓模組
- 1V轉5V,1V轉3.3V升壓極大電流晶片,外圍極少晶片
- v-model
- v-bind
- 10.29 V$SESSMETRICSSM
- 10.30 V$SESSTAT
- 10.97 V$SYSSTAT
- 8.1.1 V$ ViewsView
- 10.17 V$SESSIONSession
- 10.82 V$STATNAME
- 9.183 V$ROLLNAME
- 9.184 V$ROLLSTAT