[20250421]绑定变量太多的分析(21c补充).txt

--//前几天写了"绑定变量太多的分析(21c)"，发现自己的分析存在一些错误，做一些必要的补充。
--//我当时通过执行oradebug setospid <spid>,不断调用oradebug short_stack，收集stack信息。
$ sort ostackprof_4088.txt| uniq -c | sort -nr >| aaa.txt

$ head -6 aaa.txt
   7418 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-read()+14<-read()+85<-snttread()+16<-nttfprd()+293<-nsbasic_brc()+357<-nioqrc()+495<-opikndf2()+1078<-opitsk()+920<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
    188 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-read()+16<-read()+85<-snttread()+16<-nttfprd()+293<-nsbasic_brc()+357<-nioqrc()+495<-opikndf2()+1078<-opitsk()+920<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
     17 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-write()+16<-snttwrite()+16<-nttfpwr()+215<-nsbasic_bsd()+416<-nioqrc()+300<-opikndf2()+1078<-opitsk()+920<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
     17 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-opiltc()+436<-kxsBindBufferSetUp()+196<-kxsxsi()+1025<-opiexe()+4791<-kpoal8()+2237<-opiodr()+1256<-ttcpip()+1257<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
     11 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-qerilnil()+223<-qerilFetch()+219<-qergsFetchSimple()+7593<-qergsFetch()+263<-opifch2()+3564<-kpoal8()+4232<-opiodr()+1256<-ttcpip()+1257<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
      7 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-qetlbr()+940<-qertbFetchByRowID()+6820<-qerilFetch()+143<-qergsFetchSimple()+7593<-qergsFetch()+263<-opifch2()+3564<-kpoal8()+4232<-opiodr()+1256<-ttcpip()+1257<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
--//事后是否由于切换的问题，我先执行oradebug short_stack，然后切换执行b2.txt脚本，密集执行oradebug short_stack，导致前面
--//2个占用很多,我发现没有执行任何命令时查看stack，看到的就是前面的1，2的情况。

1.环境：
SCOTT@book01p> @ ver2
==============================
PORT_STRING                   : x86_64/Linux 2.4.xx
VERSION                       : 21.0.0.0.0
BANNER                        : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL                   : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY                 : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID                        : 0
PL/SQL procedure successfully completed.

2.建立测试环境：

create table t as select * from all_objects;
create unique index i_t_object_id on t(object_id);
--//分析略。

$ cat a.txt
set pagesize 0
set head off
set feedback off
set verify off
set timing off
spool b1.txt
select 'set termout off'  from dual;
select 'variable b'||to_char(level)||' number;'  from dual connect by level<=&1;
select 'begin'  from dual;
select ':b'||to_char(level)||' :='|| to_char(level)||';'  from dual connect by level<=&1;
select 'end;'  from dual;
select '/' from dual ;
select 'set termout on' txt from dual;
spool off

spool b2.txt
--select 'set timing on' txt from dual;
select 'select count(data_object_id) from t where (1,object_id) in (' txt from dual ;
select '(1,:b'||to_char(level)||'),' txt from dual connect by level<=&&1 -1 ;
select '(1,:b'||to_char(&&1)||'));' txt from dual ;
--select 'set timing off' txt from dual;
spool off

set pagesize 9999
set head on
set feedback on

SCOTT@book01p> @ a.txt 32767
--//输出略。这样建立2个文本b1.txt,b2.txt .
--//采用集合的比较，这样可以突破in list 1000个值的限制。

3.测试：
SCOTT@book01p> @ spid
==============================
SID                           : 151
SERIAL#                       : 9004
PROCESS                       : 3417
SERVER                        : DEDICATED
SPID                          : 3419
PID                           : 49
P_SERIAL#                     : 4
KILL_COMMAND                  : alter system kill session '151,9004' immediate;
PL/SQL procedure successfully completed.

$ pstack 3419
#0  0x00007fd605687480 in __read_nocancel () at ../sysdeps/unix/syscall-template.S:81
#1  0x0000000015415605 in read ()
#2  0x000000001540f360 in snttread ()
#3  0x000000001540dbc5 in nttfprd ()
#4  0x00000000153deef5 in nsbasic_brc ()
#5  0x00000000153f78bf in nioqrc ()
#6  0x0000000014eecbe6 in opikndf2 ()
#7  0x00000000030021e8 in opitsk ()
#8  0x0000000003007920 in opiino ()
#9  0x0000000014eefdf8 in opiodr ()
#10 0x0000000002ffe2ab in opidrv ()
#11 0x0000000003e8bd15 in sou2o ()
#12 0x0000000000e91ae0 in opimai_real ()
#13 0x0000000003e9915c in ssthrdmain ()
#14 0x0000000000e91924 in main ()
--//空闲不执行时看到就是这样，所以怀疑前面的测试存在问题。怎么前最面有1个__read_nocancel。

SCOTT@book01p> @ b1.txt
begin
*
ERROR at line 1:
ORA-04031: unable to allocate 786472 bytes of shared memory ("shared pool","begin
:b1 :=1;
:b2 :=2;
:b3 ...","PL/SQL MPCODE","BAMIMA: Bam Buffer")
--//共享池内存不足。

SCOTT@book01p> @ b1.txt
PL/SQL procedure successfully completed.
--//第2次执行成功。

SCOTT@book01p> print :b32767
    B32767
----------
     32767

SCOTT@book01p> set timing on
SCOTT@book01p> @ b2.txt

COUNT(DATA_OBJECT_ID)
---------------------
                 3852
1 row selected.
Elapsed: 00:01:09.19
--//第1次执行00:01:09.19。

SCOTT@book01p> @ b2.txt
COUNT(DATA_OBJECT_ID)
---------------------
                 3852
1 row selected.
Elapsed: 00:00:37.12
--//第1次执行00:00:37.12，以后执行基本保持这个量级。

$ uniq -c loop5x.txt
      2 /
--//执行2次。

--//window 1,先执行如下：
$ cat ost.sh
#! /bin/bash
sqlplus -s -l / as sysdba <<EOF
oradebug setospid $1
$(seq $3 | xargs -IQ echo -e "host sleep $2 \noradebug short_stack")
EOF

$ sleep 2; ./ost.sh 3419 0 11000 | tee -a  av.txt

--//然后马山切换session 1，执行如下
SCOTT@book01p> @ loop5x.txt

--//观察av.txt文件：
$ sort av.txt | grep -v "Oracle pid" | uniq -c | sort -nr | head -7
  11000
  10980 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-read()+14<-read()+85<-snttread()+16<-nttfprd()+293<-nsbasic_brc()+357<-nioqrc()+495<-opikndf2()+1078<-opitsk()+920<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
      2 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-__memcmp_sse4_1()+36<-kgwsfin()+146<-kgwsinso()+99<-kgwsins()+116<-qerilSortSingleCol()+403<-qerilInitializeInList()+1924<-qerilevao()+72<-expepr()+97<-evaiand()+36<-expeal()+820<-kdstf110010100001000km()+2819<-kdsttgr()+2297<-qertbFetch()+1075<-qergsFetchSimple()+7593<-qergsFetch()+263<-opifch2()+3564<-kpoal8()+4232<-opiodr()+1256<-ttcpip()+1257<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
      1 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-ttcoacCheck()+3<-ttcoac()+744<-ttcpip()+5098<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
      1 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-ttcfbur()+680<-ttcoac()+387<-ttcpip()+5098<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
      1 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-sagesqlInitGetMutable()+41<-sagesqlInitGetMutable()+606<-sagesqlInitGetMutable()+806<-sagesqlInitGetMutable()+606<-sagesqlInitGetMutable()+606<-qertbStart()+8371<-qergsStart()+1360<-selexe0()+1002<-opiexe()+7793<-kpoal8()+2237<-opiodr()+1256<-ttcpip()+1257<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
      1 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-qerilevao()+104<-expepr()+97<-evaiand()+36<-expeal()+820<-kdstf110010100001000km()+2819<-kdsttgr()+2297<-qertbFetch()+1075<-qergsFetchSimple()+7593<-qergsFetch()+263<-opifch2()+3564<-kpoal8()+4232<-opiodr()+1256<-ttcpip()+1257<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
--//还是没有抓取到任何有用的信息。这样看感觉还是抓取到read，反而前面1000个参数的情况抓取：

$ head -6 aaa.txt
   7418 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-read()+14<-read()+85<-snttread()+16<-nttfprd()+293<-nsbasic_brc()+357<-nioqrc()+495<-opikndf2()+1078<-opitsk()+920<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
    188 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-read()+16<-read()+85<-snttread()+16<-nttfprd()+293<-nsbasic_brc()+357<-nioqrc()+495<-opikndf2()+1078<-opitsk()+920<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
     17 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-write()+16<-snttwrite()+16<-nttfpwr()+215<-nsbasic_bsd()+416<-nioqrc()+300<-opikndf2()+1078<-opitsk()+920<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
     17 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-opiltc()+436<-kxsBindBufferSetUp()+196<-kxsxsi()+1025<-opiexe()+4791<-kpoal8()+2237<-opiodr()+1256<-ttcpip()+1257<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
     11 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-qerilnil()+223<-qerilFetch()+219<-qergsFetchSimple()+7593<-qergsFetch()+263<-opifch2()+3564<-kpoal8()+4232<-opiodr()+1256<-ttcpip()+1257<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245
      7 ksedsts()+418<-ksdxcb()+2187<-sspuser()+213<-__sighandler()<-qetlbr()+940<-qertbFetchByRowID()+6820<-qerilFetch()+143<-qergsFetchSimple()+7593<-qergsFetch()+263<-opifch2()+3564<-kpoal8()+4232<-opiodr()+1256<-ttcpip()+1257<-opitsk()+1906<-opiino()+1008<-opiodr()+1256<-opidrv()+1067<-sou2o()+165<-opimai_real()+400<-ssthrdmain()+412<-main()+292<-__libc_start_main()+245

--//做10046on跟踪看看：

SCOTT@book01p> @ ti
New tracefile_identifier = /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3419_0004.trc

SCOTT@book01p> @ 10046on 8
Session altered.

SCOTT@book01p> @ b2.txt
COUNT(DATA_OBJECT_ID)
---------------------
                 3852

SCOTT@book01p> @ 10046off
Session altered.

--//看到最多的等待事件是PGA memory operation
WAIT #140557093332784: nam='PGA memory operation' ela= 7 p1=589824 p2=1 p3=0 obj#=119609 tim=2901872629
WAIT #140557093332784: nam='PGA memory operation' ela= 5 p1=65536 p2=1 p3=0 obj#=119609 tim=2901872932
WAIT #140557093332784: nam='PGA memory operation' ela= 3 p1=65536 p2=1 p3=0 obj#=119609 tim=2901872987
WAIT #140557093332784: nam='PGA memory operation' ela= 3 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873041
WAIT #140557093332784: nam='PGA memory operation' ela= 3 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873071
WAIT #140557093332784: nam='PGA memory operation' ela= 2 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873094
WAIT #140557093332784: nam='PGA memory operation' ela= 2 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873116
WAIT #140557093332784: nam='PGA memory operation' ela= 1 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873141
WAIT #140557093332784: nam='PGA memory operation' ela= 2 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873176
WAIT #140557093332784: nam='PGA memory operation' ela= 3 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873209
WAIT #140557093332784: nam='PGA memory operation' ela= 2 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873238
WAIT #140557093332784: nam='PGA memory operation' ela= 1 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873264
WAIT #140557093332784: nam='PGA memory operation' ela= 3 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873286
WAIT #140557093332784: nam='PGA memory operation' ela= 4 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873329
WAIT #140557093332784: nam='PGA memory operation' ela= 2 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873358
WAIT #140557093332784: nam='PGA memory operation' ela= 2 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873384
WAIT #140557093332784: nam='PGA memory operation' ela= 1 p1=65536 p2=1 p3=0 obj#=119609 tim=2901873406

SYS@book> @ ashtop event 1=1 &5min
    Total                                                                                        Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT                        FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ---------------------------- ------------------- ------------------- ---------- -------- -----------
       73      .2   72% |                              2025-04-20 16:54:08 2025-04-20 16:59:07          5       62          58
       16      .1   16% | LGWR all worker groups       2025-04-20 16:54:46 2025-04-20 16:59:06          1       16          16
        6      .0    6% | log file parallel write      2025-04-20 16:54:47 2025-04-20 16:59:06          1        6           6
        4      .0    4% | control file parallel write  2025-04-20 16:54:17 2025-04-20 16:58:17          1        4           4
        3      .0    3% | db file async I/O submit     2025-04-20 16:55:22 2025-04-20 16:58:37          1        3           3
--//ashtop根本没有抓取到PGA memory operation。

SYS@book> @ ev_namepr "PGA memory operation"
==============================
EVENT#                        : 592
EVENT_ID                      : 1800992443
NAME                          : PGA memory operation
PARAMETER1                    :
PARAMETER2                    :
PARAMETER3                    :
WAIT_CLASS_ID                 : 1893977003
WAIT_CLASS#                   : 0
WAIT_CLASS                    : Other
DISPLAY_NAME                  : PGA memory operation
CON_ID                        : 0
PL/SQL procedure successfully completed.
--//没有p1.p2,p3的解析。
--//这就有点奇怪，oracle的awr不记录PGA memory operation的相关等待事件。

$ grep WAIT /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3419_0004.trc | grep 140557093332784 | grep PGA | awk '{print $7}'| paste -sd+ | bc
180
--//实际上加起来也就是180微秒，awr没有记录是正常的。使用12参数跟踪看看，生成prf报表，摘要如下：

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      7.35       7.38          0          0          0           0
Execute      1     21.81      21.91          0          0          0           0
Fetch        2      0.01       0.01          0       1479          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     29.18      29.32          0       1479          0           1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 109
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=1479 pr=0 pw=0 time=17303 us starts=1)
      3852       3852       3852   TABLE ACCESS FULL T (cr=1479 pr=0 pw=0 time=12601 us starts=1 cost=780 size=16793 card=2399)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                          355        0.00          0.00
  SQL*Net more data from client                   1        0.00          0.00
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2       23.50         23.51
********************************************************************************
--//确实看不到相关等待事件。

4.换一个思路，看看执行一次出现调用几次read。
--//修改b2.txt ，前后加入select systimestamp from dual ;

$ cat read.gdb
set pagination off
set $read  = 0

break read
commands
 silent
 shell echo -n $( date +"%Y/%m/%d %T.%N : ")
 printf "read  %02d\n", ++$read
 c
end

SCOTT@book01p> @ b2.txt
SYSTIMESTAMP
---------------------------------
2025-04-21 09:38:04.826683 +08:00

SYSTIMESTAMP                      COUNT(DATA_OBJECT_ID)
--------------------------------- ---------------------
2025-04-21 09:38:43.142500 +08:00                  3852


SYSTIMESTAMP
---------------------------------
2025-04-21 09:38:43.174848 +08:00

(gdb) c
Continuing.
2025/04/21 09:38:04.830567184 :read  01
2025/04/21 09:38:04.835298723 :read  02
2025/04/21 09:38:04.839491215 :read  03
2025/04/21 09:38:04.843638489 :read  04 --//第1次select systimestamp from dual 完成;

2025/04/21 09:38:43.107504865 :read  05
2025/04/21 09:38:43.112547333 :read  06
2025/04/21 09:38:43.117347458 :read  07
2025/04/21 09:38:43.122505612 :read  08
2025/04/21 09:38:43.137211193 :read  09
2025/04/21 09:38:43.141162663 :read  10 --//输出的时间大致在这个时间之后。
2025/04/21 09:38:43.163222066 :read  11
2025/04/21 09:38:43.166492146 :read  12
2025/04/21 09:38:43.169921346 :read  13
2025/04/21 09:38:43.173196827 :read  14

2025/04/21 09:38:43.177558826 :read  15
2025/04/21 09:38:43.180892728 :read  16
2025/04/21 09:38:43.184232936 :read  17
2025/04/21 09:38:43.187469209 :read  18  --//第2次select systimestamp from dual 完成;

--//从测试看出read调用基本在快结束之后，并且09:38:04到09:38:43之间oracle到底在做什么才是关键。
--//尝试使用执行时马上使用pstack观察。
$ pstack 3519
#0  0x00007f30afb35480 in __read_nocancel () at ../sysdeps/unix/syscall-template.S:81
#1  0x0000000015415605 in read ()
#2  0x000000001540f360 in snttread ()
#3  0x000000001540dbc5 in nttfprd ()
#4  0x00000000153deef5 in nsbasic_brc ()
#5  0x00000000153f78bf in nioqrc ()
#6  0x0000000014eecbe6 in opikndf2 ()
#7  0x00000000030021e8 in opitsk ()
#8  0x0000000003007920 in opiino ()
#9  0x0000000014eefdf8 in opiodr ()
#10 0x0000000002ffe2ab in opidrv ()
#11 0x0000000003e8bd15 in sou2o ()
#12 0x0000000000e91ae0 in opimai_real ()
#13 0x0000000003e9915c in ssthrdmain ()
#14 0x0000000000e91924 in main ()
--//实际上stack最前面的还是__read_nocancel。
--//当我再次执行b2.txt，在使用top -u oracle观察，才发现实际上cpu忙的进程是3517对应sqlplus进程，而不是oracle的进程3519。
--//实际上绑定变量太多实际上问题不在数据库，而是在客户端，当然没有相应的等待事件，自己绕了1个大弯才知道问题所在。
--//包括执行b1.txt时情况也类似。

$ seq 2000 | xargs -IQ pstack 3517 | tee -a  av.txt

$ awk '/^#1 /{print $4}' av.txt | wc
   1157    1157   13160

$ awk '/^#0 /{print $4}' av.txt | sort | uniq -c | sort -nr
    274 lxoBinCmpMutl
    190 kpubndpi
    172 afibndfind
    117 _intel_fast_memcmp
    100 kpurdup
     77 __read_nocancel
     61 lxpoCmpStr
     49 lxoCmpNStr
     49 kpugbp
     24 lxmcpen
     22 lxmopen
      9 lxpoCmpStr@plt
      5 lxoCmpNStr@plt
      1 ttcoac
      1 lxoBinCmpMutl@plt
      1 lxmopen@plt
      1 lfiyfss
      1 kpummTLSGLOP
      1 __intel_new_memset
      1 _intel_fast_memcpy
      1 afipp

$ awk '/^#1 /{print $4}' av.txt | sort | uniq -c | sort -nr
    275 lxpoCmpStr
    190 kpubndp2
    172 afibndxbind
    117 kpurdup
    100 kpurscn
     94 lxoCmpNStr
     77 afibndfind
     76 _IO_new_file_underflow
     49 OCIStmtGetBindInfo
      1 ttckpuDoOAC
      1 snttread
      1 lfibfit
      1 kpuraddbnd
      1 kpummgnls
      1 kghalo
      1 afixeqr

--//出现最多的是：
#0  0x00007f7e26ad90c2 in lxoBinCmpMutl () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libclntshcore.so.21.1
#1  0x00007f7e26ad87ef in lxpoCmpStr () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libclntshcore.so.21.1
#2  0x00007f7e2687784e in lxoCmpNStr () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libclntshcore.so.21.1
#3  0x00007f7e2b19a2a8 in afibndfind () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#4  0x00007f7e2b199e5a in afibndxbind () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#5  0x00007f7e2b20d711 in afixeqqry () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#6  0x00007f7e2b20bca2 in afixeqsql () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#7  0x00007f7e2b20b549 in afixeqr () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#8  0x00007f7e2b19db90 in aficfd () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#9  0x00007f7e2b19c5fc in aficdr () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#10 0x00007f7e2b1c614e in afidrv () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#11 0x0000000000400f30 in main ()

--//第2多的是：
#0  0x00007f7e27218be1 in kpubndpi () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libclntsh.so.21.1
#1  0x00007f7e27219976 in kpubndp2 () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libclntsh.so.21.1
#2  0x00007f7e2b1d9c93 in afioci () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#3  0x00007f7e2b199f46 in afibndxbind () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#4  0x00007f7e2b20d711 in afixeqqry () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#5  0x00007f7e2b20bca2 in afixeqsql () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#6  0x00007f7e2b20b549 in afixeqr () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#7  0x00007f7e2b19db90 in aficfd () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#8  0x00007f7e2b19c5fc in aficdr () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#9  0x00007f7e2b1c614e in afidrv () from /u01/app/oracle/product/21.0.0/dbhome_1/lib/libsqlplus.so
#10 0x0000000000400f30 in main ()

--//这让我想起以前学习使用DBMS_SQL包执行sql语句的一些细节，例子：

variable b20 number ;
exec :b20 := 20;

DECLARE
   mcur     NUMBER;
   mstat    NUMBER;
   v_name   VARCHAR2 (14);
BEGIN
   mcur := DBMS_SQL.open_cursor;
   DBMS_SQL.parse ( mcur ,'select dname from dept where deptno = :deptno' ,DBMS_SQL.native);
   DBMS_SQL.bind_variable (mcur, ':deptno', 20);
   DBMS_SQL.define_column ( mcur ,1 ,v_name ,:b20);
   mstat := DBMS_SQL.execute (mcur);
   mstat := DBMS_SQL.fetch_rows (mcur);
   DBMS_SQL.COLUMN_VALUE (mcur, 1, v_name);
   DBMS_OUTPUT.put_line ('查询结果:' || v_name);
   DBMS_SQL.close_cursor (mcur);
END;
/
--//理解上面对oracle如何执行sql语句有很好的理解.
--//首先打开游标
--//分析语句
--//确定绑定变量
--//定义字段的输出
--//执行
--//提取
--//传给变量
--//输出结果
--//关闭游标

--//问题集中在给绑定变量赋值，DBMS_SQL.bind_variable (mcur, ':deptno', 20);而这步实际上主要CPU消耗在客户端。