5 Replies Latest reply on Sep 20, 2017 12:58 PM by Mike Kutz

    Very slow query execution on 11.2g

    FedeGiova

      We have an ongoing issue after an upgrade to 11.2 from 10.2 where the same application used to run flawless; now some

      queries take an exceptionally long time to complete while the CPU on the server spinning at 100% for several minutes, an example

      on one of those query is:

       

      SELECT EVA_COMP.MVTIPREC,

             EVA_COMP.MVROWNUM,

             EVA_COMP.CPROWORD,

             EVA_COMP.MVTIPRIG,

             EVA_COMP.MVCODICE,

             EVA_COMP.MVCODART,

             EVA_COMP.MVUNIMIS,

             EVA_COMP.MVQTAMOV,

             EVA_COMP.MVQTAUM1,

             EVA_COMP.MVCODCAU,

             EVA_COMP.CPROWNUM,

             KEY_ARTI.CADESART AS MVDESART,

             KEY_ARTI.CADESSUP AS MVDESSUP,

             ART_ICOL.ARCATCON,

             ART_ICOL.ARCODCLA,

             ART_ICOL.ARCODIVA,

             VOCIIVA.IVPERIVA,

             VOCIIVA.IVBOLIVA,

             ART_ICOL.ARPESNET,

             ART_ICOL.ARNOMENC,

             ART_ICOL.ARUMSUPP,

             ART_ICOL.ARMOLSUP,

             ART_ICOL.ARFLLOTT,

             EVA_COMP.MVDATEVA,

             EVA_COMP.MVSERRIF,

             EVA_COMP.MVROWRIF,

             EVA_COMP.MVQTASAL,

             EVA_COMP.MVCODMAG,

             EVA_COMP.MVKEYSAL,

             EVA_COMP.MVFLORDI,

             EVA_COMP.MVFLIMPE,

             EVA_COMP.MVFLRISE,

             EVA_COMP.MVFLERIF,

             EVA_COMP.MVDESSUP AS MVDESSU1,

             ART_ICOL.ARMAGPRE,

             EVA_COMP.MVMAGORI,

             EVA_COMP.MVMATORI,

             EVA_COMP.MVCODCEN,

             EVA_COMP.MVCODCOM,

             EVA_COMP.MVCODATT,

             ART_ICOL.ARVOCCEN,

             ART_ICOL.ARVOCRIC,

             ART_ICOL.ARCODCEN,

             EVA_ARTI.CPROWORD AS ROWDISP,

             EVA_ARTI.MVCODART AS CODART,

             ART_ICOL.ARDATINT

      FROM

      (

          (  

              (

                  (

                      GIOPLART_ICOL ART_ICOL INNER JOIN GIOPLEVA_COMP EVA_COMP ON EVA_COMP.MVCODART=ART_ICOL.ARCODART

                  )

                  INNER JOIN GIOPLKEY_ARTI KEY_ARTI ON EVA_COMP.MVCODICE=KEY_ARTI.CACODICE

              )

              INNER JOIN GIOPLEVA_ARTI EVA_ARTI ON EVA_ARTI.MVSERIAL=EVA_COMP.MVSERIAL

                  AND EVA_ARTI.CPROWNUM=EVA_COMP.MVROWNUM

          )

          LEFT OUTER JOIN GIOPLVOCIIVA VOCIIVA ON VOCIIVA.IVCODIVA=ART_ICOL.ARCODIVA

      )

      WHERE (EVA_COMP.MVSERIAL = '0000023301'

             AND EVA_COMP.MVTIPREC IN ('1', '2'))

      ORDER BY 1,2,3

       

       

      Note that the biggest table in this example has 3k rows while GIOPLVOCIIVA has 4/5 rows so I don't expect a combinatorial explosion due to the outer join and the

      size of the computation should be well beyond the capabilities of our (last gen - 1) Xeon CPU.

       

      Moreover the issue manifest itself when the database is accessed by the instant_client ODBC, in that case we have the CPU _on the server_ spinning and the

      query above takes 5-6 minutes to complete, the same query issued on the same client machine by JDBC is instantaneous; the execution is slow even from sqlplus on the client

      but not from sqlplus on the server. Moreover the execution plans in both case are completely different, it's like if for the ODBC access we're bypassing all the indexes.

       

      Oracle in installed on a Centos 7 distribution, I've checked the kernel parameters like shmmax and they are fine but I don't see the problem in our specific setup because

      while the oracle process is spinning the rest of the system is almost idle, if the problem is caused by a kernel / filesystem issues I'd rather expect some kernel thread to be busy as well.

       

      The client uses instant_client 12.2.0.1.0 32bit installed on Windows 10 Pro creators update at 64bit.

        • 1. Re: Very slow query execution on 11.2g
          Gaz in Oz

          . Are the table/index stats up-to-date for that table? (and the other table/s used in the badly performing sql?)

          . Are the CBO related initialization parameters the same in the old and the new db?

          . Have you done any testing with hints to try and force the query to use the same execution path it used to take?

          . Are disks, cpu, other hardware of a higher spec (supposidly faster) than the old machine? (as it seems you have upgraded database AND migrated to a different server).

           

          Please read these:

          When your query takes too long ...

          HOW TO: Post a SQL statement tuning request - template posting

          • 2. Re: Very slow query execution on 11.2g
            FedeGiova

            Thank you for you support!

             

            - the indexes are fine for the dbs, at least:

               SELECT owner, index_name, tablespace_name

                  FROM dba_indexes

                  WHERE status = 'UNUSABLE';

              returns nothing

             

            - actually I haven't touched any optimizer parameters, they are left as the installation default

            - the cpu and the hardware is definitely faster than the previous machine; we've upgraded an 8 years old server, now we have

              16Gb of RAM and the disk benchmarks gives around 180Mbyte/sec for reads and writes.

             

            But I've captured the trace for both cases and the results are surprising different; here is the trace obtained by ODBC

             

            Rows (1st) Rows (avg) Rows (max)  Row Source Operation

            ---------- ---------- ----------  ---------------------------------------------------

                     1          1          1  SORT ORDER BY (cr=232 pr=23760 pw=190215 time=281800280 us cost=74 size=3016 card=1)

                     1          1          1   HASH JOIN OUTER (cr=232 pr=23760 pw=190215 time=281800262 us cost=73 size=3016 card=1)

                     1          1          1    HASH JOIN  (cr=230 pr=23760 pw=190215 time=281800094 us cost=69 size=3005 card=1)

               5925858    5925858    5925858     MERGE JOIN CARTESIAN (cr=224 pr=0 pw=0 time=1985312 us cost=67 size=249 card=1)

                  3174       3174       3174      MERGE JOIN CARTESIAN (cr=111 pr=0 pw=0 time=4108 us cost=32 size=194 card=1)

                     1          1          1       TABLE ACCESS FULL GIOPLEVA_ARTI (cr=6 pr=0 pw=0 time=198 us cost=2 size=90 card=1)

                  3174       3174       3174       BUFFER SORT (cr=105 pr=0 pw=0 time=3301 us cost=30 size=322088 card=3097)

                  3174       3174       3174        TABLE ACCESS FULL GIOPLKEY_ARTI (cr=105 pr=0 pw=0 time=810 us cost=30 size=322088 card=3097)

               5925858    5925858    5925858      BUFFER SORT (cr=113 pr=0 pw=0 time=1433203 us cost=36 size=102410 card=1862)

                  1867       1867       1867       TABLE ACCESS FULL GIOPLART_ICOL (cr=113 pr=0 pw=0 time=1413 us cost=34 size=102410 card=1862)

                     1          1          1     TABLE ACCESS FULL GIOPLEVA_COMP (cr=6 pr=0 pw=0 time=243 us cost=2 size=2756 card=1)

                    35         35         35    TABLE ACCESS FULL GIOPLVOCIIVA (cr=2 pr=0 pw=0 time=24 us cost=3 size=385 card=35)

             

             

            And here _the same query_ issued by SqlDeveloper

            Rows (1st) Rows (avg) Rows (max)  Row Source Operation

            ---------- ---------- ----------  ---------------------------------------------------

                     1          1          1  SORT ORDER BY (cr=12 pr=0 pw=0 time=459 us cost=2 size=3016 card=1)

                     1          1          1   NESTED LOOPS OUTER (cr=12 pr=0 pw=0 time=413 us cost=1 size=3016 card=1)

                     1          1          1    NESTED LOOPS  (cr=10 pr=0 pw=0 time=379 us cost=0 size=3005 card=1)

                     1          1          1     NESTED LOOPS  (cr=7 pr=0 pw=0 time=324 us cost=0 size=2901 card=1)

                     1          1          1      NESTED LOOPS  (cr=4 pr=0 pw=0 time=184 us cost=0 size=2846 card=1)

                     1          1          1       TABLE ACCESS BY INDEX ROWID GIOPLEVA_ARTI (cr=2 pr=0 pw=0 time=51 us cost=0 size=90 card=1)

                     1          1          1        INDEX RANGE SCAN PK_GIOPLEVA_ARTI (cr=1 pr=0 pw=0 time=41 us cost=0 size=0 card=1)(object id 27246)

                     1          1          1       TABLE ACCESS BY INDEX ROWID GIOPLEVA_COMP (cr=2 pr=0 pw=0 time=130 us cost=0 size=2756 card=1)

                     1          1          1        INDEX RANGE SCAN PK_GIOPLEVA_COMP (cr=1 pr=0 pw=0 time=30 us cost=0 size=0 card=1)(object id 27248)

                     1          1          1      TABLE ACCESS BY INDEX ROWID GIOPLART_ICOL (cr=3 pr=0 pw=0 time=137 us cost=0 size=55 card=1)

                     1          1          1       INDEX UNIQUE SCAN PK_GIOPLART_ICOL (cr=2 pr=0 pw=0 time=49 us cost=0 size=0 card=1)(object id 27514)

                     1          1          1     TABLE ACCESS BY INDEX ROWID GIOPLKEY_ARTI (cr=3 pr=0 pw=0 time=53 us cost=0 size=104 card=1)

                     1          1          1      INDEX UNIQUE SCAN PK_GIOPLKEY_ARTI (cr=2 pr=0 pw=0 time=28 us cost=0 size=0 card=1)(object id 27656)

                     1          1          1    TABLE ACCESS BY INDEX ROWID GIOPLVOCIIVA (cr=2 pr=0 pw=0 time=30 us cost=1 size=11 card=1)

                     1          1          1     INDEX UNIQUE SCAN PK_GIOPLVOCIIVA (cr=1 pr=0 pw=0 time=6 us cost=0 size=0 card=1)(object id 27195)

             

             

            Total execution time 0.5ms vs 281 s. and to a good reason since the optimizer is expanding the query to 5 millions rows.

             

            I really don't have any idea about why the execution paths are so different, moreover the queries are executed by an accounting software whose code I cannot touch.

            • 3. Re: Very slow query execution on 11.2g
              Mike Kutz

              Did you notice that SQL*Developer thinks that the Cardinality=1 for every step and the ODBC does not?

              Which one is correct?

              Which one runs faster?

              • 4. Re: Very slow query execution on 11.2g
                FedeGiova

                Actually we have found the point. It seems that the whole problem was caused by

                 

                NLS_COMP=LINGUISTIC

                NLS_SORT=BINARY_CI

                 

                in an environment variable on the windows hosts; after removing them the query speed went back to the normal value

                and the CPU usage dropped. It might be some misconfiguration of the indexes by the accounting software?

                 

                Thank you for your valuable support.

                • 5. Re: Very slow query execution on 11.2g
                  Mike Kutz

                  FedeGiova wrote:

                   

                  Actually we have found the point. It seems that the whole problem was caused by

                   

                  NLS_COMP=LINGUISTIC

                  NLS_SORT=BINARY_CI

                   

                  in an environment variable on the windows hosts; after removing them the query speed went back to the normal value

                  and the CPU usage dropped. It might be some misconfiguration of the indexes by the accounting software?

                   

                  Thank you for your valuable support.

                   

                  You better do some serious testing.

                  If I understand things correctly, those parameters affect how "ö" and "o" match.

                   

                  MK