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

From: Jonathan Lewis <jlewisoracle_at_gmail.com>
Date: Wed, 14 Oct 2020 11:14:14 +0100
Message-ID: <CAGtsp8nok9pnRDMrHXpPXY6ryL=G82FnNup6mwyy89oXHacaew_at_mail.gmail.com>

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

Received on Wed Oct 14 2020 - 12:14:14 CEST