[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"