sql每一个session第一次执行固定花费20秒

yhqtxy1314

大家好，现在遇到一个问题
现象：一条sql每一个session第一次执行固定花费20秒
环境，oracle 11g 11.2.0.4 ,RAC 2节点，centos 6.8
sql语句如下：
select ST_AsText(SDE.ST_Geometry('POINT (10 10)', 0)) from dual;
起初以为是执行计划或者统计信息问题，重新收集，然后还是一样，新开一个session，执行第一次花费20秒
执行计划如下：
SQL> select ST_AsText(ST_Geometry('POINT (10 10)', 0)) from dual;

ST_ASTEXT(ST_GEOMETRY('POINT(1010)',0))
--------------------------------------------------------------------------------
POINT  ( 10.00000000 10.00000000)


Execution Plan
----------------------------------------------------------
Plan hash value: 1388734953

-----------------------------------------------------------------
| Id  | Operation         | Name | Rows        | Cost (%CPU)| Time        |
-----------------------------------------------------------------
|   0 | SELECT STATEMENT |        |     1 |     2   (0)| 00:00:01 |
|   1 |  FAST DUAL         |        |     1 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------


Statistics
----------------------------------------------------------
       2092  recursive calls
        208  db block gets
       3232  consistent gets
         16  physical reads
          0  redo size
       1167  bytes sent via SQL*Net to client
        949  bytes received via SQL*Net from client
          5  SQL*Net roundtrips to/from client
        113  sorts (memory)
          0  sorts (disk)
          1  rows processed

经过几次执行发现，每次都是固定20秒，所以怀疑不是sql执行计划的问题，这时候拿出AWR报告
发现file:///C:/Users/Administrator/Desktop/%E5%BE%AE%E4%BF%A1%E5%9B%BE%E7%89%87_20181205141235.png
Foreground Wait Class
s - second, ms - millisecond - 1000th of a second
ordered by wait time desc, waits desc
%Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Captured Time accounts for 102.6% of Total DB time 204.68 (s)
Total FG Wait Time: 146.06 (s) DB CPU time: 63.86 (s)
Wait Class        Waits        %Time -outs        Total Wait Time (s)        Avg wait (ms)        %DB time
Application        11,266        1        90        8        44.12

Foreground Wait Events
s - second, ms - millisecond - 1000th of a second
Only events with Total Wait Time (s) >= .001 are shown
ordered by wait time desc, waits desc (idle events last)
%Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Event        Waits        %Time -outs        Total Wait Time (s)        Avg wait (ms)        Waits /txn        % DB time
External Procedure initial connection        3        0        60        20046        0.00        29.38
External Procedure call        9,708        0        30        3        0.96        14.57
reliable message        3,597        0        22        6        0.36        10.75
Data file init write        2,124        0        7        3        0.21        3.60

Background Wait Events
ordered by wait time desc, waits desc (idle events last)
Only events with Total Wait Time (s) >= .001 are shown
%Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Event        Waits        %Time -outs        Total Wait Time (s)        Avg wait (ms)        Waits /txn        % bg time
Streams AQ: qmn coordinator waiting for slave to start        9        89        43        4802        0.00        13.10

发现这个：External Procedure initial connection 稳定耗时20秒，sql是调用一个lib文件，空间库的东西（不懂），
但是现象是在本地和测试的rac环境，执行都是正常，唯独在线上环境执行，耗时很久，线上环境是本地的cp
本地awr截图
file:///C:/Users/Administrator/Desktop/TIM%E6%88%AA%E5%9B%BE20181205142048.png
Foreground Wait Events
s - second, ms - millisecond - 1000th of a second
Only events with Total Wait Time (s) >= .001 are shown
ordered by wait time desc, waits desc (idle events last)
%Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
Event        Waits        %Time -outs        Total Wait Time (s)        Avg wait (ms)        Waits /txn        % DB time
reliable message        1,836        0        2        1        1.53        11.16
log file sync        126        0        0        3        0.10        2.96
gc current grant busy        73        0        0        2        0.06        0.82
查阅了很多资料，发现该问题比较少，特来pub看看有人遇到过没有，给个思路。。。

目前应该能确定问题是出现在External Procedure initial connection上。。

newkid

https://community.oracle.com/thread/2490921

issue:
we had an application that uses external procedures for a token function. This application call to external library. When we execute the call the first time in the session, this hang
waiting for "External procedure initial connection" wait for 6 minutes. After the first call, all next calls works fine in milliseconds.

Explanation:

The issue occurs because since RAC 11gR2 only configures sqlnet.ora of grid infraestructure oracle home with NAMES.DIRECTORY_PATH=(tnsnames, ezconnect) . However in RDBMS oracle home sqlnet.ora is empty! It ocurrs only in Grid infrastructure configuration. Otherwise, sqlnet.ora of rdbms oracle home is configured by default as NAMES.DIRECTORY_PATH=(tnsnames, ezconnect) too.
This cause that external procedures takes default configuration " NAMES.DIRECTORY_PATH=(tnsnames, ldap, ezconnect) " and it wait until ldap time out, and causes "External procedure initial connection" waits

Solution:
I added NAMES.DIRECTORY_PATH=(tnsnames, ezconnect) to sqlnet.ora of RDBMS oracle home and now this works fine!!.

I hope I can help to sameone.

yhqtxy1314

https://community.oracle.com/thread/2490921

issue:
we had an application that uses external procedures for a token function. This application call to external library. When we execute the call the first time in the session, this hang
waiting for "External procedure initial connection" wait for 6 minutes. After the first call, all next calls works fine in milliseconds.

感谢newkid大佬，昨天也看到这个文档，粗略过了一遍，发现在grid下面有
[grid@rac2 admin]$ cat /u01/app/11.2.0/grid/network/admin/sqlnet.ora
# sqlnet.ora.rac2 Network Configuration File: /u01/app/11.2.0/grid/network/admin/sqlnet.ora.rac2
# Generated by Oracle configuration tools.

NAMES.DIRECTORY_PATH= (TNSNAMES, EZCONNECT)

ADR_BASE = /u01/app/grid
--就没有处理
今早上再次查看，在oralce路径下面加了该文件
[grid@rac2 admin]$ cat /u01/app/oracle/product/11.2.0/db_1/network/admin/sqlnet.ora
NAMES.DIRECTORY_PATH= (TNSNAMES)
--测试，发现一切正常，真的是。。。。虽然不知道具体的原理，还是非常感谢，解决了问题

--但还是存在一个疑问，在测试环境，并没有添加oracle路径下的/u01/app/oracle/product/11.2.0/db_1/network/admin/sqlnet.ora ，返回时毫秒级
，但在线上的环境，没有这个文件，就是稳定的需要花费20秒，
2个环境都是11.2.0.4 rac(2节点），centos6.8，只不过测试是虚拟机环境，线上是实体机。

sqysl

yhqtxy1314 发表于 2018-12-6 10:09
感谢newkid大佬，昨天也看到这个文档，粗略过了一遍，发现在grid下面有
[grid@rac2 admin]$ cat /u01/ ...

1、没有添加，不代表没有，也许其他人添加了呢，楼主还是确认下测试环境RDBMS $ORACLE_HOME相应sqlnet.ora的内容。
2、谢谢newkid的分享，学习了。