SET SERVEROUTPUT ON results in a database call for each and every command (bug?)

user9540031

Hi,

Recently I tried Adrian Billington's mystats.sql utility in SQLcl, in order to collect session's statistics.

(The web page for Adrian Billington's utilities for Oracle developers is here; the source code of the mystats.sql script is here.)

Actually, for reasons explained in this post, I used a slightly modified version of the original script, in order to specify explicit paths for spool files.

Given that the mystats.sql script is not only clever, but also very simple, I expected it to run within the blink of an eye, and I was very disappointed: using SQLcl, it took a noticeably long time to run the following:

SQL> @mystats start s=s,t

PL/SQL procedure successfully completed.

How long? More than 1 full second, perhaps 2 seconds... I didn't time it exactly, but it was long enough to warrant a quick performance investigation, all the more so as running the same in SQL*Plus did not take longer than the blink of an eye—so there was a huge feeling of a performance difference here.

Using the JDBC Profiler in VisualVM, the culprit was found out quickly, as you may see in the following screenshot:

The JDBC Profiler lists statements in decreasing order of total (elapsed) time. The first statement in the list is the one in which the most time was spent. On the above screenshot you may see that this statement was executed 106 times, for a total of 153 ms.

(Remark: please do not pay attention to the timings in the above screenshot: it was taken on a test computer with the database running in a local virtual machine, so here the client-server latency is very quick, in the 1 ms ballpark... But picture yourself in a different, real-world customer site, with a remote database and a client-server latency closer to 10 ms, and then the above 153 ms expand to no fewer than 1.5 second... and that feels slow.)

The SQL id for this statement (which you may find by tracing the session) is 5yaurap8h97nx, and it reads as follows:

declare
    l_line varchar2(32767);
    l_done number;
    l_buffer varchar2(32767) := '';
    l_lengthbuffer number := 0;
    l_lengthline number := 0;
begin
  loop
    dbms_output.get_line( l_line, l_done );
    if (l_buffer is null) then
      l_lengthbuffer := 0;
    else
      l_lengthbuffer := length(l_buffer);
    end if;
    if (l_line is null) then
      l_lengthline := 0;
    else
      l_lengthline := length(l_line);
    end if;
  exit when l_lengthbuffer + l_lengthline > :maxbytes OR l_lengthbuffer + l_lengthline > 32767 OR l_done = 1;
  l_buffer := l_buffer || l_line || chr(10);
    end loop;
    :done := l_done;
    :buffer := l_buffer;
    :line := l_line;
end;

Yes, that's the PL/SQL block used by SQLcl / SQL Developer to fetch lines from DBMS_OUTPUT's internal buffer once SERVEROUTPUT has been switched to ON.

(In the session trace file, it appeared that the value of the :maxbytes input bind variable was equal to 1000.)

But wait! There's exactly 1 and only 1 PL/SQL block in the mystats.sql script. (And SQLcl wraps it into what appears as the 2nd statement in the JDBC profile; that block was executed only once, with an elapsed time of 60.3 ms above). And further, there was no output line to be fetched at all: as shown above, @mystats start does not output anything (the readout comes with @mystats stop). So why had SQLcl executed the output-fetching statement (SQL id: 5yaurap8h97nx) 106 times?

The JDBC Profiler includes the call stacks for each JDBC statement call; this enables to figure out where in the client application JDBC calls are originating from. The following screenshot shows the call stacks in their full glory—just to briefly lift the veil and see how complex the implementation may be...

Humm... Let's try something simpler here.

E:\Home\user9540031\Temp> sqlcl /nolog

SQLcl: Release 22.1 Production on Sun Jun 12 16:39:00 2022
Copyright (c) 1982, 2022, Oracle.  All rights reserved.

SQL> connect [email protected]_rva
Password? (**********?) *****
Connected.

Now restart the JDBC Profiler.

(Remark: SQLcl's JVM barks about illegal reflective accesses:

SQL> Profiler Agent: JNI OnLoad Initializing...
Profiler Agent: JNI OnLoad Initialized successfully
Profiler Agent: Waiting for connection on port 5140 (Protocol version: 20)
Profiler Agent: Established connection with the tool
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.graalvm.visualvm.lib.jfluid.server.ClassLoaderManager to method java.lang.ClassLoader.findLoadedClass(java.lang.String)
WARNING: Please consider reporting this to the maintainers of org.graalvm.visualvm.lib.jfluid.server.ClassLoaderManager
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
Profiler Agent: Local accelerated session
*** Profiler engine warning: class jdk.internal.reflect.GeneratedMethodAccessor39 loaded by *** Profiler Agent Communication Thread

Meanwhile, profiling seems to work, so let's carry on with our tests.)

SQL> set serveroutput on

Now the JDBC profile reads as follows:

As you can see, the output-fetching statement (SQL id: 5yaurap8h97nx) has been called exactly once so far.

So let's type in a SQL*Plus command; note that this is a client-side only command, one which doesn't require any database call at all, in principle.

SQL> prompt test
test

Meanwhile... Surprise! SQLcl did make a database call:

Let's carry on:

SQL> define def_sub = ""

SQL> column c1 format a10

SQL> set verify off

Do you see a pattern here?

SQL> undefine def_sub
SQL> column c1 clear
SQL> spool temp.out
SQL> spool off

All the above commands are client-side only commands: they do not make, nor require, any call to the database, so it seems obvious that they should not cause any change to the contents of the DBMS_OUTPUT buffer. So why is SQLcl trying to fetch more output lines?

So there you have it: when SERVEROUTPUT is ON, SQLcl makes a database call to get new lines from the DBMS_OUTPUT buffer after each and every command, even commands which do not make any call to the database.

And if running elaborate SQL*Plus scripts, such as Adrian Billington's mystats.sql utility (which is far from sophisticated by the way, but uses many SQL*Plus client-side commands such as COLUMN, DEFINE, UNDEFINE, etc.) and the database client-server latency is high, say 10 ms or more, this behaviour results in scripts being noticeably slower in SQLcl than they are in SQL*Plus, due to the many additional client-server round-trips.

Workaround: issue the SET SERVEROUTPUT ON command just before running the output-generating PL/SQL block(s), and call SET SERVEROUTPUT OFF as soon as possible afterwards.

(This is the opposite of the common usage, which consists of placing the SET SERVEROUTPUT ON command at the very beginning of any script using DBMS_OUTPUT... 😕)

user9540031

[Continued: obviously, performance issues with the Forum software have been getting fixed—thanks!—meanwhile, when writing complex posts with code/screenshots, there may still come a point when scripts begin to run slow in the navigator, be it Firefox or Chrome, and at that point it may be simpler/safer to split the discussion.]

SQL Developer's behaviour, as regards fetching lines from the DBMS_OUTPUT buffer, is exactly the same as that of SQLcl.

Further, SQL Developer has been behaving that way for quite a long time now. I tested several past releases, and it seems that this behaviour was introduced some time between SQL Developer 17.4.1, which does not seem to make extra calls to get new output lines (SQL id: 5yaurap8h97nx), and SQL Developer 18.3.0, which does.

So, it is a bug? A feature? An implementation simplification?

And, does it matter? After all, this has been going on for almost 4 years, and I had not noticed it. Did anyone complain?

For the most part, as far as I'm concerned I'd say that the degree of compatibility of SQLcl / SQL Developer with SQL*Plus scripts is excellent: there are a couple of quirks, and residual unsupported commands, but overall the SQL Developer Dev team has done a fine job of making it possible to run vast amounts of SQL*Plus scripts in SQLcl / SQL Developer with little or no change at all.

That said, I fail to see why SQLcl / SQL Developer could not be aware of when fetching new lines from the DBMS_OUTPUT buffer would be necessary, and when not.

And I have different response-time expectations when running a relatively simple script in SQLcl than I have when occasionally running the same script in SQL Developer: SQLcl being a text-mode/console tool, as opposed to a GUI tool as SQL Developer, I'd expect it to be lightweight, hence quicker. In any case, I would not expect it to be much slower than SQL*Plus, at least not to such a noticeable extent—1.5 second compared to less than 0.1 second. Especially knowing that SQLcl is advertised as an alternative to SQL*Plus for most DBA tasks: if it's supposed to be SQL*Plus++, then it should not run SQL*Plus scripts much slower than SQL*Plus for no good reason.

But that's just me...

Regards,