[20201118]18c 10046跟蹤時間戳3(虛擬機器).txt

[20201118]18c 10046跟蹤時間戳3(虛擬機器).txt

--//以前寫的http://blog.itpub.net/267265/viewspace-2712755/=>[20200818]12c 10046跟蹤時間戳.txt
--//http://blog.itpub.net/267265/viewspace-2712756/=>[20200818]12c 10046跟蹤時間戳2.txt
--//我當時想當然的以為僅僅windows系統會使用這個時間戳偏移，它來之系統啟動時間，我以前看到9i for windows就是使用系統啟動
--//時間的偏移。
--//今天我找一臺linux下機器驗證，發現跟蹤檔案裡面的時間戳還是來自系統啟動時間的偏移量。
--//難道我記憶哪裡出錯了，oracle為什麼要這樣做呢，我再仔細看發現我測試這臺伺服器實際上在虛擬機器。

1.環境：
SYS@192.168.x.y:1521/orcl> select banner from v$version where rownum=1;
BANNER
----------------------------------------------------------------------
Oracle Database 18c Enterprise Edition Release 18.0.0.0.0 - Production

# cat /etc/redhat-release
Red Hat Enterprise Linux Server release 7.8 (Maipo)

# dmidecode  | grep -i vmware
        Manufacturer: VMware, Inc.
        Product Name: VMware Virtual Platform
        Serial Number: VMware-42 35 1f 25 1c 6f 63 32-f1 8a 76 4a 12 10 67 68
        Description: VMware SVGA II
--//說明安裝在虛擬機器上。

2.測試：
SYS@192.168.x.y:1521/orcl> @ 10046on 12
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.

SYS@192.168.x.y:1521/orcl> select sysdate from dual ;
SYSDATE
-------------------
2020-11-18 10:16:34

SYS@192.168.x.y:1521/orcl> @ 10046off
Session altered.

3.檢查跟蹤檔案內容可以發現：
WAIT #140224663102584: nam='Disk file operations I/O' ela= 103 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=30146852944076
WAIT #140224663102584: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=30146852945537

*** 2020-11-18T10:16:34.636063+08:00 (ORCL(3))
WAIT #140224663102584: nam='SQL*Net message from client' ela= 8173018 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=30146861118609
CLOSE #140224663102584:c=12,e=12,dep=0,type=1,tim=30146861118788
=====================
PARSING IN CURSOR #140224638394688 len=25 dep=0 uid=0 oct=3 lid=0 tim=30146861120800 hv=409144692 ad='e3404ca8' sqlid='f0wzs9nc663bn'
select sysdate from dual
END OF STMT
PARSE #140224638394688:c=1714,e=1956,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=30146861120799
---// 執行xdate
$ xdate 30146861120799
1970-12-16 06:07:41.120799000
--// 很明顯這個時間戳不是來之從1970/1/1 UTC 的微秒數。
EXEC #140224638394688:c=128,e=127,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=30146861121048
WAIT #140224638394688: nam='Disk file operations I/O' ela= 39 FileOperation=8 fileno=0 filetype=8 obj#=-1 tim=30146861121164
WAIT #140224638394688: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=30146861121232
FETCH #140224638394688:c=17,e=18,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=30146861121294
STAT #140224638394688 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 #140224638394688: nam='SQL*Net message from client' ela= 709 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=30146861122151
FETCH #140224638394688:c=2,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=30146861122236
WAIT #140224638394688: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=30146861122273

*** 2020-11-18T10:16:37.532233+08:00 (ORCL(3))
WAIT #140224638394688: nam='SQL*Net message from client' ela= 2892471 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=30146864014768
CLOSE #140224638394688:c=12,e=12,dep=0,type=0,tim=30146864015060
=====================
PARSING IN CURSOR #140224638394688 len=55 dep=0 uid=0 oct=42 lid=0 tim=30146864015416 hv=2217940283 ad='0' sqlid='06nvwn223659v'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #140224638394688:c=271,e=271,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=30146864015416
EXEC #140224638394688:c=581,e=712,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=30146864016229

4.那麼對於這個偏移來自哪裡呢?

$ cat /proc/uptime
30147243.30 116822985.23

--//第一個時間是開機執行的秒數。很接近前面看到的秒數,上面的單位是微秒，1微秒等於百萬分之一秒(10的負6次方秒).
--//編寫指令碼如下：(拿以前寫tdemsg指令碼修改如下)
# offdate uptime 30146861120799
2020-11-18 10:16:34

--//指令碼如下：
# cat offdate
#! /bin/bash
FORMAT="%Y-%m-%d %T.%N"

now=$(date +%s)
cputime=$(grep -m1 "sched_clk" /proc/sched_debug | cut -f2 -d: )
uptime=$(grep -m1 "ktime" /proc/sched_debug | cut -f2 -d: )

# echo $now $cputime $uptime

if [ "$1" == "uptime" ] ; then
        cputime=$uptime
else
        cputime=$cputime
fi

offset=$( echo $2 / 1000000 | bc -l )
stamp=$( echo $now - $cputime / 1000 + $offset  | bc -l )
#echo "$(date -d "1970-01-01 00:00:00 UTC $stamp seconds" +"${FORMAT}") $line"
echo "$(date -d "@${stamp}" +"${FORMAT}")"

--//注意這個計算存在很多缺陷，第一你必須在服務端執行，因為開機時間在服務端，另外如果跟蹤檔案與當前時間很久遠，計算誤差很大。
--//可以使用cputime作為第2個引數計算，但是還是存在誤差，可以參考連結
--//http://blog.itpub.net/267265/viewspace-2680811/ => [20200316]dmesg與時間戳2.txt
--//http://blog.itpub.net/267265/viewspace-2680811/ => [20200317]dmesg與時間戳3.txt
--//我的測試環境：
# tdmesg
2020-11-16 10:06:02: [28345153.334274] 2020/11/16 10:00:01
2020-11-16 11:05:54: [28348745.577448] 2020/11/16 11:00:01
2020-11-16 12:05:47: [28352338.819503] 2020/11/16 12:00:01
2020-11-16 13:05:40: [28355931.133599] 2020/11/16 13:00:01
2020-11-16 14:05:32: [28359523.393676] 2020/11/16 14:00:01
2020-11-16 15:05:25: [28363116.658326] 2020/11/16 15:00:01
2020-11-16 16:05:18: [28366708.917992] 2020/11/16 16:00:01
2020-11-16 17:05:11: [28370302.189565] 2020/11/16 17:00:01
2020-11-16 18:05:03: [28373894.437457] 2020/11/16 18:00:01
2020-11-16 19:04:55: [28377486.674114] 2020/11/16 19:00:01
2020-11-16 20:04:49: [28381079.935263] 2020/11/16 20:00:01
2020-11-16 21:04:41: [28384672.196371] 2020/11/16 21:00:01
2020-11-16 22:04:34: [28388265.426788] 2020/11/16 22:00:01
2020-11-16 23:04:26: [28391857.655986] 2020/11/16 23:00:01
2020-11-17 00:04:19: [28395450.058134] 2020/11/17 00:00:01
2020-11-17 01:04:12: [28399043.265290] 2020/11/17 01:00:01
2020-11-17 02:04:05: [28402635.972930] 2020/11/17 02:00:01
2020-11-17 03:03:57: [28406228.486767] 2020/11/17 03:00:01
2020-11-17 04:03:49: [28409820.816700] 2020/11/17 04:00:01
2020-11-17 05:03:42: [28413413.508483] 2020/11/17 05:00:01
2020-11-17 06:03:35: [28417005.964601] 2020/11/17 06:00:01
2020-11-17 07:03:28: [28420599.202515] 2020/11/17 07:00:01
2020-11-17 08:03:20: [28424191.705563] 2020/11/17 08:00:01
2020-11-17 09:03:13: [28427783.967290] 2020/11/17 09:00:01
2020-11-17 10:03:05: [28431376.766519] 2020/11/17 10:00:01
2020-11-17 11:02:58: [28434969.403589] 2020/11/17 11:00:01
2020-11-17 12:02:51: [28438562.645236] 2020/11/17 12:00:01
2020-11-17 13:02:43: [28442154.665491] 2020/11/17 13:00:01
2020-11-17 14:02:37: [28445747.923185] 2020/11/17 14:00:01
2020-11-17 15:02:29: [28449340.057217] 2020/11/17 15:00:01
2020-11-17 16:02:22: [28452933.307610] 2020/11/17 16:00:01
2020-11-17 17:02:14: [28456525.838084] 2020/11/17 17:00:01
2020-11-17 18:02:07: [28460118.087813] 2020/11/17 18:00:01
2020-11-17 19:02:00: [28463710.912744] 2020/11/17 19:00:01
2020-11-17 20:01:52: [28467303.173746] 2020/11/17 20:00:01
2020-11-17 21:01:45: [28470896.431236] 2020/11/17 21:00:01
2020-11-17 22:01:37: [28474488.698584] 2020/11/17 22:00:01
2020-11-17 23:01:31: [28478081.952897] 2020/11/17 23:00:01
2020-11-18 00:01:23: [28481674.336027] 2020/11/18 00:00:01
2020-11-18 01:01:15: [28485266.584552] 2020/11/18 01:00:01
2020-11-18 02:01:08: [28488859.796401] 2020/11/18 02:00:01
2020-11-18 03:01:01: [28492452.033651] 2020/11/18 03:00:01
2020-11-18 04:00:54: [28496045.274463] 2020/11/18 04:00:01
2020-11-18 05:00:47: [28499637.881315] 2020/11/18 05:00:01
2020-11-18 06:00:39: [28503230.127465] 2020/11/18 06:00:01
2020-11-18 07:00:32: [28506823.375056] 2020/11/18 07:00:01
2020-11-18 08:00:24: [28510415.595099] 2020/11/18 08:00:01
2020-11-18 09:00:16: [28514007.819326] 2020/11/18 09:00:01
2020-11-18 10:00:10: [28517601.077983] 2020/11/18 10:00:01
2020-11-18 11:00:02: [28521193.339397] 2020/11/18 11:00:01
--//越靠近當前時間越準確，而越離開當前時間誤差越大。
--//還有如果伺服器重啟，這個時間戳計算是錯誤的。

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

5.總結：
--//可以發現即使是linux作業系統跟蹤檔案時間戳裡面的偏移也可能是來自系統啟動時間。
--//主要看安裝OS的宿主的OS的作業系統。至於這個偏移windows為什麼是系統啟動時間，linux來自1970/1/1 UTC 的微秒數。
--//也許跟OS的設計有關。