ITPub博客

首页 > 数据库 > Oracle > [20210220]gdb跟踪逻辑读2.txt

[20210220]gdb跟踪逻辑读2.txt

原创 Oracle 作者:lfree 时间:2021-02-20 17:00:22 0 删除 编辑

[20210220]gdb跟踪逻辑读2.txt

--//有了昨天的测试,链接如下:
--//http://blog.itpub.net/267265/viewspace-2757857/ =>[20210219]全表扫描逻辑读问题.txt
--//http://blog.itpub.net/267265/viewspace-2757859/ => [20210220]全索引扫描快速索引扫描的逻辑读.txt

--//知道这些函数,就可以写出gdb脚本,跟踪那些逻辑读.查看register,以及某些寄存器的地址就可以知道带入的参数,我主要想知道读那
--//些数据块. 过程略.我仅仅贴出gdb脚本,肯定存在许多错误.

1.环境:
SYS@book> @ ver1
PORT_STRING                    VERSION        BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

2.gdb脚本:
$ cat gdb/fetch.gdb
break sntpread
set pagination off
commands
    silent
    set var a=0x0
    set var b=0x0
    continue
end

break kteinpscan
set pagination off
  commands
    silent
    shell echo -n $( date +"%Y/%m/%d %T.%N : ")
    printf "kteinpscan 0x%x\n", *($rdi+4)
    continue
  end

break kdst_fetch if *($rsi+28) != 0
set pagination off
  commands
    silent
    shell echo -n $( date +"%Y/%m/%d %T.%N : ")
    printf "kdst_fetch 0x%x\n", *($rsi+28)
    continue
  end

break kteinmap
set pagination off
  commands
    silent
    shell echo -n $( date +"%Y/%m/%d %T.%N : ")
    printf "kteinmap 0x%x\n", *($rdi+4)
    continue
  end

#set var a=0x0
break kdifxs if *($rdi+28) != a
set pagination off
  commands
    silent
    shell echo -n $( date +"%Y/%m/%d %T.%N : ")
    printf "kdifxs 0x%x\n", *($rdi+28)
        set var a= *($rdi+28)
    continue
  end

#set var b=0x0
break kdsgrp if *($rdi+28) != b
set pagination off
  commands
    silent
    shell echo -n $( date +"%Y/%m/%d %T.%N : ")
    printf "kdsgrp 0x%x\n", *($rdi+28)
        set var b= *($rdi+28)
    continue
  end

#break kdircys
#set pagination off
#  commands
#    silent
#    shell echo -n $( date +"%Y/%m/%d %T.%N : ")
#    printf "kdircys 0x%x\n", *($rdi+4)
#    continue
#  end

#break qeilbk
#set pagination off
#  commands
#    silent
#    shell echo -n $( date +"%Y/%m/%d %T.%N : ")
#    printf "qeilbk 0x%x\n", *($rsi+28)
#    continue
#  end

--//说明:qeilbk,kdircys函数无法跟踪,我不知道为什么? kdifxs 视乎每取1行调用1次,改写成上面的样子.逻辑读统计肯定有问题的.特
--//别是设置array很小的情况.另外kdsgrp类似,估计临近的块算1个逻辑读.
--//另外我还遇到kdst_fetch *($rsi+28) = 0的情况.我不跟踪这样的情况.
--//我多设置断点break sntpread,主要目的是为了初始话a,b变量值为0,不然下次执行的sql记录的是新的值,这样可能会漏掉一些信息.

3.测试前准备与说明:
--//注意测试前sql语句最好多次避免一些递归,还有一些大表可能采用直接路径读,绕过了oracle的数据缓存,自然看不到.
--//还有唯一索引,索引root节点,分支节点跟踪不到,或者使用的函数我不知道暂时放弃.
--//另外测试没有考虑读undo的情况,先暂时放弃.

--//sesion 1:
SCOTT@book> @ spid

       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
       295          5 46722                    DEDICATED 46723       21          3 alter system kill session '295,5' immediate;

--//sesion 2:
$ gdb -p 46723 -x ~/gdb/fetch.gdb
...
Breakpoint 1 at 0x994df72
Breakpoint 2 at 0xfcafda
Breakpoint 3 at 0x947da78
Breakpoint 4 at 0xfc97f0
Breakpoint 5 at 0x95ed0ca
Breakpoint 6 at 0x94471a4
(gdb)

4.测试:
--//测试结果以后面的gdb脚本为准.
--//全表扫描:
select * from emp;
--//跟踪文件:
*** 2021-02-20 15:34:21.723
pin ktewh26: kteinpscan dba 0x1000092:4 time 2565022127
pin kdswh11: kdst_fetch dba 0x1000093:1 time 2565028245
pin kdswh11: kdst_fetch dba 0x1000094:1 time 2565033596
pin kdswh11: kdst_fetch dba 0x1000095:1 time 2565038986
pin kdswh11: kdst_fetch dba 0x1000096:1 time 2565044408
pin kdswh11: kdst_fetch dba 0x1000097:1 time 2565049667
pin kdswh11: kdst_fetch dba 0x1000097:1 time 2565070280
--//gdb:
2021/02/20 15:34:57.544337510 :kteinpscan 0x1000092
2021/02/20 15:34:57.549826022 :kteinmap 0x1000092
2021/02/20 15:34:57.555883105 :kdst_fetch 0x1000093
2021/02/20 15:34:57.561262392 :kdst_fetch 0x1000094
2021/02/20 15:34:57.566930570 :kdst_fetch 0x1000095
2021/02/20 15:34:57.572255586 :kdst_fetch 0x1000096
2021/02/20 15:34:57.591945115 :kdst_fetch 0x1000097
2021/02/20 15:34:57.597271327 :kdst_fetch 0x1000097
--//注extent仅仅1个的情况下,"_trace_pin_time"=1跟踪看不到kteinmap,实际逻辑读是7.

--//INDEX FULL SCAN:
select count(*) from emp;
--//跟踪文件:
*** 2021-02-20 15:35:35.428
pin qeilwhrp: qeilbk dba 0x100009b:1 time 2638727352
--//gdb:
2021/02/20 15:36:05.752024571 :kdifxs 0x100009b

--//INDEX FAST FULL SCAN
select /*+ index_ffs(emp) */ count(*) from emp;
--//跟踪文件:
*** 2021-02-20 15:36:45.413
pin ktewh26: kteinpscan dba 0x100009a:4 time 2708712237
pin kdiwh100: kdircys dba 0x100009b:1 time 2708717602
--//gdb显示:
2021/02/20 15:36:45.400717820 :kteinpscan 0x100009a
2021/02/20 15:36:45.406515456 :kteinmap 0x100009a
2021/02/20 15:36:45.411622200 :kteinpscan 0x100009a
2021/02/20 15:36:45.416993772 :kteinmap 0x100009a

--// TABLE ACCESS BY USER ROWID
select * from emp where rowid='AAAVREAAEAAAACXAAA';
--//跟踪文件:
*** 2021-02-20 15:38:29.342
pin kdswh05: kdsgrp dba 0x1000097:1 time 2812641841

--//gdb显示:
2021/02/20 15:38:29.334660926 :kdsgrp 0x1000097

--//这个结果使用上面的gdb脚本:
--//INDEX RANGE SCAN   
SCOTT@book> select * from emp where empno  between 7788 and 7900;
     EMPNO ENAME      JOB              MGR HIREDATE                   SAL       COMM     DEPTNO
---------- ---------- --------- ---------- ------------------- ---------- ---------- ----------
      7788 SCOTT      ANALYST         7566 1987-04-19 00:00:00       3000                    20
      7839 KING       PRESIDENT            1981-11-17 00:00:00       5000                    10
      7844 TURNER     SALESMAN        7698 1981-09-08 00:00:00       1500          0         30
      7876 ADAMS      CLERK           7788 1987-05-23 00:00:00       1100                    20
      7900 JAMES      CLERK           7698 1981-12-03 00:00:00        950                    30
--//跟踪文件:
*** 2021-02-20 15:46:16.744
pin qeilwhrp: qeilbk dba 0x100009b:1 time 3280043412
pin kdswh05: kdsgrp dba 0x1000097:1 time 3280070000
pin kdiwh16: kdifxs dba 0x100009b:1 time 3280096298
pin kdswh05: kdsgrp dba 0x1000097:1 time 3280108554
--//gdb显示:
2021/02/20 15:46:16.749466318 :kdifxs 0x100009b
2021/02/20 15:46:16.762301302 :kdsgrp 0x1000097
2021/02/20 15:46:16.788847316 :kdifxs 0x100009b
2021/02/20 15:46:16.801327592 :kdsgrp 0x1000097

Plan hash value: 169057108
--------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name   | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |
--------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |        |      1 |        |       |     2 (100)|          |      5 |00:00:00.03 |       4 |
|   1 |  TABLE ACCESS BY INDEX ROWID| EMP    |      1 |      5 |   190 |     2   (0)| 00:00:01 |      5 |00:00:00.03 |       4 |
|*  2 |   INDEX RANGE SCAN          | PK_EMP |      1 |      5 |       |     1   (0)| 00:00:01 |      5 |00:00:00.01 |       2 |
--------------------------------------------------------------------------------------------------------------------------------

--//再找一条sql语句测试看看.
SCOTT@book> select /*+ index(t) */ CREATED from t where owner='SCOTT';
Plan hash value: 3696261165
--------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name               | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |
--------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                    |      1 |        |       |  2237 (100)|          |     22 |00:00:00.20 |      18 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T                  |      1 |   2923 | 40922 |  2237   (0)| 00:00:27 |     22 |00:00:00.20 |      18 |
|*  2 |   INDEX RANGE SCAN          | I_T_OWNER_OBJ_NAME |      1 |   2923 |       |    19   (0)| 00:00:01 |     22 |00:00:00.02 |       4 |
--------------------------------------------------------------------------------------------------------------------------------------------

--//跟踪文件:
*** 2021-02-20 15:51:01.925
pin qeilwhnp: qeilbk dba 0x1000e8f:1 time 3565224759
pin kdswh05: kdsgrp dba 0x100074c:1 time 3565254780
pin kdiwh16: kdifxs dba 0x1000e8f:1 time 3565290060
pin kdswh05: kdsgrp dba 0x1000755:1 time 3565302136
pin kdswh05: kdsgrp dba 0x100074c:1 time 3565314752
pin kdswh05: kdsgrp dba 0x1000755:1 time 3565327400
pin kdswh05: kdsgrp dba 0x100074c:1 time 3565340047
pin kdswh05: kdsgrp dba 0x1000755:1 time 3565354194
pin kdswh05: kdsgrp dba 0x100074d:1 time 3565367977
pin kdswh05: kdsgrp dba 0x1000755:1 time 3565380604
pin kdswh05: kdsgrp dba 0x100074c:1 time 3565394572
pin kdswh05: kdsgrp dba 0x1000755:1 time 3565409295
pin kdswh05: kdsgrp dba 0x100074c:1 time 3565423088
pin kdswh05: kdsgrp dba 0x100074d:1 time 3565436764
pin kdswh05: kdsgrp dba 0x100074c:1 time 3565450436
pin kdswh05: kdsgrp dba 0x1000755:1 time 3565463067
--//gdb显示:
2021/02/20 15:51:26.825408913 :kdifxs 0x1000e8f
2021/02/20 15:51:26.837967584 :kdsgrp 0x100074c
2021/02/20 15:51:26.864101083 :kdifxs 0x1000e8f
2021/02/20 15:51:26.876209013 :kdsgrp 0x1000755
2021/02/20 15:51:26.888767163 :kdsgrp 0x100074c
2021/02/20 15:51:26.901400712 :kdsgrp 0x1000755
2021/02/20 15:51:26.913979815 :kdsgrp 0x100074c
2021/02/20 15:51:26.928021294 :kdsgrp 0x1000755
2021/02/20 15:51:26.941792597 :kdsgrp 0x100074d
2021/02/20 15:51:26.954469410 :kdsgrp 0x1000755
2021/02/20 15:51:26.968166227 :kdsgrp 0x100074c
2021/02/20 15:51:26.982954562 :kdsgrp 0x1000755
2021/02/20 15:51:26.996717134 :kdsgrp 0x100074c
2021/02/20 15:51:27.015716039 :kdsgrp 0x100074d
2021/02/20 15:51:27.029494844 :kdsgrp 0x100074c
2021/02/20 15:51:27.042042161 :kdsgrp 0x1000755
--//这样看到的逻辑读就很接近了.
--//0x1000e8f = set dba 4,3727 = alter system dump datefile 4 block 3727 = 16780943

SYS@book> @ which_obj 4 3727
SYS@book> @ prxx
==============================
OWNER                         : SCOTT
SEGMENT_NAME                  : I_T_OWNER_OBJ_NAME
PARTITION_NAME                :
SEGMENT_TYPE                  : INDEX
TABLESPACE_NAME               : USERS
EXTENT_ID                     : 17
FILE_ID                       : 4
BLOCK_ID                      : 3712
BYTES                         : 1048576
BLOCKS                        : 128
RELATIVE_FNO                  : 4
PL/SQL procedure successfully completed.

总结:
--//纯粹无聊,自己也不熟悉gdb,不要在生产系统做这样的测试与操作!!
--//写这么长,主要记录自己学习和分析的过程,实际上的测试过程远比上面写的要曲折复杂的多,经过多次反复.

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

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

注册时间:2008-01-03

  • 博文量
    2855
  • 访问量
    6643915