SQL elapsed time dramatically increases on HP-UX 11i v3 (Doc ID 1313110.1)

Last updated on NOVEMBER 03, 2016

Applies to:

Oracle Database - Enterprise Edition - Version 9.2.0.1 and later
HP-UX Itanium
HP-UX PA-RISC (64-bit)

Symptoms

After OS upgrade to "HP-UX 11i Version 3 March 2011", queries running on a certain group of clients becomes extremely slow.

1. 10046 outputs


a) Good Case

********************************************************************************

select count(*)
from
mon.fix_stat_backup


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 2 0.42 0.41 0 12400 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.42 0.41 0 12400 0 1

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 1 0.00 0.00



********************************************************************************





b) Bad Case: Without any particular wait events or CPU time, only the value of 'elapsed time' increased.

********************************************************************************

select count(*)
from
mon.fix_stat_backup


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 2 0.46 80.63 0 12400 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.46 80.63 0 12400 0 1

Misses in library cache during parse: 1
Optimizer mode: CHOOSE
Parsing user id: SYS

Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE
709973 TABLE ACCESS FULL FIX_STAT_BACKUP


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 3.08 3.17



********************************************************************************

 

2. TUSC output

A repetitive pattern of calling select() can be seen.

 

[20854] gettimeofday(0x9fffffffffff98f0, NULL) ..................................................... = 0
[20854] getrusage(RUSAGE_SELF, 0x9fffffffffff89a0) ................................................. = 0
[20854] select(2048, 0x9fffffffffff7760, 0x9fffffffffff7860, 0x9fffffffffff7960, 0x9fffffffffff7750) = 0
[20854] select(2048, 0x9fffffffffff7760, 0x9fffffffffff7860, 0x9fffffffffff7960, 0x9fffffffffff7750) = 0
[20854] select(2048, 0x9fffffffffff7760, 0x9fffffffffff7860, 0x9fffffffffff7960, 0x9fffffffffff7750) = 0
[20854] select(2048, 0x9fffffffffff7760, 0x9fffffffffff7860, 0x9fffffffffff7960, 0x9fffffffffff7750) = 0
[20854] select(2048, 0x9fffffffffff7760, 0x9fffffffffff7860, 0x9fffffffffff7960, 0x9fffffffffff7750) =
0

 

NOTE: The select() function indicates which of the specified file descriptors is ready for reading, ready for writing, or has an error condition pending. If the specified condition is false for all of the specified file descriptors, select() blocks, up to the specified timeout interval, until the specified condition is true for at least one of the specified file descriptors.

 

3. SQL*NET Server Trace


Matching server trace and client trace, some odd messages are being reported on server traces whenever there is a time-delay.

[000001 01-APR-2011 12:50:39:406] nsdo: entry
[000001 01-APR-2011 12:50:39:406] nsdo: cid=0, opcode=85, *bl=0, *what=0, uflgs=0x0, cflgs=0x3
[000001 01-APR-2011 12:50:39:406] nsdo: rank=64, nsctxrnk=0
[000001 01-APR-2011 12:50:39:407] nsdo: nsctx: state=8, flg=0x420c, mvd=0
[000001 01-APR-2011 12:50:39:407] nsdo: gtn=143, gtc=143, ptn=10, ptc=2011
[000001 01-APR-2011 12:50:39:407] nsdo: switching to application buffer
[000001 01-APR-2011 12:50:39:407] nsrdr: entry
[000001 01-APR-2011 12:50:39:407] nsrdr: recving a packet
[000001 01-APR-2011 12:50:39:407] nsprecv: entry
[000001 01-APR-2011 12:50:39:407] nsprecv: reading from transport...
[000001 01-APR-2011 12:50:39:407] nttrd: entry
[000001 01-APR-2011 12:50:43:550] nttrd: socket 12 had bytes read=208
[000001 01-APR-2011 12:50:43:550] nttrd: exit
[000001 01-APR-2011 12:50:43:550] nsprecv: 208 bytes from transport
[000001 01-APR-2011 12:50:43:551] nsprecv: tlen=208, plen=208, type=6
[000001 01-APR-2011 12:50:43:551] nsprecv: packet dump
[000001 01-APR-2011 12:50:43:551] nsprecv: 00 D0 00 00 06 00 00 00 |........|
[000001 01-APR-2011 12:50:43:551] nsprecv: 00 00 03 5E 08 02 80 61 |...^...a|
[000001 01-APR-2011 12:50:43:551] nsprecv: 00 01 02 01 2C 01 01 0C |....,...|
[000001 01-APR-2011 12:50:43:551] nsprecv: 00 01 00 01 01 00 00 00 |........|
[000001 01-APR-2011 12:50:43:551] nsprecv: 00 00 00 00 01 01 00 FE |........|
[000001 01-APR-2011 12:50:43:551] nsprecv: 40 20 73 65 6C 65 63 74 |@.sel` ect|
[000001 01-APR-2011 12:50:43:551] nsprecv: 20 70 72 6F 63 65 73 73 |.process|
[000001 01-APR-2011 12:50:43:551] nsprecv: 20 22 63 6C 69 65 6E 74 |."client|
[000001 01-APR-2011 12:50:43:551] nsprecv: 22 2C 20 70 2E 73 70 69 |",.p.spi|
[000001 01-APR-2011 12:50:43:551] nsprecv: 64 20 22 73 68 61 64 6F |d."shado|
[000001 01-APR-2011 12:50:43:551] nsprecv: 77 22 20 66 72 6F 6D 20 |w".from.|
[000001 01-APR-2011 12:50:43:551] nsprecv: 76 24 73 65 73 73 69 6F |v$sessio|
[000001 01-APR-2011 12:50:43:551] nsprecv: 6E 20 73 2C 20 76 24 70 |n.s,.v$p|
[000001 01-APR-2011 12:50:43:551] nsprecv: 72 40 6F 63 65 73 73 20 |r@ocess.|
[000001 01-APR-2011 12:50:43:551] nsprecv: 70 20 77 68 65 72 65 20 |p.where.|
[000001 01-APR-2011 12:50:43:551] nsprecv: 73 2E 73 69 64 20 3D 20 |s.sid.=.|
[000001 01-APR-2011 12:50:43:551] nsprecv: 28 73 65 6C 65 63 74 20 |(select.|
[000001 01-APR-2011 12:50:43:551] nsprecv: 73 69 64 20 66 72 6F 6D |sid.from|
[000001 01-APR-2011 12:50:43:551] nsprecv: 20 76 24 6D 79 73 74 61 |.v$mysta|
[000001 01-APR-2011 12:50:43:551] nsprecv: 74 20 77 68 65 72 65 20 |t.where.|
[000001 01-APR-2011 12:50:43:551] nsprecv: 72 6F 77 6E 75 6D 20 3D |rownum.=|
[000001 01-APR-2011 12:50:43:551] nsprecv: 20 31 16 29 20 61 6E 64 |.1.).and|
[000001 01-APR-2011 12:50:43:551] nsprecv: 20 73 2E 70 61 64 64 72 |.s.paddr|
[000001 01-APR-2011 12:50:43:551] nsprecv: 20 3D 20 70 2E 61 64 64 |.=.p.add|
[000001 01-APR-2011 12:50:43:551] nsprecv: 72 00 01 01 00 00 00 00 |r.......|
[000001 01-APR-2011 12:50:43:551] nsprecv: 00 00 01 01 00 00 00 00 |........|
[000001 01-APR-2011 12:50:43:551] nsprecv: normal exit
[000001 01-APR-2011 12:50:43:551] nsrdr: got NSPTDA packet
[000001 01-APR-2011 12:50:43:551] nsrdr: NSPTDA flags: 0x0
[000001 01-APR-2011 12:50:43:551] nsrdr: normal exit
[000001 01-APR-2011 12:50:43:551] nsdo: *what=1, *bl=2001
[000001 01-APR-2011 12:50:43:551] nsdo: nsctxrnk=0
[000001 01-APR-2011 12:50:43:551] nsdo: normal exit
[000001 01-APR-2011 12:50:43:551] nioqrc: exit
[000001 01-APR-2011 12:50:43:558] nioqsn: entry
[000001 01-APR-2011 12:50:43:558] nsmore2recv: entry
[000001 01-APR-2011 12:50:43:558] nsmore2recv: testing for MOREDATA from transport
[000001 01-APR-2011 12:50:43:577] nsmore2recv: exit (0)

[000001 01-APR-2011 12:50:43:577] nsmore2recv: entry
[000001 01-APR-2011 12:50:43:577] nsmore2recv: testing for MOREDATA from transport
[000001 01-APR-2011 12:50:43:597] nsmore2recv: exit (0)
[000001 01-APR-2011 12:50:43:597] nsmore2recv: entry
[000001 01-APR-2011 12:50:43:597] nsmore2recv: testing for MOREDATA from transport
[000001 01-APR-2011 12:50:43:617] nsmore2recv: exit (0)

<---------------------DELAY

[000001 01-APR-2011 12:50:58:477] nsmore2recv: entry
[000001 01-APR-2011 12:50:58:477] nsmore2recv: testing for MOREDATA from transport
[000001 01-APR-2011 12:50:58:497] nsmore2recv: exit (0)
[000001 01-APR-2011 12:50:58:497] nsmore2recv: entry
[000001 01-APR-2011 12:50:58:497] nsmore2recv: testing for MOREDATA from transport
[000001 01-APR-2011 12:50:58:517] nsmore2recv: exit (0)
[000001 01-APR-2011 12:50:58:517] nsmore2recv: entry
[000001 01-APR-2011 12:50:58:517] nsmore2recv: testing for MOREDATA from transport
[000001 01-APR-2011 12:50:58:537] nsmore2recv: exit (0)



The messages above mean that there are more data to be delivered not only on NS level, but also NT level. So it gives us an idea that there may be a problem on networking layer.

NS MORE 2 RECV: make best effort to answer the question "is there more for me to receive?" by looking, progressively, to one or both of the following sources:

1. NS recv buffer
2. NT-provider buffer


About the meaning of NS & NT, please look over the following definitions.

Oracle® Database Net Services Administrator's Guide
10g Release 2 (10.2)
Part Number B14212-02

NS (network session)
A session layer that is used in typical Oracle Net connections to establish and maintain the connection between a client application and a database server.

NT (network transfer)
A networking layer that maintains end-to-end reliability through data flow control and error recovery methods. The Oracle Net foundation layer uses Oracle protocol support for the transport layer.

4. PSTACK output


 Pstack dumped from the server process shows that the call nsmore2recv() invokes select system call.

0: c000000000436350 : _select_sys() + 0x30 (/usr/lib/hpux64/libc.so.1)
1: c00000000044b9b0 : _select() + 0xf0 (/usr/lib/hpux64/libc.so.1)
2: 4000000005b93cb0 : snttmoredata() at snttmore.c:177
3: 400000000592a8b0 : nsmore2recv() at nsmore.c:140
4: 40000000010da290 : $cold_nioqts() + 0xb0 (/orahome1/oracle/product/920/bin/oracle)
5: 400000000122b3d0 : $cold_qerfxFetch() + 0x3f0 (/orahome1/oracle/product/920/bin/oracle)
6: 40000000018762a0 : qerflFetchOutside() at qerfl.c:284
7: 4000000001718940 : subsr1() at sub.c:215
8: 4000000001a677a0 : evaopn2() at /net/usunnbh25/private1/lmandali/cpu/9207/aprcpu07/197/source/evah2p.c:4169
9: 4000000001a67340 : expepr() at expima.c:182
10: 4000000001a67540 : expeal() at expima.c:114
11: 40000000018762d0 : qerflFetchOutside() at qerfl.c:292
12: 4000000001beb200 : kpofrws() at kpof.c:776
13: 4000000001bbf300 : opifch2() at opifch.c:1526
14: 4000000001bc6650 : opiall0() at opiall.c:736
15: 4000000001ce1540 : kpoal8() at kpoal8.c:624
16: 4000000001acad20 : opiodr() at opiodr.c:582
17: 4000000001ca90b0 : ttcpip() at /net/usunnbh25/private1/lmandali/cpu/9207/aprcpu07/197/source/ttcpip.c:876
18: 4000000001cae800 : opitsk() at /net/usunnbh25/private1/lmandali/cpu/9207/aprcpu07/197/source/opitsk.c:722
19: 4000000001f13c60 : opiino() at opiino.c:1065
20: 4000000001acad20 : opiodr() at opiodr.c:582
21: 4000000001fb4a90 : opidrv() at opidrv.c:772
22: 4000000001fbc270 : sou2o() at sou2o.c:63
23: 4000000002005590 : main() at opimai.c:186
24: c000000000045900 : main_opd_entry() + 0x50 (/usr/lib/hpux64/dld.so)

 

Changes

OS upgraded to "HP-UX 11i Version 3 March 2011"

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms