[20200818]12c 10046跟蹤時間戳.txt

[20200818]12c 10046跟蹤時間戳.txt

--//昨天被別人問一個問題,10046跟蹤檔案裡面的tim=NNNNNNNN,記錄的時間是等待事件的開始時間還是結束時間.
--//透過SQL*Net message from client等待事件很容易驗證.

1.環境:
SCOTT@test01p> @ ver1
PORT_STRING          VERSION    BANNER                                                                       CON_ID
-------------------- ---------- ---------------------------------------------------------------------------- ------
IBMPC/WIN_NT64-9.1.0 12.2.0.1.0 Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production      0

SYS@test> @ ev_name 'sql*net%message'
EVENT#   EVENT_ID NAME                               PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS DISPLAY_NAME                       CON_ID
------ ---------- ---------------------------------- ---------- ---------- ---------- ------------- ----------- ---------- ---------------------------------- ------
   414 2067390145 SQL*Net message to client          driver id  #bytes                   2000153315           7 Network    SQL*Net message to client          0
   415 3655533736 SQL*Net message to dblink          driver id  #bytes                   2000153315           7 Network    SQL*Net message to dblink          0
   418 1421975091 SQL*Net message from client        driver id  #bytes                   2723168908           6 Idle       SQL*Net message from client        0
   420 4093028837 SQL*Net message from dblink        driver id  #bytes                   2000153315           7 Network    SQL*Net message from dblink        0
   422  483818214 SQL*Net vector message from client driver id  #bytes                   2723168908           6 Idle       SQL*Net vector message from client 0
   423  599122182 SQL*Net vector message from dblink driver id  #bytes                   2723168908           6 Idle       SQL*Net vector message from dblink 0
6 rows selected.

--//SQL*Net message from client 的 WAIT_CLASS 是 Idle,SQL*Net message to client的WAIT_CLASS 是Network.
--//這也是容易混淆的原因.如果網路出現問題,要特別關注SQL*Net message from client等待事件.

2.建立測試環境:

$ cat aa.sql
@ 10046on 12
host sleep 5
select * from dept ;
host sleep 7
@ 10046off

SCOTT@test01p> @ aa.sql
old   1: alter session set events '10046 trace name context forever, level &1'
new   1: alter session set events '10046 trace name context forever, level 12'
Session altered.
    DEPTNO DNAME                LOC
---------- -------------------- -------------
        10 ACCOUNTING           NEW YORK
        20 RESEARCH             DALLAS
        30 SALES                CHICAGO
        40 OPERATIONS           BOSTON
Session altered.

3.檢查跟蹤檔案:
*** 2020-08-17T21:26:54.563896+08:00 (TEST01P(3))
*** SESSION ID:(100.40420) 2020-08-17T21:26:54.563896+08:00
*** CLIENT ID:() 2020-08-17T21:26:54.563896+08:00
*** SERVICE NAME:(test01p) 2020-08-17T21:26:54.563896+08:00
*** MODULE NAME:(SQL*Plus) 2020-08-17T21:26:54.563896+08:00
*** ACTION NAME:() 2020-08-17T21:26:54.563896+08:00
*** CLIENT DRIVER:(SQL*PLUS) 2020-08-17T21:26:54.563896+08:00
*** CONTAINER ID:(3) 2020-08-17T21:26:54.563896+08:00
WAIT #646039264: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2566974777
*** 2020-08-17T21:26:59.688189+08:00 (TEST01P(3))
WAIT #646039264: nam='SQL*Net message from client' ela= 5123815 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2572119986
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
CLOSE #646039264:c=0,e=33,dep=0,type=1,tim=2572120470
=====================
PARSING IN CURSOR #646021600 len=19 dep=0 uid=81 oct=3 lid=81 tim=2572120902 hv=4071881952 ad='7ff11e35c78' sqlid='4g0qfgmtb7z70'
select * from dept
END OF STMT
PARSE #646021600:c=0,e=238,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=2572120899
EXEC #646021600:c=0,e=88,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3383998547,tim=2572121955
WAIT #646021600: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2572122196
FETCH #646021600:c=0,e=502,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3383998547,tim=2572122875
WAIT #646021600: nam='SQL*Net message from client' ela= 6393 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2572129463
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
WAIT #646021600: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2572129793
FETCH #646021600:c=0,e=241,p=0,cr=4,cu=0,mis=0,r=3,dep=0,og=1,plh=3383998547,tim=2572129980
STAT #646021600 id=1 cnt=4 pid=0 pos=1 obj=22487 op='TABLE ACCESS FULL DEPT (cr=8 pr=0 pw=0 str=1 time=242 us cost=3 size=80 card=4)'
--//資料在這裡傳送到客戶端.
*** 2020-08-17T21:27:06.844598+08:00 (TEST01P(3))
WAIT #646021600: nam='SQL*Net message from client' ela= 7145543 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2579276231
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
CLOSE #646021600:c=0,e=21,dep=0,type=0,tim=2579276707
=====================
PARSING IN CURSOR #646021600 len=55 dep=0 uid=81 oct=42 lid=81 tim=2579276952 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #646021600:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=2579276950
EXEC #646021600:c=0,e=1571,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=2579279123

--//注:看下劃線ela,時間單位是微秒.你可以發現前後2個都很大(一個5秒,7秒),實際上第1個,第3個出現等待事件'SQL*Net message
--//from client'.而僅僅第2個才是我們在最佳化時關注的情況,而第1次,第3次實際上我打入命令後,等待打入下一個命令命令的等待時間,
--//完全是idle等待事件.

WAIT #646039264: nam='SQL*Net message from client' ela= 5123815 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2572119986
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
CLOSE #646039264:c=0,e=33,dep=0,type=1,tim=2572120470

--//看看這2條tim的差值,2572120470-2572119986 = 484,單位是微秒.可以發現兩者的時間相差很小.可以推斷tim記錄的時間戳是該等待
--//事件的結束時間.

--//因為如果tim記錄的時間戳是該等待事件的開始時間.這樣2條tim的差值大於5XXXXXX.這樣明顯不對或者解析不通.

4.疑問:
--//12c 10046跟蹤檔案的tim與11g版本存在不同.以前這裡記錄的從1970/1/1 UTC 的微秒數,而現在明顯偏小.

$ ./xdate.sh 2572119986
1970-01-01 08:42:52.119986000
--//很明顯現在情況發生了變化,這個記錄是相對偏移.猜測一下我開機並開啟資料庫的時間並不長.可能是某個偏移+42分52秒.
--//當時測試沒有注意,晚上再寫一篇blog驗證看看取的是那個時間.

--//附上xdate.sh指令碼:
$ cat xdate.sh
#! /bin/bash
#date -d "1970-01-01 00:00:00  UTC  $( echo "scale=6; $1/1000000"  |bc -l) seconds" +"%Y-%m-%d %T.%N"
date -d "@$( echo "scale=6; $1/1000000"  |bc -l)" +"%Y-%m-%d %T.%N"