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

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

--//昨天測試12c 10046跟蹤時間戳與原來11g不同,以前這裡記錄的從1970/1/1 UTC 的微秒數,而現在明顯偏小.
--//晚上驗證看看這個偏移量來自那裡.

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

2.建立測試指令碼並執行:
$ cat ba.sql
@ 10046on 12
select systimestamp from dual ;
@ 10046off

SCOTT@test01p> @ ba.sql
Session altered.
SYSTIMESTAMP
--------------------------
2020-08-18 20:56:49.472000
Session altered.


3.檢查跟蹤檔案內容:

=====================
PARSING IN CURSOR #792350760 len=30 dep=0 uid=81 oct=3 lid=81 tim=1271948665 hv=2569258288 ad='7ff11d1dd90' sqlid='8hwwkpuck7j9h'
select systimestamp from dual
END OF STMT
PARSE #792350760:c=62400,e=91121,p=0,cr=236,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1271948664
EXEC #792350760:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1271948872
WAIT #792350760: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1271948959
FETCH #792350760:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1271949095
STAT #792350760 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 str=1 time=3 us cost=2 size=0 card=1)'
WAIT #792350760: nam='SQL*Net message from client' ela= 15311 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1271964570
FETCH #792350760:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=1271964708
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
WAIT #792350760: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1271964755
WAIT #792350760: nam='SQL*Net message from client' ela= 14640 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1271979428
CLOSE #792350760:c=0,e=11,dep=0,type=0,tim=1271979539
=====================

$ ./xdate.sh 1271964708
1970-01-01 08:21:11.964708000

$ date -d "2020-08-18 20:56:49.472000 -1271.964708 seconds" +"%Y-%m-%d %T.%N"
2020-08-18 20:35:37.507292000
--//偏移量是2020-08-18 20:35:37.507292000.
--//我檢查oracle v$database,v$instance,v$thread檢視裡面有關時間的資訊,根本對不上,無論從cdb還是pdb看,看到的時間都要晚.
--//我重複執行指令碼多次.

SCOTT@test01p> @ ba
Session altered.
SYSTIMESTAMP
--------------------------
2020-08-18 21:14:32.191000
Session altered.

--//跟蹤檔案內容:
=====================
PARSING IN CURSOR #615598984 len=30 dep=0 uid=81 oct=3 lid=81 tim=2334648609 hv=2569258288 ad='7ff006d2ef8' sqlid='8hwwkpuck7j9h'
select systimestamp from dual
END OF STMT
PARSE #615598984:c=62401,e=60225,p=0,cr=236,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=2334648607
EXEC #615598984:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=2334648819
WAIT #615598984: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2334648896
FETCH #615598984:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=2334648956
STAT #615598984 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 str=1 time=2 us cost=2 size=0 card=1)'
WAIT #615598984: nam='SQL*Net message from client' ela= 550 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2334649650
FETCH #615598984:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=2334649719
WAIT #615598984: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2334649755
WAIT #615598984: nam='SQL*Net message from client' ela= 1198 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2334650984
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
CLOSE #615598984:c=0,e=8,dep=0,type=0,tim=2334651068
=====================

$ date -d "2020-08-18 21:14:32.191000 -2334.650984 seconds" +"%Y-%m-%d %T.%N"
2020-08-18 20:35:37.540016000
--//基本偏移在2020-08-18 20:35:37.

SYS@test> select * from v$instance
  2  @ prxx
==============================
INSTANCE_NUMBER               : 1
INSTANCE_NAME                 : test
HOST_NAME                     : ZWS
VERSION                       : 12.2.0.1.0
STARTUP_TIME                  : 2020-08-18 20:53:05
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
STATUS                        : OPEN
PARALLEL                      : NO
THREAD#                       : 1
ARCHIVER                      : STARTED
LOG_SWITCH_WAIT               :
LOGINS                        : ALLOWED
SHUTDOWN_PENDING              : NO
DATABASE_STATUS               : ACTIVE
INSTANCE_ROLE                 : PRIMARY_INSTANCE
ACTIVE_STATE                  : NORMAL
BLOCKED                       : NO
CON_ID                        : 0
INSTANCE_MODE                 : REGULAR
EDITION                       : EE
FAMILY                        :
DATABASE_TYPE                 : SINGLE
PL/SQL procedure successfully completed.

SYS@test> select * from v$thread
  2  @ prxx
==============================
THREAD#                       : 1
STATUS                        : OPEN
ENABLED                       : PUBLIC
GROUPS                        : 3
INSTANCE                      : test
OPEN_TIME                     : 2020-08-18 20:53:38
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
CURRENT_GROUP#                : 1
SEQUENCE#                     : 169
CHECKPOINT_CHANGE#            : 12268220
CHECKPOINT_TIME               : 2020-08-18 20:53:38
ENABLE_CHANGE#                : 1
ENABLE_TIME                   : 2018-10-06 21:16:41
DISABLE_CHANGE#               : 0
DISABLE_TIME                  :
LAST_REDO_SEQUENCE#           : 169
LAST_REDO_BLOCK               : 119235
LAST_REDO_CHANGE#             : 12270513
LAST_REDO_TIME                : 2020-08-18 21:02:51
CON_ID                        : 0
PL/SQL procedure successfully completed.

--//看了視乎windows系統這個偏差來源於,可以透過systeminfo啟動觀察.
$ systeminfo | grep 2020
系統啟動時間:     2020/8/18, 20:35:39
--//對比前面計算還是存在2秒的差值.真心不知道偏移量來之那裡.

--//注:在windows下執行透過管道報錯.
d:\> systeminfo | grep "2020"
grep: writing output: Invalid argument


4.附上xdate指令碼:
$ 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"