Re: Weird Oracle 12.2 issue ..

From: Sayan Malakshinov <xt.and.r_at_gmail.com>
Date: Fri, 15 Sep 2017 10:49:25 +0300
Message-ID: <CAOVevU66EKSjqWH9jJchcaVewO5ieq989H=o+hg-ezSrv9MYVA_at_mail.gmail.com>



Upendra,

*why does this query runs faster when it is run directly on the DB server vs run through a client?*
Because your client requires additional roundtrip for each of your LOBs. As far as I remember SQL*Plus doesn't support special functions for LOB buffering like these:
https://docs.oracle.com/cd/B28359_01/appdev.111/b28395/oci07lob.htm#i444556 You can try to use latest versions Oracle SQL Developer or SQLCl

*Is there a relationship between the LOB data and the latency we are seeing?*
Just comment out the part with lobs and you'll see the difference. And do not forget to change arraysize.

On Fri, Sep 15, 2017 at 10:35 AM, Upendra nerilla <nupendra_at_hotmail.com> wrote:

> It is true that we are using LOBs, but the main question is, why does this
> query runs faster when it is run directly on the DB server vs run through a
> client?
>
> Directly executing your query completed in 2.65 seconds. However when the
> same query was executed through a sqlplus client (through sqlnet) it took
> 14+ seconds..
>
> Is there a relationship between the LOB data and the latency we are seeing?
>
> Here is the description of the function call:
>
> FUNCTION GET_DESC_LIST RETURNS VARCHAR2
> Argument Name Type In/Out Default?
> ------------------------------ ----------------------- ------ --------
> P_DESC_ID NUMBER IN
> FUNCTION GET_DESC_LIST RETURNS VARCHAR2
> Argument Name Type In/Out Default?
> ------------------------------ ----------------------- ------ --------
> P_DESC_ID NUMBER IN
> P_CLIENT_ID NUMBER IN
>
> _at_Peter, I put in the sqlnet.ora parameter, i didn't see any difference
> between the executions.
>
>
> -Upendra
>
>
> ------------------------------
> *From:* Sayan Malakshinov <xt.and.r_at_gmail.com>
> *Sent:* Friday, September 15, 2017 2:50 AM
> *To:* pgr_at_miracle.dk
> *Cc:* Upendra nerilla; Oracle-L
> *Subject:* Re: Weird Oracle 12.2 issue ..
>
> Upendra,
>
> I've just checked your trace file for LOBS:
> $ grep -c LOBREAD rcaqa_ora_27261.trc
> 590
>
> $ awk -F, '/LOBREAD/ {print $2}' rcaqa_ora_27261.trc | sort | uniq
> bytes=25
> bytes=80
>
> Could you show what returns the function *aep_i18n.get_desc_list*?
> Execute "*desc aep_i18n.get_desc_list*" in sql*plus and send us the
> output of this command.
>
> Also you can try the following query - I've split allFields0 into 2
> columns: allFields0_varchar is for short strings(as varchar2)
>
> select
> SERVICE_NAME
> ,ID
> ,DESCRIPTION_ID
> ,case when length("allFields0")<=4000 then cast("allFields0" as
> varchar2(4000)) end "allFields0_varchar"
> ,case when length("allFields0")>4000 then "allFields0" end
> "allFields0_CLOB"
> from (
> select /*+NO_XML_QUERY_REWRITE*/
> AES_REC_TYPE.SERVICE_NAME SERVICE_NAME,
> AES_REC_TYPE.ID ID,
> aep_i18n.get_desc_list(AES_REC_TYPE.DESCRIPTION_ID,
> AES_REC_TYPE.CLIENT_ID) "DESCRIPTION_ID",
> (SELECT (xmlelement("_fieldType",
> xmlagg(xmlelement("allFields",
> xmlforest(AES_FLD_TYPE.SERVICE_NAME
> SERVICE_NAME0, AES_FLD_TYPE.ID ID0, aep_i18n.get_desc_list(AES_FLD_TYPE.DESCRIPTION_ID,
> AES_REC_TYPE.CLIENT_ID) "DESCRIPTION_ID0",
> aep_attributes.fetch_attr(AES_
> FLD_TYPE.ID, 'AES_FLD_TYPE', 'COLUMN_NAME', AES_REC_TYPE.CLIENT_ID)
> "COLUMN_NAME",
> aep_attributes.fetch_attr(AES_
> FLD_TYPE.ID, 'AES_FLD_TYPE', 'BI_COLUMN_NAME', AES_REC_TYPE.CLIENT_ID)
> "BI_COLUMN_NAME"))))).getClobVal()
>
> FROM AES_FLD_TYPE AES_FLD_TYPE
> WHERE AES_REC_TYPE.ID = AES_FLD_TYPE.REC_TYPE_ID
> AND AES_FLD_TYPE.DELETED_DATE IS NULL
> AND AES_REC_TYPE.client_id = AES_FLD_TYPE.client_id)
> "allFields0"
> FROM AES_REC_TYPE AES_REC_TYPE
> WHERE AES_REC_TYPE.DELETED_DATE IS NULL
> AND AES_REC_TYPE.CLIENT_ID = 12313400144 <(231)%20340-0144>
> )
> /
>
>
> On Fri, Sep 15, 2017 at 9:19 AM, Peter Gram Miracle A/S <pgr_at_miracle.dk>
> wrote:
>
>> Hi
>>
>> Try setting tcp.nodelay=yes in the sqlnet.ora on the client just to make
>> surer you are not bite by that.
>>
>> Gram/
>>
>>
>> Med Venlig Hilsen
>>
>> Peter Gram
>>
>> Kultur-kustode for Miracle
>>
>> *Miracle Expert Services*
>> Borupvang 2c, 2750 Ballerup, Denmark
>> <https://maps.google.com/?q=Borupvang+2c,+2750+Ballerup,+Denmark&entry=gmail&source=g>
>> Cell: (+45) 53747107 <+45%2053%2074%2071%2007>
>> Office Phone: (+45) 44668855 <+45%2044%2066%2088%2055>
>> Office Fax: (+45) 44668856 <+45%2044%2066%2088%2056>
>> Home : (+45) 38745696 <+45%2038%2074%2056%2096>
>> Home : Sæbyholmsvej 18 2500 Valby
>> <https://maps.google.com/?q=S%C3%A6byholmsvej+18+2500+Valby&entry=gmail&source=g>
>> Mail: peter.gram_at_miracle.dk
>> linkedin: dk.linkedin.com/in/petergram/
>> OakTable : oaktable.net/members <http://oaktable.net/members>
>>
>> On 15 September 2017 at 01:17, Upendra nerilla <nupendra_at_hotmail.com>
>> wrote:
>>
>>> All,
>>>
>>> We are running into a unique issue.. We recently migrated a database
>>> from 11.2 to 12.2 for testing.
>>>
>>> When we compared the performance, 12.2 performance was 3x-4x slow
>>> compared to 11g.
>>>
>>> When we were peeling the layers to troubleshoot, we discovered:
>>>
>>> - A query which runs in 3 seconds at the database directly (in 12.2)
>>> takes between 11-14 seconds when it is run through a client like pl/sql
>>> developer.
>>> - To eliminate the variables, we ran sqlplus from another host
>>> (which is in same network), and the execution time was still over 13
>>> seconds.
>>> - sqlplus on the DB server (using tns/sqlnet) produces the result in
>>> about 3 seconds as well
>>> - Sysadmin says, Network throughput between the servers have no
>>> issue, he was able to scp a 500MB file in less than 2 seconds.
>>>
>>>
>>> Here is the output from SQL trace.. the output from running the query
>>> from the DB server and through the client produce identical output, except
>>> the elapsed time..
>>>
>>>
>>> <snip>
>>>
>>> 583 rows selected.
>>>
>>>
>>> *Elapsed: 00:00:02.51 vs Elapsed: 00:00:11.44 *
>>> Execution Plan
>>> ----------------------------------------------------------
>>> Plan hash value: 2598178018
>>>
>>> ------------------------------------------------------------
>>> ------------------------------------------------
>>> | Id | Operation | Name |
>>> Rows | Bytes | Cost (%CPU)| Time |
>>> ------------------------------------------------------------
>>> ------------------------------------------------
>>> | 0 | SELECT STATEMENT | |
>>> 1220 | 56120 | 1244 (0)| 00:00:01 |
>>> | 1 | SORT AGGREGATE | |
>>> 1 | 47 | | |
>>> |* 2 | TABLE ACCESS BY INDEX ROWID BATCHED| AES_FLD_TYPE |
>>> 1 | 47 | 2 (0)| 00:00:01 |
>>> |* 3 | INDEX RANGE SCAN | AES_IDX_FTYPE_RTYPE |
>>> 1 | | 1 (0)| 00:00:01 |
>>> |* 4 | TABLE ACCESS FULL | AES_REC_TYPE |
>>> 1220 | 56120 | 24 (0)| 00:00:01 |
>>> ------------------------------------------------------------
>>> ------------------------------------------------
>>>
>>> Predicate Information (identified by operation id):
>>> ---------------------------------------------------
>>>
>>> 2 - filter("AES_FLD_TYPE"."DELETED_DATE" IS NULL)
>>> 3 - access("AES_FLD_TYPE"."REC_TYPE_ID"=:B1 AND
>>> "AES_FLD_TYPE"."CLIENT_ID"=:B2)
>>> 4 - filter("AES_REC_TYPE"."DELETED_DATE" IS NULL AND
>>> "AES_REC_TYPE"."CLIENT_ID"=12313400144 <(231)%20340-0144>)
>>>
>>> Statistics
>>> ----------------------------------------------------------
>>> 66503 recursive calls
>>> 0 db block gets
>>> 71151 consistent gets
>>> 0 physical reads
>>> 0 redo size
>>> 382206 bytes sent via SQL*Net to client
>>> 248383 bytes received via SQL*Net from client
>>> 1168 SQL*Net roundtrips to/from client
>>> 0 sorts (memory)
>>> 0 sorts (disk)
>>> 583 rows processed
>>> <snip>
>>>
>>> Any suggestions on what I could check to pin-point the issue might be
>>> helpful..
>>>
>>> Thanks in advance
>>>
>>>
>>> -Upendra
>>>
>>
>>
>
>
> --
> Best regards,
> Sayan Malakshinov
> Oracle performance tuning engineer
> Oracle ACE Associate
> http://orasql.org
>

-- 
Best regards,
Sayan Malakshinov
Oracle performance tuning engineer
Oracle ACE Associate
http://orasql.org

--
http://www.freelists.org/webpage/oracle-l
Received on Fri Sep 15 2017 - 09:49:25 CEST

Original text of this message