1 2 Previous Next 15 Replies Latest reply on Jan 12, 2016 8:49 AM by user8850362

    [Bug?] Autotrace without output

    user8850362

      I recently stumbled across a bug(?) while using autotrace in sql developer. Many statements generate an autotrace output. But there are some that doesnt. I tried to reproduce our select for an environment without our data but i didnt succeded. But then i accidentally found this misbehavior while using a very very basic select. Its reproducable for me:

       

      (1) select * from dba_indexes where owner in ('SYS');

      (2) select * from dba_indexes where owner = 'SYS';

      (3) select * from dba_indexes order by 'SYS';

       

      but not while executing

      (4) select * from dba_indexes;

       

      Executing an autotrace script produces the following output, eg. for select (2):

      Plan hash value: 186721070

       

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

      | Id  | Operation                                     | Name            | Rows  | Bytes | Cost (%CPU)| Time     |

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

      |   0 | SELECT STATEMENT                              |                 |    93 | 42222 |   784   (1)| 00:00:01 |

      |*  1 |  HASH JOIN                                    |                 |    93 | 42222 |   784   (1)| 00:00:01 |

      |   2 |   TABLE ACCESS FULL                           | USER$           |   140 |  2800 |     5   (0)| 00:00:01 |

      |   3 |   NESTED LOOPS                                |                 |    93 | 40362 |   779   (1)| 00:00:01 |

      |   4 |    NESTED LOOPS                               |                 |    93 | 40362 |   779   (1)| 00:00:01 |

      |*  5 |     HASH JOIN RIGHT OUTER                     |                 |    93 | 36921 |   593   (1)| 00:00:01 |

      |   6 |      TABLE ACCESS FULL                        | USER$           |   140 |  2800 |     5   (0)| 00:00:01 |

      |   7 |      NESTED LOOPS OUTER                       |                 |    93 | 35061 |   587   (1)| 00:00:01 |

      |   8 |       NESTED LOOPS OUTER                      |                 |    93 | 31992 |   401   (1)| 00:00:01 |

      |*  9 |        HASH JOIN RIGHT OUTER                  |                 |    93 | 28086 |   308   (1)| 00:00:01 |

      |  10 |         TABLE ACCESS FULL                     | TS$             |   141 |  4794 |    41   (0)| 00:00:01 |

      |  11 |         NESTED LOOPS OUTER                    |                 |    93 | 24924 |   266   (1)| 00:00:01 |

      |  12 |          NESTED LOOPS                         |                 |    93 | 14043 |   266   (1)| 00:00:01 |

      |  13 |           NESTED LOOPS                        |                 |   409 | 24949 |   255   (1)| 00:00:01 |

      |  14 |            TABLE ACCESS BY INDEX ROWID        | USER$           |     1 |    20 |     1   (0)| 00:00:01 |

      |* 15 |             INDEX UNIQUE SCAN                 | I_USER1         |     1 |       |     0   (0)| 00:00:01 |

      |* 16 |            TABLE ACCESS BY INDEX ROWID BATCHED| OBJ$            |   409 | 16769 |   254   (1)| 00:00:01 |

      |* 17 |             INDEX RANGE SCAN                  | I_OBJ2          |   409 |       |     6   (0)| 00:00:01 |

      |* 18 |           TABLE ACCESS BY INDEX ROWID         | IND$            |     1 |    90 |     1   (0)| 00:00:01 |

      |* 19 |            INDEX UNIQUE SCAN                  | I_IND1          |     1 |       |     0   (0)| 00:00:01 |

      |  20 |          TABLE ACCESS BY INDEX ROWID          | DEFERRED_STG$   |     1 |   117 |     0   (0)| 00:00:01 |

      |* 21 |           INDEX UNIQUE SCAN                   | I_DEFERRED_STG1 |     1 |       |     0   (0)| 00:00:01 |

      |  22 |        TABLE ACCESS CLUSTER                   | SEG$            |     1 |    42 |     1   (0)| 00:00:01 |

      |* 23 |         INDEX UNIQUE SCAN                     | I_FILE#_BLOCK#  |     1 |       |     0   (0)| 00:00:01 |

      |  24 |       TABLE ACCESS BY INDEX ROWID BATCHED     | OBJ$            |     1 |    33 |     2   (0)| 00:00:01 |

      |* 25 |        INDEX RANGE SCAN                       | I_OBJ1          |     1 |       |     1   (0)| 00:00:01 |

      |* 26 |     INDEX RANGE SCAN                          | I_OBJ1          |     1 |       |     1   (0)| 00:00:01 |

      |  27 |    TABLE ACCESS BY INDEX ROWID                | OBJ$            |     1 |    37 |     2   (0)| 00:00:01 |

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

       

      Predicate Information (identified by operation id):

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

       

         1 - access("IO"."OWNER#"="IU"."USER#")

         5 - access("ITO"."OWNER#"="ITU"."USER#"(+))

         9 - access("I"."TS#"="TS"."TS#"(+))

        15 - access("U"."NAME"='SYS')

        16 - filter(BITAND("O"."FLAGS",128)=0)

        17 - access("U"."USER#"="O"."OWNER#" AND "O"."NAME" LIKE 'I_CDE%')

             filter("O"."NAME" LIKE 'I_CDE%')

        18 - filter(BITAND("I"."FLAGS",4096)=0)

        19 - access("O"."OBJ#"="I"."OBJ#")

        21 - access("I"."OBJ#"="DS"."OBJ#"(+))

        23 - access("I"."TS#"="S"."TS#"(+) AND "I"."FILE#"="S"."FILE#"(+) AND "I"."BLOCK#"="S"."BLOCK#"(+))

        25 - access("I"."INDMETHOD#"="ITO"."OBJ#"(+))

        26 - access("I"."BO#"="IO"."OBJ#")

       

         Statistics

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

                     1  CPU used by this session

                     1  CPU used when call started

                     2  DB time

                     5  Requests to/from client

                   226  consistent gets

                    17  consistent gets examination

                    17  consistent gets examination (fastpath)

                   226  consistent gets from cache

                   209  consistent gets pin

                   209  consistent gets pin (fastpath)

                     5  non-idle wait count

                     3  opened cursors cumulative

                     1  opened cursors current

                     1  pinned cursors current

                   226  session logical reads

                     7  user calls

       

      Executing the same within sql developer using the autotrace button does not generate an output(On the other hand, statement (4) does):

      strange2.PNG

      Reproducable at least with sql developer 4.1.1 and 4.1.2.

       

      There is no entry in the log.

        • 1. Re: [Bug?] Autotrace without output
          thatJeffSmith-Oracle

          I tried both select on indexes view with no predicates and also what you have in your screenshot

          SELECT * FROM dba_indexes WHERE owner = 'SYS' AND

          index_name like 'I_CDE%'

           

          Both return plans and stats.

           

          What do you have enabled in autotrace page in preferences?

           

          Here's what you should see in your statements panel, guessing our SQL_ID would be different...

           

          2364sqldevdemo2alter session set statistics_level=TYPICALnull
          2363sqldevdemo1rollbacknull
          2362sqldevdemo19select s.last_elapsed_time , s.last_output_rows , s.last_cr_buffer_gets , s.last_starts, s.LAST_DISK_READS, s.LAST_CU_BUFFER_GETS, s.LAST_DISK_WRITES , p.* from v$sql_plan p, v$sql_plan_statistics s where p.hash_value = ? and p.child_number = ? and p.hash_value = s.hash_value(+) and p.child_number = s.child_number(+)and p.id = s.operation_id(+)order by p.id1="2391764784", 2="1"
          2361sqldevdemo2select hash_value, child_number from v$sql where sql_id = ? order by last_load_time desc1="4kw75by78yvth"
          2360sqldevdemo6  select name,value, ROW_NUMBER() OVER (ORDER BY pt.STATISTIC#) num from V$STATNAME sn, V$mystat pt where sn.STATISTIC# = pt.STATISTIC# order by lower(name) null
          2359sqldevdemo91SELECT * FROM dba_indexes WHERE owner = 'SYS' AND index_name like 'I_CDE%'null
          2358sqldevdemo23  select name,value, ROW_NUMBER() OVER (ORDER BY pt.STATISTIC#) num from V$STATNAME sn, V$mystat pt where sn.STATISTIC# = pt.STATISTIC# order by lower(name) null
          2357sqldevdemo1alter session set TIMED_STATISTICS = TRUEnull
          • 2. Re: [Bug?] Autotrace without output
            user8850362

            Hi Jeff,

             

            thank you for answering so fast. My settings for autotrace are as follows:

            checkboxes are set for: cardinality, cost, last_cr_buffer_gets, object name

            and for

            V$MYSTAT

            skip statistics with zero values (sry, my own translation from german)

            all rows.

             

            explain plan creates an output btw.

             

            Statement log is as follows:

             

            select hash_value, child_number from v$sql where sql_id = ? order by last_load_time desc
              select name,value, ROW_NUMBER() OVER (ORDER BY pt.STATISTIC#) num from V$STATNAME sn, V$mystat pt where sn.STATISTIC# = pt.STATISTIC# order by lower(name)
            select * from dba_indexes where owner = 'SYS' and index_name like 'I_CDE%'
              select name,value, ROW_NUMBER() OVER (ORDER BY pt.STATISTIC#) num from V$STATNAME sn, V$mystat pt where sn.STATISTIC# = pt.STATISTIC# order by lower(name)
            alter session set TIMED_STATISTICS = TRUE
            alter session set statistics_level=ALL

             

            PS: i wanted to thank you for your youtube sql dev channel. Its really helpful and enjoying. I really appreciate it.

            • 3. Re: [Bug?] Autotrace without output
              thatJeffSmith-Oracle

              I wonder if it's not finding the SQL_ID, is it right? maybe we're hashing it wrong

              • 4. Re: [Bug?] Autotrace without output
                user8850362

                Could be right: i just took the sqlid from the statements list:

                 

                select * from v$sql where sql_id = '46bkjcm1pm3xr';

                 

                Didnt find a row.

                 

                Then i ran this

                select * from  v$sql where sql_text like '%I_CDE%';

                 

                and found a row with  sql_id = am7d33pqab9f2.

                 

                Maybe this is important: we have some adaptive_plan options enabled:

                optimizer_adaptive_reporting_only   FALSE

                optimizer_adaptive_features   TRUE

                 

                Regards.

                • 5. Re: [Bug?] Autotrace without output
                  thatJeffSmith-Oracle

                  def the prob is that the sql_id isn't found, can't pull a plan w/o it

                   

                  why it's wrong, that I can't say, but I'll ask the dev to take a look

                  • 6. Re: [Bug?] Autotrace without output
                    Vadim Tropashko-Oracle

                    Let's establish what correct sql_id value is.  The problem is that adding/removing a single white space changes it, perhaps that new line interpretation difference between various operating systems playing legacy joke on us.

                     

                    Question 1: is problem reproducible for one line statements?

                     

                    Question 2: I see the following sql_id values:


                    select * from dba_indexes where owner = 'SYS' and index_name like 'I_CDE%';

                    sql_id = "dn7vqd0rrv8uq"

                     

                    select * from dba_indexes where owner = 'SYS'

                    and index_name like 'I_CDE%';

                    sql_id =  "gtrpra14uyr3m"


                    The easy way to know sql_id is just hit the plan menu button; there would be 3 menu items with sql_id value. After executing autotrace I see the first one one (Child_number=1) enabled.

                    • 7. Re: [Bug?] Autotrace without output
                      user8850362

                      Hi there,

                      i dont know if these are questions for me...

                      If i execute "select * from dba_indexes where owner = 'SYS' and index_name like 'I_CDE%';" i see three disabled children (under the plan button) with the sql_id dn7vqd0rrv8uq. Hitting the autotrace button leads to an empty trace.

                       

                      "select * from dba_indexes where owner = 'SYS'

                      and index_name like 'I_CDE%';"

                       

                      ...leads to three disabled children with a different sql_id 46bkjcm1pm3xr. Also, here is no output.

                       

                      Querying "select * from V$sql where sql_text like '%index_name like%';" now leads to some hits with the cursor select * from dba_indexes where owner = :"SYS_B_0" and index_name like :"SYS_B_1". But these are two different sql_ids: 72gkudf8qwzzs and 5f29ckd99anhh.

                       

                      Maybe my ideas analyzing this is wrong. Please correct me, if i should do something else.

                       

                       

                      Let me know if you need additional info. I am on a german windows 7 machine.

                       

                      My nls_parameters:

                       

                      PARAMETERSESSIONDATABASEINSTANCE
                      NLS_COMPBINARYBINARYBINARY
                      NLS_SORTGERMANGERMANnull
                      NLS_CALENDARGREGORIANGREGORIANnull
                      NLS_CURRENCY?null
                      NLS_LANGUAGEGERMANGERMANGERMAN
                      NLS_TERRITORYGERMANYGERMANYGERMANY
                      NLS_DATE_FORMATDD.MM.RRDD.MM.YYYYDD.MM.RR
                      NLS_TIME_FORMATHH24:MI:SSXFFHH24:MI:SSXFFnull
                      NLS_CHARACTERSETnullWE8MSWIN1252null
                      NLS_ISO_CURRENCYGERMANYGERMANYnull
                      NLS_DATE_LANGUAGEGERMANGERMANnull
                      NLS_DUAL_CURRENCY?null
                      NLS_RDBMS_VERSIONnull12.1.0.2.0null
                      NLS_TIME_TZ_FORMATHH24:MI:SSXFF TZRHH24:MI:SSXFF TZRnull
                      NLS_NCHAR_CONV_EXCPFALSEFALSEFALSE
                      NLS_LENGTH_SEMANTICSBYTEBYTEBYTE
                      NLS_TIMESTAMP_FORMATDD.MM.RR HH24:MI:SSXFFDD.MM.RR HH24:MI:SSXFFnull
                      NLS_NCHAR_CHARACTERSETnullAL16UTF16null
                      NLS_NUMERIC_CHARACTERS,.,.null
                      NLS_TIMESTAMP_TZ_FORMATDD.MM.RR HH24:MI:SSXFF TZRDD.MM.RR HH24:MI:SSXFF TZRnull

                      .

                      • 8. Re: [Bug?] Autotrace without output
                        user8850362

                        I provide additional settings within the sql developer

                        settings.PNG

                        The gui language obviously is not english but i am sure you know how to identify the correct translation.

                        • 9. Re: [Bug?] Autotrace without output
                          user8850362

                          I made some other tests. There seems to be a pattern:

                           

                          select * from user_tables;

                          select * from user_tables order by "TABLE_NAME";

                          select * from user_tables order by table_name;

                          select * from user_tables where table_name is not null;

                          select * from dba_tables where tablespace_name is null;

                           

                          All of the above are fine. There is at least one not disabled entry under the plan button. The followings do not show an enabled plan entry:

                           

                          select * from user_tables where table_name like 'O%';

                          select * from user_tables where table_name = 'OL$HINTS';

                          select * from user_tables where pct_free = 10;

                          select * from user_tables where table_name in ('OL$HINTS');

                           

                          I typed all characters by myself, no copy and paste.

                           

                          uh..uh.. i got it, maybe: Look at the following database parameter:

                           

                          cursor_sharing    force

                           

                          If i am not wrong it means that literals will be replaced by bind variables. Therefore maybe the statement can't be found.

                          • 10. Re: [Bug?] Autotrace without output
                            thatJeffSmith-Oracle

                            As a work-aroud, in your worksheet

                             

                            set autotrace on

                             

                            your script/sql

                             

                            execute via F5

                             

                            you'll get the sqlplus style autotrace output

                             

                            106 rows selected

                            Plan hash value: 1445457117

                             

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

                            | Id  | Operation                                 | Name      | Rows  | Bytes | Cost (%CPU)| Time                      |

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

                            |   0 | SELECT STATEMENT            |                 |   106   |  9858 |     3   (0)        | 00:00:01                |

                            |   1 |  TABLE ACCESS FULL           | EMPLOYEES      |   106  |  9858             |     3   (0)| 00:00:01 |

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

                             

                             

                               Statistics

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

                                          42  CPU used by this session

                                          49  CPU used when call started

                                          63  DB time

                                          27  Requests to/from client

                                          27  SQL*Net roundtrips to/from client

                                        1496  buffer is not pinned count

                                          91  buffer is pinned count

                                        1280  bytes received via SQL*Net from client

                                       53427  bytes sent via SQL*Net to client

                                         589  calls to get snapshot scn: kcmgss

                                          76  calls to kcmgcs

                                      647168  cell physical IO interconnect bytes

                                         111  cluster key scan block gets

                                          99  cluster key scans

                                        1888  consistent gets

                                         653  consistent gets examination

                                         649  consistent gets examination (fastpath)

                                        1888  consistent gets from cache

                                        1235  consistent gets pin

                                        1164  consistent gets pin (fastpath)

                                           4  cursor authentications

                                          23  enqueue releases

                                          23  enqueue requests

                                         501  execute count

                                      105853  file io wait time

                                         125  free buffer inspected

                                          79  free buffer requested

                                           4  hot buffers moved to head of LRU

                                         129  index fetch by key

                                         371  index scans kdiixs1

                                    15466496  logical read bytes from cache

                                        1152  no work - consistent read gets

                                         103  non-idle wait count

                                          11  non-idle wait time

                                         494  opened cursors cumulative

                                           1  opened cursors current

                                          23  parse count (hard)

                                          55  parse count (total)

                                          47  parse time cpu

                                          59  parse time elapsed

                                          75  physical read IO requests

                                      647168  physical read bytes

                                          75  physical read total IO requests

                                      647168  physical read total bytes

                                          79  physical reads

                                          79  physical reads cache

                                           4  physical reads cache prefetch

                                        1198  recursive calls

                                          40  recursive cpu usage

                                           3  rows fetched via callback

                                           1  session cursor cache count

                                         471  session cursor cache hits

                                        1888  session logical reads

                                           6  shared hash latch upgrades - no wait

                                         108  sorts (memory)

                                        1801  sorts (rows)

                                         443  table fetch by rowid

                                           5  table fetch continued row

                                         195  table scan blocks gotten

                                        8143  table scan disk non-IMC rows gotten

                                        8143  table scan rows gotten

                                          36  table scans (short tables)

                                          10  user I/O wait time

                                          29  user calls

                            • 11. Re: [Bug?] Autotrace without output
                              user8850362

                              Hi Jeff,

                               

                              you're right. Thats what i did and copied into my first post.

                               

                              I visited a tuning course via oracle university and they praised sql developer for tuning puposes. Especially the HotSpot feature i'd love to use.

                               

                              Regarding the workaround:

                              I didnt get it running as wanted. Switching off the row results doesnt work. I can switch on autotrace with

                               

                              set autotrace on

                               

                              but i cannot suppress returning rows with:

                               

                              set autotrace traceonly

                               

                              ....

                               

                              Regarding the main problem:

                               

                              Ha! Gotcha! It seems to be the cursor_sharing parameter:

                               

                              I did

                               

                              alter session set cursor_sharing='EXACT';

                               

                              and then its all working.

                               

                              Question: Is this a bug and can this be fixed? I'd love to betatest a new version.

                               

                              Regards.

                              • 12. Re: [Bug?] Autotrace without output
                                Vadim Tropashko-Oracle

                                Bugged as 22250314. Thank you for thorough troubleshooting!

                                1 person found this helpful
                                • 13. Re: [Bug?] Autotrace without output
                                  user8850362

                                  Hi Vadim,

                                   

                                  did you see the other maybe-bug?

                                   

                                  As a workaround one can set autotrace on in the worksheet. So we get the autotrace output as script output. So far, so good. But if i want to set autotrace traceonly, the output of queried rows should be supressed. But its not. Is this worth another bug?

                                   

                                  Regards.

                                  • 14. Re: [Bug?] Autotrace without output
                                    user8850362

                                    Hi there,

                                     

                                    regarding my last post:

                                    if i "set autotrace traceonly" i get a message in the script output now saying something similiar to: this trace option ist not supported right now. I missed this during my last tests (my fault, i guess). Will this option be supported someday?

                                    1 2 Previous Next