Re: Re: Can Bind variables be an issue with respect to network transfer?

From: <l.flatz_at_bluewin.ch>
Date: Wed, 14 Oct 2020 12:38:30 +0200 (CEST)
Message-ID: <1342704409.25480.1602671910078_at_bluewin.ch>

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_at_gmail.com
Datum : 14/10/2020 - 12:14 (MS)
An : oracle-l_at_freelists.org
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

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_at_bluewin.ch> 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