Discussions
Categories
- 196.8K All Categories
- 2.2K Data
- 238 Big Data Appliance
- 1.9K Data Science
- 450.2K Databases
- 221.7K General Database Discussions
- 3.8K Java and JavaScript in the Database
- 31 Multilingual Engine
- 550 MySQL Community Space
- 478 NoSQL Database
- 7.9K Oracle Database Express Edition (XE)
- 3K ORDS, SODA & JSON in the Database
- 544 SQLcl
- 4K SQL Developer Data Modeler
- 187K SQL & PL/SQL
- 21.3K SQL Developer
- 295.8K Development
- 17 Developer Projects
- 138 Programming Languages
- 292.5K Development Tools
- 107 DevOps
- 3.1K QA/Testing
- 646K Java
- 28 Java Learning Subscription
- 37K Database Connectivity
- 154 Java Community Process
- 105 Java 25
- 22.1K Java APIs
- 138.1K Java Development Tools
- 165.3K Java EE (Java Enterprise Edition)
- 18 Java Essentials
- 160 Java 8 Questions
- 86K Java Programming
- 80 Java Puzzle Ball
- 65.1K New To Java
- 1.7K Training / Learning / Certification
- 13.8K Java HotSpot Virtual Machine
- 94.3K Java SE
- 13.8K Java Security
- 204 Java User Groups
- 24 JavaScript - Nashorn
- Programs
- 437 LiveLabs
- 38 Workshops
- 10.2K Software
- 6.7K Berkeley DB Family
- 3.5K JHeadstart
- 5.7K Other Languages
- 2.3K Chinese
- 171 Deutsche Oracle Community
- 1.1K Español
- 1.9K Japanese
- 232 Portuguese
SET SERVEROUTPUT ON results in a database call for each and every command (bug?)

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... 😕)
Answers
-
[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,