ITPub博客

首页 > 数据库 > Oracle > [20200818]12c 10046跟踪时间戳.txt

[20200818]12c 10046跟踪时间戳.txt

原创 Oracle 作者:lfree 时间:2020-08-18 21:22:56 0 删除 编辑

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

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/267265/viewspace-2712755/,如需转载,请注明出处,否则将追究法律责任。

请登录后发表评论 登录
全部评论
熟悉oracle相关技术,擅长sql优化,rman备份与恢复,熟悉linux shell编程。

注册时间:2008-01-03

  • 博文量
    2713
  • 访问量
    6543086