1 2 Previous Next 28 Replies Latest reply: Feb 4, 2011 1:28 PM by Billy~Verreynne RSS

    SET SERVEROUTPUT strange behaviour

    824574
      Hello.

      Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bi
      PL/SQL Release 10.2.0.4.0 - Production

      We have a pl/sql block, which does the following:

      - sets serveroutput on
      - loop through a cursor
      - perform an update
      - output updated rows count
      - commit

      Everything works but the dbms_output commands.

      The strange thing is, running the script TWICE in the same session produces the output! It's as if SERVEROUTPUT isn't being set until the second run. We've commented out the update statement - and then dbms_output works!

      Here's the code:

      SET SERVEROUTPUT ON
      DECLARE
      v_upd_date DATE := SYSDATE;
      v_upd_count NUMBER := 0;
      BEGIN
      dbms_output.put_line('ABC');
      FOR c IN (SELECT
      ENTITY_CODE
      ,ENTITY_TYPE
      ,REGION
      ,TRADE_ETD_FLAG
      ,FX_ETD_FLAG
      ,FX_ETC_FLAG
      ,TAP_FLAG
      ,CLS_FLAG
      FROM PORG_ATT_STG
      where entity_code = 'AU00002')
      LOOP
      dbms_output.put_line('c.entity_code ' || c.entity_code);
      v_upd_count := v_upd_count + 1;
      UPDATE entity_extension
      SET
      user_ind62 = 'Y'
      ,user_ind63 = 'Y'
      ,user_ind65 = 'Y'
      ,user_ind66 = 'Y'
      ,user_ind68 = 'Y'
      WHERE trim(entity_id) = (SELECT distinct trim(e.Entity_id)
      FROM rulesdbo.entity_extension ee
      ,rulesdbo.entity e
      WHERE e.Entity_Id = ee.Entity_Id
      AND e.Entity_Type = c.Entity_Type
      AND trim(e.Entity_Code) = trim(c.Entity_Code));
      END LOOP;
      dbms_output.put_line(v_upd_count);
      COMMIT;
      END;
      /

      Any suggestions gratefully receieved; we've been going bonkers on this one.

      Thanks
        • 1. Re: SET SERVEROUTPUT strange behaviour
          Solomon Yakobson
          DBMS_OUTPUT.PUT_LINE does not display anything on client screen. All it does is writing data to on internal buffer. Then client, when it regains control can do with the buffer whatever it needs. So when you issue SET SERVEROUTPUT ON, SQL*Plus knows you are asking to print DBMS_OUTPUT buffer on screen. But again it can only happen when SQL*Plus regains control. In your case, PL/SQL block starts executing and updates one row at a time and also adds one line at a time output data to DBMS_OUTPUT buffer. Nothing is displayed at this time since control is still in PL/SQL. After ALL rows are updated in a loop PL/SQL block completes control is returned back to SQL*Plus and ONLY THEN SQL*Plus displayes all that info DBMS_OUTPUT.PUT_LINE added to buffer.

          SY.
          • 2. Re: SET SERVEROUTPUT strange behaviour
            736193
            Just to add to Solomon's reply.

            And sqlplus is using dbms_output.get_line(s) calls to retrieve the buffer contents, and then print it on the screen.
            • 3. Re: SET SERVEROUTPUT strange behaviour
              Billy~Verreynne
              DBMS_OUTPUT is a PL/SQL package with a collection variable. When you call PUT_LINE() or similar, it appends that data to this collection variable. It also has calls to enable this behaviour, and calls to read and clear the contents of this variable.

              When using set serveroutput on in SQL*Plus, it makes a PL/SQL call to DBMS_OUTPUT to enable it. After SQL*Plus has made a server call to Oracle, it calls DBMS_OUTPUT to read (and clear) the contents of the DBMS_OUTPUT buffer variable and display it locally.

              So it depends on how SQL*Plus behaves after a call is made - does it make the PL/SQL call to DBMS_OUTPUT to read its buffer content and display that? In some cases not - which means as the DBMS_OUTPUT buffer has not been clear, any new calls will append to that buffer. And when SQL*Plus gets around to eventually interrogating the DBMS_OUTPUT buffer and displaying its contents, that buffer will contain "old" lines written to it. And these will be displayed by SQL*Plus too.

              There are alternatives to using SQL*Plus's (poorly designed) serveroutput interface to DBMS_OUTPUT. For example, you can control it as follows:
              SQL> //-- create a collection type we can use in SQL select for returning buffer contents
              SQL> create or replace type TStrings is table of varchar2(4000);
                2  /
              
              Type created.
              
              SQL> --// use a pipeline to read the DBMS_OUTPUT buffer and return it
              SQL> create or replace function DisplayDbmsOutputBuffer return TStrings pipelined is
                2          line    varchar2(32767);
                3          status  integer;
                4  begin
                5          loop
                6                  DBMS_OUTPUT.get_line( line, status );
                7                  exit when status = 1;
                8  
                9                  --// we can only display 4000 byte strings in SQL, so
               10                  --// change this to break bigger buffer lines up into
               11                  --// multiple 4000 byte lines
               12                  pipe row( substr(line,1,4000 ) );
               13  
               14          end loop;
               15  
               16          return;
               17  end;
               18  /
              
              Function created.
              
              SQL> --// normal use of DBMS_OUTPUT in SQL*Plus  - 
              SQL> set serveroutput on
              SQL> 
              SQL> exec DBMS_OUTPUT.put_line( 'hello world' );
              hello world
              
              PL/SQL procedure successfully completed.
              
              SQL> --// we now disable SQL*Plus from calling DBMS_OUTPUT 
              SQL> set serveroutput off
              SQL> 
              SQL> --// turn on DBMS_OUTPUT without telling SQL*Plus
              SQL> exec DBMS_OUTPUT.Enable;
              
              PL/SQL procedure successfully completed.
              
              SQL> 
              SQL> --// we make calls to code that writes to DBMS_OUTPUT
              SQL> exec DBMS_OUTPUT.put_line( 'hello world' ); DBMS_OUTPUT.put_line( 'What do you want universe?' )
              
              PL/SQL procedure successfully completed.
              
              SQL> --// after such a call, we use our pipeline to  read and clear the buffer contents
              SQL> select column_value as LINE from TABLE( DisplayDbmsOutputBuffer );
              
              LINE
              --------------------------------------------------
              hello world
              What do you want universe?
              
              SQL> 
              • 4. Re: SET SERVEROUTPUT strange behaviour
                824574
                Many thanks all of you who've taken the time to reply.

                Unfortunately, we're no closer to answering our question; after running the script once, we get no output apart from the standard "PL/SQL procedure successfully completed" message.

                Running it a second time gives us the expected dbms_output.

                Can anyone explain why we have to run the script twice to get some output, and how we'd get around this (without having to write functions/procedures etc.) ?

                @ Billy - "So it depends on how SQL*Plus behaves after a call is made - does it make the PL/SQL call to DBMS_OUTPUT to read its buffer content and display that? In some cases not - "

                You're saying that the behaviour of DBMS_OUTPUT is not something we can control?

                Thanks
                • 5. Re: SET SERVEROUTPUT strange behaviour
                  riedelme
                  running the script TWICE in the same session produces the output!
                  You run it once no output; run it twice and you get output - once. Commenting the update allows DBMS_OUTPUT.PUT_LINE to work as expected (???) - very odd.

                  Weirdness can occur when using dbms_output in inline functions (called through SQL) but you don't seem to be using inline functions.

                  Are you sure that you are using SET SERVEROUTPUT ON before calling the routine the first time? Its possible (though unlikely) your turn-on is after the initial run.

                  Are there any internal calls to DBMS_OUTPUT routines in the set of processes you are running that might be causing wierd results, like Billy suggested?
                  • 6. Re: SET SERVEROUTPUT strange behaviour
                    824574
                    Hello - we'd already thought of that, so tried this adding "SHOW SERVEROUTPUT" before and after the call to SET SERVEROUTPUT at the top of the script:

                    SHOW SERVEROUTPUT
                    SET SERVEROUTPUT ON
                    SHOW SERVEROUTPUT

                    DECLARE
                    v_upd_date DATE := SYSDATE;
                    v_upd_count NUMBER := 0;
                    BEGIN
                    dbms_output.put_line('ABC');
                    FOR c IN (SELECT
                    ENTITY_CODE
                    ,ENTITY_TYPE
                    ,REGION
                    ,TRADE_ETD_FLAG
                    ,FX_ETD_FLAG
                    ,FX_ETC_FLAG
                    ,TAP_FLAG
                    ,CLS_FLAG
                    FROM PORG_ATT_STG
                    where entity_code = 'AU00002')
                    LOOP
                    dbms_output.put_line('c.entity_code ' || c.entity_code);
                    v_upd_count := v_upd_count + 1;
                    UPDATE entity_extension
                    SET
                    user_ind62 = 'Y'
                    ,user_ind63 = 'Y'
                    ,user_ind65 = 'Y'
                    ,user_ind66 = 'Y'
                    ,user_ind68 = 'Y'
                    WHERE trim(entity_id) = (SELECT distinct trim(e.Entity_id)
                    FROM entity_extension ee
                    ,entity e
                    WHERE e.Entity_Id = ee.Entity_Id
                    AND e.Entity_Type = c.Entity_Type
                    AND trim(e.Entity_Code) = trim(c.Entity_Code));
                    END LOOP;
                    dbms_output.put_line(v_upd_count);
                    COMMIT;
                    END;
                    /

                    SHOW SERVEROUTPUT

                    And here's the output from 2 runs, in the same session:

                    SQL> @upd_porg_att.sql
                    serveroutput OFF
                    serveroutput ON SIZE UNLIMITED FORMAT WORD_WRAPPED

                    PL/SQL procedure successfully completed.

                    serveroutput ON SIZE UNLIMITED FORMAT WORD_WRAPPED
                    SQL> @upd_porg_att.sql
                    serveroutput ON SIZE UNLIMITED FORMAT WORD_WRAPPED
                    serveroutput ON SIZE UNLIMITED FORMAT WORD_WRAPPED
                    ABC
                    c.entity_code AU00002
                    *1*

                    PL/SQL procedure successfully completed.

                    serveroutput ON SIZE UNLIMITED FORMAT WORD_WRAPPED

                    You can see Run1 shows no output, but Run2 does. There are no internal dbms_output.put_line calls that we are aware of, it's just a loop and an update statement.

                    Is it possible that one of the SQL*Plus environment settings is overriding SERVEROUTPUT?

                    Thanks
                    • 7. Re: SET SERVEROUTPUT strange behaviour
                      BluShadow
                      From an oldish O'Reilly book:

                      >
                      #

                      If your program raises an unhandled exception, you may not see any executed output from PUT_LINE, even if you enabled the package for output .

                      This can happen because the DBMS_OUTPUT buffer will not be flushed until it is full or until the current PL/SQL block completes its execution. If a raised exception never gets handled, the buffer will not be flushed. As a result, calls to the DBMS_OUTPUT.PUT_LINE module might never show their data. So if you are working with DBMS_OUTPUT.PUT_LINE and are frustrated because you are not seeing the output you would expect, make sure that you have:

                      1.

                      Enabled output from the package by calling SET SERVEROUTPUT ON in SQL*Plus.
                      2.

                      Placed an exception section with a WHEN OTHERS handler in the outer block of your code (usually some sort of test script) so that your output can be flushed to your terminal by SQL*Plus.
                      >

                      Is that possibly happening in your code?
                      • 8. Re: SET SERVEROUTPUT strange behaviour
                        riedelme
                        More unlikely ideas (wierd problems sometimes have wierd solutions)

                        I like Blu's exception idea, but you didin't report any exceptions, and why does the second run finish? Check the update value after the first run to see if an update has taken place (assuming the value has changed after multiple runs). Or make sure the run finishes using one of the DBMS_APPLICATION_INFO routines to set a v$SESSION row which shouldn't impact your process. A WHEN OTHERS exception handler as Blu suggested can't hurt.

                        I have seen occasional weirdness with SIZE UNLIMITED on 10g. What happens if you take away the extra options (maybe use SIZE to prevent filling the buffer)?

                        Do you have a My Oracle Support account? You could check for bugs (unlikely, but possible)

                        Could there be a forgotten trigger or other behind-the-scenes process that affects your setting the first time (unlikely)?
                        • 9. Re: SET SERVEROUTPUT strange behaviour
                          824574
                          We'd tried adding some exception handling iin the inner and outer branches of the code - no exceptions were raised and the update ALWAYS works.

                          There is a trigger on the table we're updating...just to be safe we disabled it and re-ran the script - with the same result (1st run no output, 2nd run ok).

                          It's really a standalone script with no other background processes/dependencies. So we can't see why this could be happening.
                          • 10. Re: SET SERVEROUTPUT strange behaviour
                            BluShadow
                            What version of SQL*Plus are you running?
                            • 11. Re: SET SERVEROUTPUT strange behaviour
                              824574
                              Hello - we're on:

                              SQL*Plus: Release 10.2.0.4.0 - Production on Thu Feb 3 14:45:04 2011
                              • 12. Re: SET SERVEROUTPUT strange behaviour
                                smon
                                if you replace your current plsql block with a simple one like below, I assume it works/outputs first time?? If so, it might point to the Update somehow being the cause of the weirdness?
                                begin
                                dbms_output.put_line(sysdate);
                                end;
                                /
                                • 13. Re: SET SERVEROUTPUT strange behaviour
                                  824574
                                  That works fine (after setting SERVEROUTPUT to ON). We've already tried a few other things in the script in place of the looped update you see (insert/updates to other tables) and they work fine.

                                  It had occurred to us too that the SQL itself was the culprit (though it seems strange that an UPDATE statement, which works, would somehow suppress dbms_ouptut).
                                  • 14. Re: SET SERVEROUTPUT strange behaviour
                                    smon
                                    And the other Inserts/Updates output first time? How bizarre. I can't recreate it, stumped! :)
                                    1 2 Previous Next