- 196.8K All Categories
- 2.2K Data
- 238 Big Data Appliance
- 1.9K Data Science
- 450.2K Databases
- 221.7K General Database Discussions
- 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
- 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?)
Recently I tried Adrian Billington's mystats.sql utility in SQLcl, in order to collect session's statistics.
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... 😕)