Benchmarking DBMS_OUTPUT.GET_LINE[S] from JDBC

Oracle.java

import java.sql.Array;
import java.sql.CallableStatement;
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.Statement;
import java.sql.Types;
import java.util.Properties;
import java.util.stream.LongStream;
import java.util.stream.Stream;

public class Oracle {

    static String lastMessage;

    public static void main(String[] args) {
        try {
            Class.forName("oracle.jdbc.OracleDriver");

            String url = "jdbc:oracle:thin:@192.168.99.100:1521:ORCLCDB";
            String user = "TEST";
            String password = "TEST";

            Properties properties = new Properties();
            properties.setProperty("user", user);
            properties.setProperty("password", password);

            int max = 50;
            long[] getLines1 = new long[max];
            long[] getLines10 = new long[max];
            long[] getLines1000 = new long[max];
            long[] getLineReusePS = new long[max];
            long[] getLineCreatePS = new long[max];

            try (Connection c = DriverManager.getConnection(url, properties);
                Statement s = c.createStatement()) {

                for (int warmup = 0; warmup < 2; warmup++) {
                    for (int i = 0; i < max; i++) {
                        s.executeUpdate("begin dbms_output.enable(); end;");
                        String sql = "begin for i in 1 .. 100 loop dbms_output.put_line('Message ' || i); end loop; end;";
                        long t1 = System.nanoTime();
                        logGetLines(c, 100, 1, () -> s.executeUpdate(sql));
                        long t2 = System.nanoTime();
                        logGetLines(c, 100, 10, () -> s.executeUpdate(sql));
                        long t3 = System.nanoTime();
                        logGetLines(c, 100, 1000, () -> s.executeUpdate(sql));
                        long t4 = System.nanoTime();
                        logGetLineReusePS(c, 100, () -> s.executeUpdate(sql));
                        long t5 = System.nanoTime();
                        logGetLineCreatePS(c, 100, () -> s.executeUpdate(sql));
                        long t6 = System.nanoTime();
                        s.executeUpdate("begin dbms_output.disable(); end;");

                        if (warmup > 0) {
                            getLines1[i] = t2 - t1;
                            getLines10[i] = t3 - t2;
                            getLines1000[i] = t4 - t3;
                            getLineReusePS[i] = t5 - t4;
                            getLineCreatePS[i] = t6 - t5;
                        }
                    }
                }
            }

            // LongSummaryStatistics{count=50, sum=67475229, min=1040214, average=1349504.580000, max=2499841}
            // LongSummaryStatistics{count=50, sum=73946058, min=1162667, average=1478921.160000, max=2532694}
            // LongSummaryStatistics{count=50, sum=74989687, min=1195948, average=1499793.740000, max=2517335}
            // LongSummaryStatistics{count=50, sum=1491740368, min=27195319, average=29834807.360000, max=41893138}
            // LongSummaryStatistics{count=50, sum=2060018373, min=35052388, average=41200367.460000, max=73077792}

            System.out.println(LongStream.of(getLines1).summaryStatistics());
            System.out.println(LongStream.of(getLines10).summaryStatistics());
            System.out.println(LongStream.of(getLines1000).summaryStatistics());
            System.out.println(LongStream.of(getLineReusePS).summaryStatistics());
            System.out.println(LongStream.of(getLineCreatePS).summaryStatistics());
        } catch (Exception e) {
            e.printStackTrace();
        }
    }

    interface WhyUNoCheckedExceptionRunnable {
        void run() throws Exception;
    }

    static void logGetLines(Connection connection, int size, int fetchSize, WhyUNoCheckedExceptionRunnable runnable) throws Exception {
        try (Statement s = connection.createStatement()) {
            runnable.run();

            try (CallableStatement call = connection.prepareCall(
                "declare "
              + "  num integer := ?;"
              + "begin "
              + "  dbms_output.get_lines(?, num);"
              + "end;"
            )) {
                call.setFetchSize(fetchSize);
                call.setInt(1, size);
                call.registerOutParameter(2, Types.ARRAY, "DBMSOUTPUT_LINESARRAY");
                call.execute();

                Array array = null;
                try {
                    array = call.getArray(2);
                    Stream.of((Object[]) array.getArray())
                          .forEach(m -> { lastMessage = (String) m; });
                }
                finally {
                    if (array != null)
                        array.free();
                }
            }
        }
    }

    static void logGetLineReusePS(Connection connection, int size, WhyUNoCheckedExceptionRunnable runnable) throws Exception {
        try (Statement s = connection.createStatement()) {
            runnable.run();

            try (CallableStatement call = connection.prepareCall(
                "begin "
              + "  dbms_output.get_line(?, ?);"
              + "end;"
            )) {
                call.registerOutParameter(1, Types.VARCHAR);
                call.registerOutParameter(2, Types.INTEGER);

                for (int i = 0; i < size; i++) {
                    call.execute();
                    lastMessage = call.getString(1);
                }
            }
        }
    }

    static void logGetLineCreatePS(Connection connection, int size, WhyUNoCheckedExceptionRunnable runnable) throws Exception {
        try (Statement s = connection.createStatement()) {
            runnable.run();

            for (int i = 0; i < size; i++) {
                try (CallableStatement call = connection.prepareCall(
                    "begin "
                  + "  dbms_output.get_line(?, ?);"
                  + "end;"
                )) {
                    call.registerOutParameter(1, Types.VARCHAR);
                    call.registerOutParameter(2, Types.INTEGER);
                    call.execute();
                    lastMessage = call.getString(1);
                }
            }
        }
    }
}

@lukaseder, why do you call prepareCall in a loop inside logGetLine? Why don't you just prepare the call once and execute in a loop?

@vlsi: Sorry, didn't get the notification. Good point, worth exploring. The main reason is because this is what's being done by most clients. I'll re-run the example with your suggestion

@vlsi: OK, updated the code and ran the benchmark again. Indeed, there's another significant drawback when re-creating the CallableStatement for every call, but not significant enough:

LongSummaryStatistics{count=50, sum=  74989687, min= 1195948, average= 1499793.740000, max= 2517335}
LongSummaryStatistics{count=50, sum=1491740368, min=27195319, average=29834807.360000, max=41893138}
LongSummaryStatistics{count=50, sum=2060018373, min=35052388, average=41200367.460000, max=73077792}

1. Moves the loop to PL/SQL
2. Creates a single statement and loops the executions in the client
3. Creates a statement per execution