一个Oracle GeoSQL性能问题解决过程
今天客户碰到一则比较有意思的空间SQL性能低下的问题，在此简单记录一下解决过程。
描述：
客户的环境是一个linux的RAC环境，每个新的连接第一次执行GeoSQL的时候速度非常慢，大约20-25s，然后以后再执行同样的SQL速度恢复正常。
以下是抓出来的执行过程。
Trace file /data/app/oracle/diag/rdbms/huic/huic1/trace/huic1_ora_8718.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP,
Data Mining and Real Application Testing options
ORACLE_HOME = /data/app/oracle/11.2.0
System name: Linux
Node name: spoc0
Release: 2.6.18-128.el5
Version: #1 SMP Wed Dec 17 11:41:38 EST 2008
Machine: x86_64
Instance name: huic1
Redo thread mounted by this instance: 1
Oracle process number: 331
Unix process pid: 8718, image: oracle@spoc0 (TNS V1-V3)
*** 2016-03-03 09:55:45.463
*** SESSION ID:(788.5553) 2016-03-03 09:55:45.463
*** CLIENT ID:() 2016-03-03 09:55:45.463
*** SERVICE NAME:(SYS$USERS) 2016-03-03 09:55:45.463
*** MODULE NAME:(sqlplus@spoc0 (TNS V1-V3)) 2016-03-03 09:55:45.463
*** ACTION NAME:() 2016-03-03 09:55:45.463
=====================
PARSING IN CURSOR #47507141711824 len=32 dep=0 uid=0 oct=42 lid=0 tim=1456970145463207 hv=1569151342 ad='2b351e4bfe10' sqlid='4tk6t8tfsfqbf'
alter session set sql_trace=true
END OF STMT
EXEC #47507141711824:c=0,e=116,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1456970145463193
*** 2016-03-03 09:56:00.706
CLOSE #47507141711824:c=0,e=19,dep=0,type=0,tim=1456970160706140
=====================
PARSING IN CURSOR #47507141710952 len=47 dep=1 uid=0 oct=3 lid=0 tim=1456970160708376 hv=1023521005 ad='523e51358' sqlid='cb21bacyh3c7d'
select metadata from kopm$ where name='DB_FDO'
END OF STMT
PARSE #47507141710952:c=0,e=140,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3452538079,tim=1456970160708372
EXEC #47507141710952:c=0,e=104,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3452538079,tim=1456970160708617
FETCH #47507141710952:c=0,e=146,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3452538079,tim=1456970160708818
STAT #47507141710952 id=1 cnt=1 pid=0 pos=1 obj=544 op='TABLE ACCESS BY INDEX ROWID KOPM$ (cr=2 pr=0 pw=0 time=161 us cost=1 size=108 card=1)'
STAT #47507141710952 id=2 cnt=1 pid=1 pos=1 obj=545 op='INDEX UNIQUE SCAN I_KOPM1 (cr=1 pr=0 pw=0 time=102 us cost=0 size=0 card=1)'
CLOSE #47507141710952:c=0,e=11,dep=1,type=1,tim=1456970160709018
*** 2016-03-03 09:56:00.720
=====================
PARSING IN CURSOR #47507141711824 len=83 dep=0 uid=0 oct=3 lid=0 tim=1456970160720316 hv=3943410347 ad='51f261a00' sqlid='7z7b61rphrapb'
select sde.st_geometry('point (198361.47649967 212450.03968634)',300015) from dual
END OF STMT
PARSE #47507141711824:c=13998,e=14026,p=0,cr=89,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1456970160720312
EXEC #47507141711824:c=0,e=81,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1456970160720519
=====================
PARSING IN CURSOR #47507143068328 len=248 dep=1 uid=90 oct=3 lid=90 tim=1456970160728576 hv=2886254862 ad='52fc16078' sqlid='2rk82hfq0jh8f'
SELECT SR_NAME,X_OFFSET,Y_OFFSET,XYUNITS,Z_OFFSET, Z_SCALE,M_OFFSET,M_SCALE,MIN_X,MAX_X,MIN_Y,MAX_Y, MIN_Z,MAX_Z,MIN_M,MAX_M,CS_NAME,CS_TYPE,ORGANIZATION, ORG_COORDSYS_ID,DEFINITION,DESCRIPTION,CS_ID FROM SDE.ST_SPATIAL_REFERENCES WHERE SRID = :B1
END OF STMT
PARSE #47507143068328:c=0,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=861213805,tim=1456970160728572
EXEC #47507143068328:c=0,e=114,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=861213805,tim=1456970160728836
FETCH #47507143068328:c=1000,e=179,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=861213805,tim=1456970160729112
STAT #47507143068328 id=1 cnt=1 pid=0 pos=1 obj=100755 op='TABLE ACCESS BY INDEX ROWID ST_SPATIAL_REFERENCES (cr=3 pr=0 pw=0 time=136 us cost=2 size=699 card=1)'
STAT #47507143068328 id=2 cnt=1 pid=1 pos=1 obj=100756 op='INDEX UNIQUE SCAN ST_SPREFS_PK (cr=2 pr=0 pw=0 time=91 us cost=1 size=0 card=1)'
CLOSE #47507143068328:c=0,e=4,dep=1,type=3,tim=1456970160729278
*** 2016-03-03 09:56:25.771
LOBGETLEN: c=0,e=23,p=0,cr=0,cu=0,tim=1456970185771501
LOBREAD: c=0,e=68,p=0,cr=1,cu=0,tim=1456970185771851
LOBWRITE: c=999,e=348,p=0,cr=2,cu=9,tim=1456970185772534
FETCH #47507141711824:c=27995,e=25052995,p=0,cr=27,cu=172,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1456970185773615
STAT #47507141711824 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=10 us cost=2 size=0 card=1)'
FETCH #47507141711824:c=0,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=1456970185794680
LOBGETLEN: c=0,e=9,p=0,cr=0,cu=0,tim=1456970185795440
LOBREAD: c=0,e=27,p=0,cr=1,cu=0,tim=1456970185795613
LOBTMPFRE: c=0,e=44,p=0,cr=0,cu=5,tim=1456970185795827
*** 2016-03-03 09:56:42.616
CLOSE #47507141711824:c=0,e=18,dep=0,type=0,tim=1456970202616109
=====================
PARSING IN CURSOR #47507141711824 len=83 dep=0 uid=0 oct=3 lid=0 tim=1456970202623822 hv=2584045096 ad='52f2aea38' sqlid='43f483kd0atj8'
select sde.st_geometry('point (198361.47649967 212452.03968634)',300015) from dual
END OF STMT
PARSE #47507141711824:c=7999,e=7554,p=0,cr=27,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1456970202623818
EXEC #47507141711824:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1456970202623981
LOBGETLEN: c=0,e=14,p=0,cr=0,cu=0,tim=1456970202629042
LOBREAD: c=0,e=29,p=0,cr=1,cu=0,tim=1456970202629207
LOBWRITE: c=0,e=163,p=0,cr=2,cu=9,tim=1456970202629613
FETCH #47507141711824:c=4999,e=6001,p=0,cr=24,cu=162,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1456970202630073
STAT #47507141711824 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=9 us cost=2 size=0 card=1)'
FETCH #47507141711824:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=1456970202631538
LOBGETLEN: c=0,e=9,p=0,cr=0,cu=0,tim=1456970202632014
LOBREAD: c=0,e=27,p=0,cr=1,cu=0,tim=1456970202632169
LOBTMPFRE: c=0,e=37,p=0,cr=0,cu=5,tim=1456970202632337
*** 2016-03-03 09:56:51.990
CLOSE #47507141711824:c=0,e=18,dep=0,type=0,tim=1456970211990837
=====================
PARSING IN CURSOR #47507141711824 len=33 dep=0 uid=0 oct=42 lid=0 tim=1456970211992014 hv=525901419 ad='2b351e4bfe10' sqlid='aam2chsgpj7mb'
alter session set sql_trace=false
END OF STMT
PARSE #47507141711824:c=1000,e=1026,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1456970211992010
EXEC #47507141711824:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1456970211992174
使用tkprof格式化一下上述内容：
********************************************************************************
SQL ID: 4tk6t8tfsfqbf Plan Hash: 0
alter session set sql_trace=true
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
********************************************************************************
SQL ID: cb21bacyh3c7d Plan Hash: 3452538079
select metadata
from
kopm$ where name='DB_FDO'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 2 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 2 0 1
Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS BY INDEX ROWID KOPM$ (cr=2 pr=0 pw=0 time=161 us cost=1 size=108 card=1)
1 1 1 INDEX UNIQUE SCAN I_KOPM1 (cr=1 pr=0 pw=0 time=102 us cost=0 size=0 card=1)(object id 545)
********************************************************************************
SQL ID: 7z7b61rphrapb Plan Hash: 1388734953
select sde.st_geometry('point (198361.47649967 212450.03968634)',300015)
from
dual
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 87 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.02 **25.05** 0 24 172 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.04 25.06 0 111 172 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=10 us cost=2 size=0 card=1)
********************************************************************************
SQL ID: 2rk82hfq0jh8f Plan Hash: 861213805
SELECT SR_NAME,X_OFFSET,Y_OFFSET,XYUNITS,Z_OFFSET, Z_SCALE,M_OFFSET,M_SCALE,
MIN_X,MAX_X,MIN_Y,MAX_Y, MIN_Z,MAX_Z,MIN_M,MAX_M,CS_NAME,CS_TYPE,
ORGANIZATION, ORG_COORDSYS_ID,DEFINITION,DESCRIPTION,CS_ID
FROM
SDE.ST_SPATIAL_REFERENCES WHERE SRID = :B1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1 0.00 0.00 0 3 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 0.00 0 3 0 1
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 90 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 TABLE ACCESS BY INDEX ROWID ST_SPATIAL_REFERENCES (cr=3 pr=0 pw=0 time=136 us cost=2 size=699 card=1)
1 1 1 INDEX UNIQUE SCAN ST_SPREFS_PK (cr=2 pr=0 pw=0 time=91 us cost=1 size=0 card=1)(object id 100756)
********************************************************************************
SQL ID: 43f483kd0atj8 Plan Hash: 1388734953
select sde.st_geometry('point (198361.47649967 212452.03968634)',300015)
from
dual
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 27 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 24 162 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.01 0.01 0 51 162 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 FAST DUAL (cr=0 pr=0 pw=0 time=9 us cost=2 size=0 card=1)
********************************************************************************
SQL ID: aam2chsgpj7mb Plan Hash: 0
alter session set sql_trace=falseselect sde.st_geometry(‘point (198361.47649967 212452.03968634)’,300015) from dual这个sql语句，第一次执行用了25s，而第二次执行0.01s。
远程登录到系统中，发现的确如此。
为什么每次都是第一次慢，后续就快了，这个比较容易理解，由于sde.st_geometry函数使用的是oracle c external procedure方法进行调用，当第一次执行sql语句的时候，oracle后台会为后台服务进程创建一个extproc的进程，该进行来加载相应的动态库并读取相应的数据后，然后再将数据传给相应的oracle的后台服务进程。肯定是由于什么原因导致该进程启动的慢，所以第一次执行的就慢，等到以后再执行，由于进程已经启动起来了，不需要再启动，因此速度就正常了。那为什么第一次启动如此慢。
使用strace抓取后天的服务进程所调用的系统函数。
15:10:44.511330 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 11 <0.000030>
15:10:44.511419 connect(11, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, 28) = 0 <0.000086>
15:10:44.511580 fcntl(11, F_GETFL) = 0x2 (flags O_RDWR) <0.000019>
15:10:44.511661 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000019>
15:10:44.511739 gettimeofday({1456989044, 511766}, NULL) = 0 <0.000020>
15:10:44.511823 poll([{fd=11, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1 <0.000020>
15:10:44.511909 sendto(11, "\214\227\1\0\0\1\0\0\0\0\0\0\27extproc_connection_"..., 41, MSG_NOSIGNAL, NULL, 0) = 41 <0.000027>
15:10:44.512010 poll([{fd=11, events=POLLIN}], 1, 5000) = 0 <4.999232>
15:10:49.511355 close(11) = 0 <0.000029>
15:10:49.511512 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 11 <0.000026>
15:10:49.511602 connect(11, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, 28) = 0 <0.000085>
15:10:49.511770 fcntl(11, F_GETFL) = 0x2 (flags O_RDWR) <0.000019>
15:10:49.511852 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000019>
15:10:49.511930 gettimeofday({1456989049, 511958}, NULL) = 0 <0.000019>
15:10:49.512018 poll([{fd=11, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1 <0.000019>
15:10:49.512105 sendto(11, "bL\1\0\0\1\0\0\0\0\0\0\27extproc_connection_"..., 41, MSG_NOSIGNAL, NULL, 0) = 41 <0.000027>
15:10:49.512213 poll([{fd=11, events=POLLIN}], 1, 5000) = 0 <4.999333>
15:10:54.511664 gettimeofday({1456989054, 511714}, NULL) = 0 <0.000020>
15:10:54.511779 poll([{fd=11, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1 <0.000020>
15:10:54.511872 sendto(11, "bL\1\0\0\1\0\0\0\0\0\0\27extproc_connection_"..., 41, MSG_NOSIGNAL, NULL, 0) = 41 <0.000028>
15:10:54.511984 poll([{fd=11, events=POLLIN, revents=POLLIN}], 1, 5000) = 1 <0.000594>
15:10:54.512645 ioctl(11, FIONREAD, [41]) = 0 <0.000023>
15:10:54.512743 recvfrom(11, "bL\201\202\0\1\0\0\0\0\0\0\27extproc_connection_"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, [16]) = 41 <0.000024>
15:10:54.512893 close(11) = 0 <0.000027>
15:10:54.513022 open("/etc/hosts", O_RDONLY) = 11 <0.000029>
15:10:54.513123 fcntl(11, F_GETFD) = 0 <0.000020>
15:10:54.513204 fcntl(11, F_SETFD, FD_CLOEXEC) = 0 <0.000021>
15:10:54.513310 fstat(11, {st_mode=S_IFREG|0644, st_size=444, ...}) = 0 <0.000021>
15:10:54.513429 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b0bf9477000 <0.000027>
15:10:54.513522 read(11, "# Do not remove the following li"..., 4096) = 444 <0.000031>
15:10:54.513638 read(11, "", 4096) = 0 <0.000023>
15:10:54.513723 close(11) = 0 <0.000024>
15:10:54.513808 munmap(0x2b0bf9477000, 4096) = 0 <0.000029>
15:10:54.513901 open("/etc/hosts", O_RDONLY) = 11 <0.000025>
15:10:54.513997 fcntl(11, F_GETFD) = 0 <0.000022>
15:10:54.514078 fcntl(11, F_SETFD, FD_CLOEXEC) = 0 <0.000019>
15:10:54.514154 fstat(11, {st_mode=S_IFREG|0644, st_size=444, ...}) = 0 <0.000020>
15:10:54.514268 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b0bf9477000 <0.000023>
15:10:54.514353 read(11, "# Do not remove the following li"..., 4096) = 444 <0.000027>
15:10:54.514464 read(11, "", 4096) = 0 <0.000020>
15:10:54.514543 close(11) = 0 <0.000021>
15:10:54.514621 munmap(0x2b0bf9477000, 4096) = 0 <0.000029>
15:10:54.514729 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 11 <0.000030>
15:10:54.514836 connect(11, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, 28) = 0 <0.000118>
15:10:54.515030 fcntl(11, F_GETFL) = 0x2 (flags O_RDWR) <0.000019>
15:10:54.515110 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000019>
15:10:54.515189 gettimeofday({1456989054, 515216}, NULL) = 0 <0.000020>
15:10:54.515273 poll([{fd=11, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1 <0.000020>
15:10:54.515360 sendto(11, "\327\r\1\0\0\1\0\0\0\0\0\0\27extproc_connection_"..., 41, MSG_NOSIGNAL, NULL, 0) = 41 <0.000027>
15:10:54.515463 poll([{fd=11, events=POLLIN, revents=POLLIN}], 1, 5000) = 1 <0.000375>
15:10:54.515906 ioctl(11, FIONREAD, [41]) = 0 <0.000020>
15:10:54.515997 recvfrom(11, "\327\r\201\202\0\1\0\0\0\0\0\0\27extproc_connection_"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, [16]) = 41 <0.000022>
15:10:54.516126 close(11) = 0 <0.000026>
15:10:54.516212 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 11 <0.000026>
15:10:54.516296 connect(11, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, 28) = 0 <0.000059>
15:10:54.516424 fcntl(11, F_GETFL) = 0x2 (flags O_RDWR) <0.000019>
15:10:54.516503 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000019>
15:10:54.516581 gettimeofday({1456989054, 516608}, NULL) = 0 <0.000021>
15:10:54.516665 poll([{fd=11, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1 <0.000020>
15:10:54.516756 sendto(11, "\327\r\1\0\0\1\0\0\0\0\0\0\27extproc_connection_"..., 41, MSG_NOSIGNAL, NULL, 0) = 41 <0.000029>
15:10:54.516862 poll([{fd=11, events=POLLIN}], 1, 5000) = 0 <5.000170>
15:10:59.517135 close(11) = 0 <0.000042>
15:10:59.517279 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 11 <0.000036>
15:10:59.517378 connect(11, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, 28) = 0 <0.000134>
15:10:59.517586 fcntl(11, F_GETFL) = 0x2 (flags O_RDWR) <0.000020>
15:10:59.517668 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000020>
15:10:59.517754 gettimeofday({1456989059, 517786}, NULL) = 0 <0.000021>
15:10:59.517847 poll([{fd=11, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1 <0.000021>
15:10:59.517936 sendto(11, "\'\271\1\0\0\1\0\0\0\0\0\0\27extproc_connection_"..., 41, MSG_NOSIGNAL, NULL, 0) = 41 <0.000041>
15:10:59.518062 poll([{fd=11, events=POLLIN, revents=POLLIN}], 1, 5000) = 1 <0.000390>
15:10:59.518516 ioctl(11, FIONREAD, [41]) = 0 <0.000020>
15:10:59.518606 recvfrom(11, "\'\271\201\202\0\1\0\0\0\0\0\0\27extproc_connection_"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, [16]) = 41 <0.000024>
15:10:59.518743 close(11) = 0 <0.000022>
15:10:59.518824 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 11 <0.000023>
15:10:59.518905 connect(11, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, 28) = 0 <0.000039>
15:10:59.519047 fcntl(11, F_GETFL) = 0x2 (flags O_RDWR) <0.000018>
15:10:59.519127 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000018>
15:10:59.519201 gettimeofday({1456989059, 519227}, NULL) = 0 <0.000018>
15:10:59.519282 poll([{fd=11, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1 <0.000018>
15:10:59.519366 sendto(11, "\'\271\1\0\0\1\0\0\0\0\0\0\27extproc_connection_"..., 41, MSG_NOSIGNAL, NULL, 0) = 41 <0.000023>
15:10:59.519463 poll([{fd=11, events=POLLIN}], 1, 5000) = 0 <4.999254>
15:11:04.518833 close(11) = 0 <0.000030>
15:11:04.519092 mmap(NULL, 147456, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b0bf968b000 <0.000028>
15:11:04.519205 open("/data/app/oracle/11.2.0/nls/data/lx20369.nlb", O_RDONLY) = 11 <0.000035>
15:11:04.519319 read(11, "\0\0\0\5\0\3 \v\3619\2\0E0\2\0\0\0\0\0\2\0\0\0\0Z\1\0\0\0\0\0"..., 92) = 92 <0.000033>
15:11:04.519439 read(11, "i\3\0\0\1@\3\0\0\0\0\0\0\0\0\0 ~?\0\0\0\0\4\0\0\0\0\0\0\0\0"..., 145813) = 145813 <0.000183>
15:11:04.519701 close(11) 发现每次都是poll函数等待5s，连续等待了4-5次。poll函数具体功能可以到网上搜索，具体不在介绍。
15:10:44.511330 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 11 <0.000030>
15:10:44.511419 connect(11, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("10.0.8.12")}, 28) = 0 <0.000086>
15:10:44.511580 fcntl(11, F_GETFL) = 0x2 (flags O_RDWR) <0.000019>
15:10:44.511661 fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000019>
15:10:44.511739 gettimeofday({1456989044, 511766}, NULL) = 0 <0.000020>
15:10:44.511823 poll([{fd=11, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1 <0.000020>
15:10:44.511909 sendto(11, "\214\227\1\0\0\1\0\0\0\0\0\0\27extproc_connection_"..., 41, MSG_NOSIGNAL, NULL, 0) = 41 <0.000027>
15:10:44.512010 poll([{fd=11, events=POLLIN}], 1, 5000) = 0 <4.999232>
15:10:49.511355 close(11) = 0 <0.000029>上面是其中的一次，其流程是
1. 建立一个socket对象，类型是SOCK_DGRAM（UDP协议）。
2. 使用该socket对象连接到10.0.8.12的53端口。
3. 使用sendto函数发送数据。
4. 使用poll等待读信息。
初步判断应该是10.0.8.12有问题，
联系相应的维护人员，发现是DNS有问题，解析该IP有问题了，修改DNS信息后问题消除。
转载自：https://blog.csdn.net/liufeng1980423/article/details/50801626
