[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的设计有关。