8333086: Using Console.println is unnecessarily slow due to JLine initalization #19479

lahodaj · 2024-05-30T13:50:33Z

Consider these two programs:

public class SystemPrint {
    public static void main(String... args) {
        System.err.println("Hello!");
    }
}

and:

public class IOPrint {
    public static void main(String... args) {
        java.io.IO.println("Hello!");
    }
}

They do the same conceptual thing - write a text to the output. But, IO.println delegates to Console.println, which then delegates to a Console backend, and the default backend is currently based on JLine.

The issues is that JLine takes a quite a long time to initialize, and in a program like this, JLine is not really needed - it is used to provide better editing experience when reading input, but there's no reading in these programs.

For example, on my computer:

$ time java -classpath /tmp SystemPrint 
Hello!

real    0m0,035s
user    0m0,019s
sys     0m0,019s

$ time java -classpath /tmp --enable-preview IOPrint 
Hello!

real    0m0,165s
user    0m0,324s
sys     0m0,042s

The proposal herein is to delegate to the simpler Console backend from java.base as long as the user only uses methods that print to output, and switch to the JLine delegate when other methods (typically input) is used. Note that while technically writer() is a method doing output, it will force JLine initialization to avoid possible problems if the client caches the writer and uses it after switching the delegates.

With this patch, I can get timing like this:

$ time java --enable-preview -classpath /tmp/ IOPrint 
Hello!

real    0m0,051s
user    0m0,038s
sys     0m0,020s

which seems much more acceptable.

There is also #19467, which may reduce the time further.

A future work might focus on making JLine initialize faster, but avoiding JLine initialization in case where we don't need it seems like a good step to me in any case.

Progress

Change must be properly reviewed (1 review required, with at least 1 Reviewer)
Change must not contain extraneous whitespace
Commit message must refer to an issue

Issue

JDK-8333086: Using Console.println is unnecessarily slow due to JLine initalization (Bug - P3)

Reviewers

Adam Sotona (@asotona - Reviewer) ⚠️ Review applies to 9886732e
Naoto Sato (@naotoj - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/19479/head:pull/19479
$ git checkout pull/19479

Update a local copy of the PR:
$ git checkout pull/19479
$ git pull https://git.openjdk.org/jdk.git pull/19479/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 19479

View PR using the GUI difftool:
$ git pr show -t 19479

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/19479.diff

Webrev

Link to Webrev Comment

… really necessary.

…hing to JLine.

bridgekeeper · 2024-05-30T13:51:08Z

👋 Welcome back jlahoda! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

openjdk · 2024-05-30T13:51:31Z

@lahodaj This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8333086: Using Console.println is unnecessarily slow due to JLine initalization

Reviewed-by: asotona, naoto

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 173 new commits pushed to the master branch:

9b3694c: 8319822: Use a linear-time algorithm for assert_different_registers()
f73922b: 8333235: vmTestbase/nsk/jdb/kill/kill001/kill001.java fails with C1
5dcb7a6: 8160755: bug6492108.java test fails with exception Image comparison failed at (0, 0) for image 4 in GTK L&F
438121b: 8332785: Replace naked uses of UseSharedSpaces with CDSConfig::is_using_archive
d7d1afb: 8206447: InflaterInputStream.skip receives long but it's limited to Integer.MAX_VALUE
7acfba2: 8327650: Test java/nio/channels/DatagramChannel/StressNativeSignal.java timed out
c5c0867: 8333252: C2: assert(assertion_predicate_has_loop_opaque_node(iff)) failed: must find OpaqueLoop* nodes
d85b0ca: 8332457: Examine startup overheads from JDK-8294961
326dbb1: 8312436: CompletableFuture never completes when 'Throwable.toString()' method throws Exception
9a8096f: 8330047: ASAN build error with gcc 13
... and 163 more: https://git.openjdk.org/jdk/compare/08d51003d142e89b9d2f66187a4ea50e12b94fbb...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

openjdk · 2024-05-30T13:52:13Z

@lahodaj The following labels will be automatically applied to this pull request:

core-libs
kulla

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing lists. If you would like to change these labels, use the /label pull request command.

mlbridge · 2024-05-30T13:55:13Z

Webrevs

asotona

It looks like a legit performance trick.

naotoj

Looks good with a minor nit.

naotoj · 2024-06-04T16:11:05Z

test/jdk/jdk/internal/jline/LazyJdkConsoleProvider.java

+        for (TestCase tc : testCases) {
+            ProcessBuilder builder =
+                    ProcessTools.createTestJavaProcessBuilder("--enable-preview",
+                                                              "-verbose:class",


Better to explicitly specify -Djdk.console=jdk.internal.le

… provider in the test.

naotoj

LGTM. Thanks for the changes.

lahodaj · 2024-06-05T17:19:55Z

/integrate

openjdk · 2024-06-05T17:20:45Z

Going to push as commit f7dbb98.
Since your change was applied there have been 173 commits pushed to the master branch:

9b3694c: 8319822: Use a linear-time algorithm for assert_different_registers()
f73922b: 8333235: vmTestbase/nsk/jdb/kill/kill001/kill001.java fails with C1
5dcb7a6: 8160755: bug6492108.java test fails with exception Image comparison failed at (0, 0) for image 4 in GTK L&F
438121b: 8332785: Replace naked uses of UseSharedSpaces with CDSConfig::is_using_archive
d7d1afb: 8206447: InflaterInputStream.skip receives long but it's limited to Integer.MAX_VALUE
7acfba2: 8327650: Test java/nio/channels/DatagramChannel/StressNativeSignal.java timed out
c5c0867: 8333252: C2: assert(assertion_predicate_has_loop_opaque_node(iff)) failed: must find OpaqueLoop* nodes
d85b0ca: 8332457: Examine startup overheads from JDK-8294961
326dbb1: 8312436: CompletableFuture never completes when 'Throwable.toString()' method throws Exception
9a8096f: 8330047: ASAN build error with gcc 13
... and 163 more: https://git.openjdk.org/jdk/compare/08d51003d142e89b9d2f66187a4ea50e12b94fbb...master

Your commit was automatically rebased without conflicts.

openjdk · 2024-06-05T17:20:51Z

@lahodaj Pushed as commit f7dbb98.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

lahodaj added 4 commits May 27, 2024 10:04

Attempting to speedup start by delaying initialization of JLine until…

Loading
Loading status checks…

77a6d56

… really necessary.

Force Terminal when writer is requested.

d94ed3d

Using println correctly, flushing the java.base delegate before switc…

50a7981

…hing to JLine.

Cleanup, addint test.

9886732

openjdk bot added the rfr label May 30, 2024

openjdk bot added core-libs kulla labels May 30, 2024

asotona approved these changes Jun 4, 2024

View reviewed changes

openjdk bot added the ready label Jun 4, 2024

naotoj reviewed Jun 4, 2024

View reviewed changes

lahodaj added 2 commits June 5, 2024 07:54

Reflecting review feedback - explicitly selecting the jdk.internal.le…

7a0c448

… provider in the test.

Correctly reflecting review feedback

f325979

naotoj approved these changes Jun 5, 2024

View reviewed changes

openjdk bot added the integrated label Jun 5, 2024

openjdk bot closed this Jun 5, 2024

openjdk bot removed ready rfr labels Jun 5, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

8333086: Using Console.println is unnecessarily slow due to JLine initalization #19479

8333086: Using Console.println is unnecessarily slow due to JLine initalization #19479

lahodaj commented May 30, 2024 •

edited by openjdk bot

Loading

bridgekeeper bot commented May 30, 2024

openjdk bot commented May 30, 2024 •

edited

Loading

openjdk bot commented May 30, 2024

mlbridge bot commented May 30, 2024 •

edited

Loading

asotona left a comment

naotoj left a comment

naotoj Jun 4, 2024

naotoj left a comment

lahodaj commented Jun 5, 2024

openjdk bot commented Jun 5, 2024

openjdk bot commented Jun 5, 2024

8333086: Using Console.println is unnecessarily slow due to JLine initalization #19479

8333086: Using Console.println is unnecessarily slow due to JLine initalization #19479

Conversation

lahodaj commented May 30, 2024 • edited by openjdk bot Loading

Progress

Issue

Reviewers

Reviewing

Webrev

bridgekeeper bot commented May 30, 2024

openjdk bot commented May 30, 2024 • edited Loading

openjdk bot commented May 30, 2024

mlbridge bot commented May 30, 2024 • edited Loading

Webrevs

asotona left a comment

Choose a reason for hiding this comment

naotoj left a comment

Choose a reason for hiding this comment

naotoj Jun 4, 2024

Choose a reason for hiding this comment

naotoj left a comment

Choose a reason for hiding this comment

lahodaj commented Jun 5, 2024

openjdk bot commented Jun 5, 2024

openjdk bot commented Jun 5, 2024

lahodaj commented May 30, 2024 •

edited by openjdk bot

Loading

openjdk bot commented May 30, 2024 •

edited

Loading

mlbridge bot commented May 30, 2024 •

edited

Loading