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

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_at_bluewin.ch <l.flatz_at_bluewin.ch> 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_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
> 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
>> 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
>>
>>
>> --
>> http://www.freelists.org/webpage/oracle-l
>>
>>
>>
>
>

--
http://www.freelists.org/webpage/oracle-l