[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提示資訊解決定位問題.

[20221023]v$session_longops.txt

相關文章