[20221023]v$session_longops.txt
--//重复测试,链接:https://jonathanlewis.wordpress.com/2022/10/13/vsession_longops-2/
--//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博客 ” ，链接：https://blog.itpub.net/267265/viewspace-2924661/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
- [20261002]验证sskgphpjw函数参与运算的字符串是否存在规律.txt
- [20261002]oracle Semaphore Arrays Key值的计算2.txt
- [20261001]oracle Semaphore Arrays Key值的计算.txt
