Lothar,
Comparing the ela for the "PGA allocate memory" with the matching "tim=" I
think what you're seeing is the time it takes Oracle to build an array and
copy data from the SQL*Net packet to the array. Obviously some of the
difference is about the time to write to the trace file, even so there's a
lot of other CPU to account for.and it's happening between the memory
allocations. I doubt if "traffic" (i.e. movement across the network) is
relevant - the ns calls are probably a layer above that moving the data
between the sql*net layer and the session layer.
I am curious about the internal_function() and 4,700 variables. An IN list
is limited to 1,000 and I wouldn't have expected an OR of IN lists to turn
into a single internal_function(), Perhaps there's something about data
types and character set conversion (or some other conversion) that's adding
to the CPU time.
Regards
Jonathan Lewis
On Wed, 14 Oct 2020 at 11:38, l.flatz@xxxxxxxxxx <l.flatz@xxxxxxxxxx> wrote:
Hi Jonathan,
most of the bind variables is part of a long inlist, that don't filter
anything most of the time.
Runtime Stats:
----------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows
| A-Time | Buffers | Reads |
----------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 2428 | | 2219
|00:00:22.94 | 13456 | 2188 |
|* 1 | FILTER | | 2428 | | 2219
|00:00:22.94 | 13456 | 2188 |
|* 2 | TABLE ACCESS BY INDEX ROWID| XXXX | 2428 | 1 | 2219
|00:00:22.90 | 13456 | 2188 |
|* 3 | INDEX UNIQUE SCAN | XXXXXX | 2428 | 1 | 2428
|00:00:00.64 | 9712 | 751 |
----------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(:A3=:A1)
2 - filter(("XXX"=:A1 AND INTERNAL_FUNCTION("XXXX")))
3 - access("XXX"=:A0 AND "XXXX"=:A2)
trace:
call count cpu elapsed disk query
current rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.57 0.57 0 0
0 0
Execute 2424 1143.97 1145.10 0 0
0 0
Fetch 2424 22.67 23.30 2188 13433
0 2219
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 4849 1167.22 1168.97 2188 13433
0 2219
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 69
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
PGA memory operation 185 0.00
0.00
SQL*Net more data from client 1 0.00
0.00
SQL*Net message to client 2425 0.00
0.00
cell single block physical read 2188 0.00
1.08
SQL*Net message from client 2425 14.64
36.86
SQL*Net break/reset to client 1 0.00
0.00
********************************************************************************
PARSE
#18446744071515819840:c=573152,e=573199,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=2398439527108
WAIT #18446744071515819840: nam='PGA memory operation' ela= 44 p1=131072
p2=1 p3=0 obj#=411359 tim=2398439528133
WAIT #18446744071515819840: nam='PGA memory operation' ela= 10 p1=65536
p2=1 p3=0 obj#=411359 tim=2398439528409
WAIT #18446744071515819840: nam='PGA memory operation' ela= 40 p1=196608
p2=1 p3=0 obj#=411359 tim=2398439540146
WAIT #18446744071515819840: nam='PGA memory operation' ela= 18 p1=196608
p2=1 p3=0 obj#=411359 tim=2398439540512
WAIT #18446744071515819840: nam='PGA memory operation' ela= 51 p1=65536
p2=1 p3=0 obj#=411359 tim=2398439749846
WAIT #18446744071515819840: nam='PGA memory operation' ela= 22 p1=65536
p2=1 p3=0 obj#=411359 tim=2398439754806
WAIT #18446744071515819840: nam='PGA memory operation' ela= 21 p1=65536
p2=1 p3=0 obj#=411359 tim=2398439759805
WAIT #18446744071515819840: nam='PGA memory operation' ela= 17 p1=65536
p2=1 p3=0 obj#=411359 tim=2398439764572
WAIT #18446744071515819840: nam='PGA memory operation' ela= 21 p1=65536
p2=1 p3=0 obj#=411359 tim=2398439769469
WAIT #18446744071515819840: nam='PGA memory operation' ela= 29 p1=65536
p2=1 p3=0 obj#=411359 tim=2398439774210
WAIT #18446744071515819840: nam='PGA memory operation' ela= 37 p1=65536
p2=2 p3=0 obj#=411359 tim=2398439779473
.. some more PGA
WAIT #18446744071515819840: nam='SQL*Net more data from client' ela= 123
driver id=1413697536 #bytes=4 p3=0 obj#=411359 tim=2398440431382
WAIT #18446744071515819840: nam='PGA memory operation' ela= 195 p1=65536
p2=1 p3=0 obj#=411359 tim=2398440894069
EXEC
#18446744071515819840:c=1365159,e=1365158,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2546209255,tim=2398440894253
WAIT #18446744071515819840: nam='SQL*Net message to client' ela= 2 driver
id=1413697536 #bytes=1 p3=0 obj#=411359 tim=2398440894594
WAIT #18446744071515819840: nam='cell single block physical read' ela= 458
cellhash#=2996480889 diskhash#=868261556 bytes=8192 obj#=356252
tim=2398440895364
WAIT #18446744071515819840: nam='cell single block physical read' ela= 387
cellhash#=2996480889 diskhash#=868261556 bytes=8192 obj#=313172
tim=2398440895899
FETCH
#18446744071515819840:c=10577,e=11101,p=2,cr=5,cu=0,mis=0,r=0,dep=0,og=1,plh=2546209255,tim=2398440905918
STAT #18446744071515819840 id=1 cnt=0 pid=0 pos=1 obj=0 op='FILTER (cr=5
pr=2 pw=0 str=1 time=11105 us)'
STAT #18446744071515819840 id=2 cnt=0 pid=1 pos=1 obj=313172 op='TABLE
ACCESS BY INDEX ROWID NLEI (cr=5 pr=2 pw=0 str=1 time=11097 us cost=1
size=554 card=1)'
STAT #18446744071515819840 id=3 cnt=1 pid=2 pos=1 obj=356252 op='INDEX
UNIQUE SCAN NLEI~2 (cr=4 pr=1 pw=0 str=1 time=650 us cost=1 size=0 card=1)'
WAIT #18446744071515819840: nam='PGA memory operation' ela= 2223 p1=0 p2=0
p3=0 obj#=313172 tim=2398440910024
WAIT #18446744071515819840: nam='SQL*Net message from client' ela= 10073
driver id=1413697536 #bytes=1 p3=0 obj#=313172 tim=2398440920234
*
Regards
Lothar
----Ursprüngliche Nachricht----
Von : jlewisoracle@xxxxxxxxx
Datum : 14/10/2020 - 12:14 (MS)
An : oracle-l@xxxxxxxxxxxxx
Betreff : Re: Can Bind variables be an issue with respect to network
transfer?
Lothar,
I was curious about the 4,700 bind variables - it doesn't seem consistent
with a query that returns one or zero rows.
Is this an aggregate query with a very long IN-list?
Have you checked the sql_trace level 8 output, because I would expect that
to give you the answer: probably with lines something like:
PARSE #1242152521452152 ...
WAIT #1234134141 sql*net more data from from client
WAIT #1234134141 sql*net more data from from client
WAIT #1234134141 sql*net more data from from client
WAIT #1234134141 sql*net more data from from client
EXEC #1242152521452152 ...
FETCH #1242152521452152 ...
WAIT #1234134141 sql*net message to client
WAIT #1234134141 sql*net message from client
For each execution.
That's not something I've demonstrated, just something I would expect
based on your description of executing a statement with 4,700 binds. The
number of "more data..." calls would probably depend on the SDU size and
the number, type, and values of non-null bind variables.
Regards
Jonathan Lewis
On Wed, 14 Oct 2020 at 10:04, Lothar Flatz < l.flatz@xxxxxxxxxx> wrote:
Hi,
I investigate a software that gets single rows in a loop.
In this case it is 2400 iterations each retrieving one or no row. Access
is quick, via primary key index but the execution time is suspiciously
high.
My investigation shows in the runtime stats that the statement is
executed on the DB in a fraction of the time.
The total run time for the statement is 8 minutes, the total database
execution time for 2400 executions is about 10 seconds.
Did iterative stack on the oracle process and it show that the time was
spend on network transfer.
But the question still remains why network transfer is done in the
execution phase of a statement.
I guess the reason could be bind variables since there are over 4700
bind variables and the binding is done in the execution phase.
I wonder if that idea is reasonable. Even if there are many bind
variables I wonder if it can make up to that amount of time.
The bind variables are all rather short.
75% of the time I see this stack:
ffffffff47de1d80 read (18, ffffffff7d63d74e, 8010)
0000000117585650 nsprecv (ffffffff7d63bf08, ffffffff7fff5daf,
ffffffff7d62b4c8, 0, 0, ffffffff7d63d680) + 1b0
00000001175993d0 nsrdr (ffffffff7db606b8, ffffffff7d62b4c8,
ffffffff7d63bf08, 0, 0, ffffffff7da5d580) + 90
00000001174f659c nsfull_pkt_rcv (ffffffff7d62b2d8, 55, 1000,
ffffffff7d62b550, ffffffff7fff9ecb, ffffffff7d62b4c8) + 1fdc
00000001174fc40c nsfull_brc (ffffffff7d62b2d8, 10000000,
ffffffff7fff9ecb, 3, 2fc, f0e0c00) + 6c
000000011763cb3c nioqrc (ffffffff7daad150, 11869cb48,
ffffffff7fffce0d, 1, 0, ffffffff7d62b170) + 17c
0000000109de001c opikndf2 (ffffffff7daad150, 2, ffffffff7da92e0c, 1,
1a2, 1) + 45c
0000000109dce4a8 opitsk (202db9, ffffffff7da92e08, ffffffff7da92e0c,
ffffffff7da89768, 0, ffffffff7da8faf0) + 3a8
0000000109de2d24 opiino (1, ffffffff7fffe080, 10000, ffffffff7daad048,
10a, ffffffffffff3354) + 384
0000000109e0456c opiodr (22000, ffffffff7daad050, 1328, 1358, 3c, 0) +
44c
0000000109dc2ae4 opidrv (1694, 0, ffffffff7daad048, ffffffff7da92e38,
1328, 1fc00) + 384
000000010d0ea16c sou2o (ffffffff7fffe058, 3c, 4, ffffffff7fffe080,
102ebf000, 70) + 6c
0000000104a667cc opimai_real (2, ffffffff7fffe458, 1,
ffffffff7fffe080, 103392000, 103392) + 12c
000000010d110bc4 ssthrdmain (0, 1186a8, 1186a8000, 0, 118400,
ffffffff7fffe280) + 1c4
0000000104a660f8 main (2, ffffffff7fffe568, 0, ffffffff7fffe468,
ffffffff7fffe578, 0) + 138
It seems to be obvious that this code part is receiving a message.
25% I also see this
ffffffff47de2638 __write (ffffffff7d63c6d0, 10, ffffffff7d63c168, 0, 1,
0) + c
0000000117579de0 nsntwrn (ffffffff7d645ef8, ffffffff7d63c6d0,
ffffffff7d5d82e6, ffffffff7d63c168, 200000, 0) + 40
000000011758c4e0 nspsend (ffffffff7d63bf08, ffffffff7d63c168,
ffffffff7d62b420, 0, 0, 0) + 2a0
00000001175385a8 nsdofls (30a, ffffffff7d62b420, ffffffff7d63bf08,
100400c, 0, 0) + 208
0000000117534380 nsdo (ffffffff7d62b2d8, 54, ffffffff7d62b420,
ffffffff7d62b420, 0, 0) + 7480
00000001174fc464 nsfull_bsd (ffffffff7d62b2d8, ffffffff7d62b420, 1,
20, 300, 1) + 24
000000011763cab0 nioqrc (ffffffff7daad150, 11869cb48,
ffffffff7fffce0d, 1, 8, ffffffff7d62b170) + f0
0000000109de001c opikndf2 (ffffffff7daad150, 2, ffffffff7da92e0c, 1,
1a2, 1) + 45c
0000000109dce4a8 opitsk (202db9, ffffffff7da92e08, ffffffff7da92e0c,
ffffffff7da89768, 0, ffffffff7da8faf0) + 3a8
0000000109de2d24 opiino (1, ffffffff7fffe080, 10000, ffffffff7daad048,
10a, ffffffffffff3354) + 384
0000000109e0456c opiodr (22000, ffffffff7daad050, 1328, 1358, 3c, 0) +
44c
0000000109dc2ae4 opidrv (1694, 0, ffffffff7daad048, ffffffff7da92e38,
1328, 1fc00) + 384
000000010d0ea16c sou2o (ffffffff7fffe058, 3c, 4, ffffffff7fffe080,
102ebf000, 70) + 6c
0000000104a667cc opimai_real (2, ffffffff7fffe458, 1,
ffffffff7fffe080, 103392000, 103392) + 12c
000000010d110bc4 ssthrdmain (0, 1186a8, 1186a8000, 0, 118400,
ffffffff7fffe280) + 1c4
0000000104a660f8 main (2, ffffffff7fffe568, 0, ffffffff7fffe468,
ffffffff7fffe578, 0) + 138
0000000104a65f6c _start (0, 0, 0, 0, 0, 0) + 12c
That seems to be sending a message. What kind of Message could that be?
An acknowledge?
Regards
Lothar
--
//www.freelists.org/webpage/oracle-l
