Issue2604

classification
Title: 2.7.1 is slower than 2.7.0 in some cases
Type: behaviour Severity: normal
Components: None Versions: Jython 2.7
Milestone:
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: amak, jamesmudd, rhwood, zyasoft
Priority: Keywords:

Created on 2017-07-04.13:38:15 by rhwood, last changed 2017-07-09.17:05:41 by jamesmudd.

Files
File name Uploaded Description Edit Remove
JythonIssue2604Test.java rhwood, 2017-07-04.14:18:31 Reproducible Test Case
Messages
msg11464 (view) Author: Randall Wood (rhwood) Date: 2017-07-04.13:38:14
I have a process that uses Jython to check that files are being checked into a SCM using the correct line ends (its a Java test that uses Jython, embedded using JSR 223, to run 29057 tests. Each test is the following Jython script (written on the fly in Java where PATH is the file to check and changes every time):

import os
failing = False
if "\r\n" in open(os.path.normpath(PATH), "rb").read():
    failing = True

This has the following runtimes (in seconds) on the same computer with no other changes than Jython version:

Jython 2.7.0: 89.442 (~1.5 minutes)
Jython 2.7.1: 10,788.489 (~3 hours or ~120 times as long as 2.7.0)

Am working on an isolated reproducible Java class; will attach when ready.
msg11465 (view) Author: Randall Wood (rhwood) Date: 2017-07-04.14:18:31
Reproducible Test Case. Run (on a POSIX system; I don't know the syntax for Windows) as:

javac -classpath hamcrest-core-1.3.jar:jython-standalone-2.7.1.jar:junit-4.12.jar:. JythonIssue2604Test.java
java -classpath hamcrest-core-1.3.jar:jython-standalone-2.7.1.jar:junit-4.12.jar:. JythonIssue2604Test

Requires:
JUnit 4.12 (http://repo1.maven.org/maven2/junit/junit/4.12/junit-4.12.jar)
Hamcrest Core 1.3 (http://repo1.maven.org/maven2/org/hamcrest/hamcrest-core/1.3/hamcrest-core-1.3.jar)

Jython Standalone. Run with version 2.7.0 and 2.7.1 to see the difference in behavior.
msg11467 (view) Author: James Mudd (jamesmudd) Date: 2017-07-05.18:20:50
I have tested this using the uploaded test case and can't see a large difference between 2.7.0 and 2.7.1. Here are my results:

james@james-desktop ~/Desktop/Jython-2604 $ java -classpath hamcrest-core-1.3.jar:jython-standalone-2.7.0.jar:junit-4.12.jar:. JythonIssue2604Test
JUnit version 4.12
.
Time: 1.059

OK (1 test)

james@james-desktop ~/Desktop/Jython-2604 $ java -classpath hamcrest-core-1.3.jar:jython-standalone-2.7.1.jar:junit-4.12.jar:. JythonIssue2604Test
JUnit version 4.12
.
Time: 1.055

OK (1 test)

Recompiled between the tests. I have run each lots of times and see variation around +-0.1 sec on both versions. Should I expect to see 2.7.1 being a lot slower?

Maybe you could provide some more details, what OS and what JVM?
msg11468 (view) Author: Randall Wood (rhwood) Date: 2017-07-05.23:16:40
With only one file tested, most of the time is the initialization of Jython, and any difference is hidden by that. With the 29057 iterations of that four line script in a single JVM, the effect is visible.

If you download the sources.jar for jython-standalone-2.7.1, unzip it, and run the test from the root of that unzipped JAR, that the results are:
Tests run: 3648,  Failures: 46
Time: 10.366 (Jython 2.7.0)
Time: 943.857 (Jython 2.7.1)

Sorry I wasn't clear on the need to run this against a large directory structure to see the effect.
msg11469 (view) Author: Randall Wood (rhwood) Date: 2017-07-06.10:03:33
I am seeing this on macOS 10.12.5 with java 1.8.0_102.

Travis CI (Ubuntu 12.04.5 LTS with java 1.8.0_121) and AppVeyor (Windows Server 2012 R2 with java 1.8.0_121) are both killing my CI builds in the original use case (29057 files) with Jython 2.7.1 because the builds are running over an hour.
msg11471 (view) Author: James Mudd (jamesmudd) Date: 2017-07-07.22:31:25
Ok I have definitely reproduced this and it is bad! On Linux Mint 18.1, openjdk version "1.8.0_131"

Slightly different file set but run over: Tests run: 4546,  Failures: 50
2.7.0 = 5.61 secs
2.7.1 = 688.406 secs

So in my test 2.7.1 is also ~120 times slower.

Haven't identified where the performance changed but will hopefully get time to have a look at that.
msg11472 (view) Author: James Mudd (jamesmudd) Date: 2017-07-09.17:05:40
After a little work with git bisect I know the cause of this problem, however I am unsure of the correct solution.

This problem was introduced in commit c7a3eba where a change is made to "Isolate each JSR ScriptEngine with separate PySystemState" to fix #2154.

Simply reverting this commit appears to resolve this problem and causes no problems in the regrtests, however I don't know if this is a good idea. I'm still not completely sure why this change results in such a large performance issue here.

I have a pull request (https://github.com/jythontools/jython/pull/82) to revert this commit for discussion,  would be good if Jim could have a look at this.
History
Date User Action Args
2017-07-09 17:05:41jamesmuddsetnosy: + zyasoft
messages: + msg11472
2017-07-07 22:31:25jamesmuddsetmessages: + msg11471
2017-07-06 10:03:34rhwoodsetmessages: + msg11469
2017-07-05 23:16:40rhwoodsetmessages: + msg11468
2017-07-05 18:20:51jamesmuddsetnosy: + jamesmudd
messages: + msg11467
2017-07-04 14:18:31rhwoodsetfiles: + JythonIssue2604Test.java
messages: + msg11465
2017-07-04 13:48:24amaksetnosy: + amak
2017-07-04 13:38:15rhwoodcreate