Issue2399

classification
Title: regrtest failures related to sort() on Java 8
Type: behaviour Severity: normal
Components: Core Versions: Jython 2.7
Milestone: Jython 2.7.2
process
Status: closed Resolution: accepted
Dependencies: Superseder:
Assigned To: Nosy List: jamesmudd, jeff.allen, stefan.richthofer, zyasoft
Priority: normal Keywords: test failure causes

Created on 2015-09-14.21:27:38 by jeff.allen, last changed 2017-03-23.09:11:31 by jamesmudd.

Files
File name Uploaded Description Edit Remove
test_sort_example_failure.py jamesmudd, 2017-03-18.15:15:25 A reproducible failure of the type seem in test_sort
sort_benchmark.py jamesmudd, 2017-03-22.21:11:08
TestSort.java jamesmudd, 2017-03-23.09:11:30
Messages
msg10261 (view) Author: Jeff Allen (jeff.allen) Date: 2015-09-14.21:27:37
Running the regression tests on Java 8 produces a couple of failures related to sort(). This was observed in:

Jython 2.7.1 (default:7ebdc6c80d55, Sep 11 2015, 01:50:57)
[Java HotSpot(TM) 64-Bit Server VM (Oracle Corporation)] on java1.8.0_45

test_sort produces quite a lengthy complaint that isn't actually failure (but I'm not sure how to interpret it):

error in exception during sort left some permutation
out of order at index 417 Complains(417) Complains(416)
...
followed by several hundred lines of output.

The specific failure in test_list_jy is:

======================================================================
ERROR: test_sort (__main__.JavaListTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\jython\2.7.1b1\Lib\test\list_tests.py", line 442, in test_sort
    self._test_sort()
  File "C:\jython\2.7.1b1\Lib\test\list_tests.py", line 446, in _test_sort
    u.sort()
TypeError: sort(): expected 1 args; got 0

----------------------------------------------------------------------
Which is odd.
msg10272 (view) Author: Jim Baker (zyasoft) Date: 2015-09-22.17:40:53
Java 8 added a sort method to java.util.List (https://docs.oracle.com/javase/8/docs/api/java/util/List.html#sort-java.util.Comparator-), which takes one arg. Meanwhile JavaProxyList defines list_sort, which takes the standard Python args for sorting a list.

I'm surprised that our version does not override. Perhaps related to http://bugs.jython.org/issue2391?

Easy to reproduce on Jython running on Java 8:

$ dist/bin/jython
Jython 2.7.1 (default:7ebdc6c80d55+, Sep 21 2015, 18:28:51)
[Java HotSpot(TM) 64-Bit Server VM (Oracle Corporation)] on java1.8.0_45
Type "help", "copyright", "credits" or "license" for more information.
>>> from java.util import ArrayList
>>> x = ArrayList([1, 0])
>>> x.sort()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
TypeError: sort(): expected 1 args; got 0
msg11098 (view) Author: Stefan Richthofer (stefan.richthofer) Date: 2017-02-15.20:31:50
I guess I already created and fixed kind of a duplicate of this one (regarding test_list_jy) in #2550 (sorry for overlooking this issue).
Could you check if that solved all Java8 regressions you observed? I think test_sort still has issues though, so leaving this one open for now.
msg11099 (view) Author: Jeff Allen (jeff.allen) Date: 2017-02-16.22:40:07
I thought #2550 sounded familiar :)

test_list_jy is clean now (one skip), but test_sort still creates output like:

     [exec] test_sort
     [exec] test test_sort produced unexpected output:
     [exec] **********************************************************************
     [exec] error in exception during sort left some permutation
     [exec] out of order at index 5 Complains(5) Complains(4)
     [exec] [Complains(0), Complains(1), Complains(2), Complains(3), Complains(4), Complains(5), Complains(6), Complains(7), Complains(8), Complains(9), Complains(10), Complains(11), Complains(12), Complains(13), Complains(14), Complains(15), Complains(16), Complains(17), Complains(18), Complains(19), Complains(20), Complains(21), Complains(22), Complains(23), Complains(24), Complains(25), Complains(26), Complains(27), Complains(28), ...
...
     [exec] error in exception during sort left some permutation
     [exec] out of order at index 3 Complains(3) Complains(4)
     [exec] [Complains(0), Complains(1), Complains(2), Complains(3), Complains(4), Complains(5), Complains(6), Complains(7), Complains(8), Complains(9), Complains(10), Complains(11), Complains(12), Complains(13), Complains(14), Complains(15), Complains(16), Complains(17), Complains(18), ...
msg11241 (view) Author: James Mudd (jamesmudd) Date: 2017-03-18.15:15:25
I have been looking at the test_sort failure and now have managed to create a simple (ish) way of reproducing the failure test_sort is having. After spending quite a while debugging it one issue is that the test makes lots of use of randomness to shuffle up list and to make exceptions occur randomly, this isn't very helpful when trying to understand the issue.

So I have made a script which reproduces one of these failures reliably which is attached. Its based on an observed failure while running the real test.

Essentially the problem is after calling sort() the returned list now contains duplicated elements and other elements have been removed, this does seem like quite a bad issue and I still don't think I understand why this is happening, but though a way to reproduce it might be helpful for others to investigate.

I made the script also run in cpython however the order of the comparisons there is different so it never actually triggers the RuntimeError, but it does work as expected.

Not sure if this issue should be blocking for 2.7.1 it does seem bad?
msg11242 (view) Author: James Mudd (jamesmudd) Date: 2017-03-18.16:59:31
Having said that it seems to only occur if the comparator raises an exception and I think that should be rare?
msg11243 (view) Author: Jeff Allen (jeff.allen) Date: 2017-03-18.18:30:51
That's a helpful script. It seems clear that the essence of the test is the expected behaviour when some comparison raises an exception. I've been looking around the web for the expected behaviour since you posted it, and haven't found the answer.

It appears we should expect not to lose any items, but not to have it in any particular order. Java 8 drops and duplicates elements?
msg11244 (view) Author: Jeff Allen (jeff.allen) Date: 2017-03-19.10:49:30
A little more investigation shows that (for arrays that are not small, and in some circumstances) TimSort makes use of an auxilliary array that it will copy back into the main array in a merge-sort, doing comparisons along the way.

In Java, if one of those comparisons blows up part-way through a merge, the stack unwinds from there, and the copy that might have occurred is omitted:
http://hg.openjdk.java.net/jdk8u/jdk8u60/jdk/file/935758609767/src/share/classes/java/util/TimSort.java#l782

In CPython, when an exception is raised, the sorting is abandoned, but the merge function keeps its promise to put the elements back into the main array, here:
https://hg.python.org/cpython/file/v2.7.12/Objects/listobject.c#l1574

I can't find where either language promises not to mess up your list in these circumstances, so arguably test_sort is asking too much. But we like to do the same as CPython if we can. I don't like the obvious answer: preserve and restore the original list, doing more than CPython at considerable cost in memory. I think it follows logically that we would have to conceal the exception raised in the comparator, to let the Java sort run to completion somehow, then rethrow it.
msg11245 (view) Author: James Mudd (jamesmudd) Date: 2017-03-19.12:10:13
I have carried on investigating this is a similar direction, and can confirm the issue is with Java's TimSort which is now the default sorting algorithm for objects. I now also have a pure java example of this issue attached (sorry its a bit messy, very quickly written). @Jeff your exactly right to see the list become "corrupted" you need the comparator to throw an exception while TimSort is doing a merge an example stack is:

	at test.TestSortJava$ComplainsComparator.compare(TestSortJava.java:30)
	at test.TestSortJava$ComplainsComparator.compare(TestSortJava.java:1)
	at java.util.TimSort.mergeLo(TimSort.java:717)
	at java.util.TimSort.mergeAt(TimSort.java:514)
	at java.util.TimSort.mergeCollapse(TimSort.java:441)
	at java.util.TimSort.sort(TimSort.java:245)
	at java.util.Arrays.sort(Arrays.java:1512)
	at java.util.ArrayList.sort(ArrayList.java:1454)
	at java.util.Collections.sort(Collections.java:175)
	at test.TestSortJava.main(TestSortJava.java:57)

I'm not clear on what the best fix is, the simplest option is to disable TimSort, which you can do by reverting to the legacy sort algorithm by setting the property -Djava.util.Arrays.useLegacyMergeSort=true see also http://stackoverflow.com/questions/13575224/comparison-method-violates-its-general-contract-timsort-and-gridlayout
I'm not sure this is a workable fix for jython as you can't ensure this property will be set when embedded in other applications but its an option?

It might also be possible to cache and restore the list somehow if we know the sort has gone wrong, I could probably write a patch for that? This will slow down sorting as we will need to compare the items in the before and after lists to determine is we are seeing this issue but I think it would be robust? For large lists this could be bad.

There are also some bugs in Java around this e.g. http://bugs.java.com/bugdatabase/view_bug.do?bug_id=7075600 (and linked) so maybe it's fixed in 9, and we should but ignore it till then? I'm not clear this is actually a Java bug though the behaviour of this case seems undefined.
msg11246 (view) Author: James Mudd (jamesmudd) Date: 2017-03-19.12:29:18
Just tried it with the Java 9 EA (build 9-ea+161) and the behaviour is the same
msg11251 (view) Author: Jeff Allen (jeff.allen) Date: 2017-03-20.08:36:05
@James: I think you've identified yourself the drawbacks of useLegacyMergeSort and keeping a copy of the original list. Ok as a user workaround I think.

I haven't found a Java bug report that encapsulates our issue. Maybe your Java example makes it possible to raise one? It's more an enhancement really, as nothing is promised.

I was hinting at another option. I was thinking that around here:
https://hg.python.org/jython/file/tip/src/org/python/core/PyList.java#l812
and here:
https://hg.python.org/jython/file/tip/src/org/python/core/PyList.java#l864
since we have to provide a Comparator that wraps the __lt__ or custom Python comparator for Java, we could easily catch the exception, and return to TimSort an acceptable result (e.g. claim equality). This would probably let TimSort complete, or at least finish the merge. (Might get an "inconsistent with equals" exception?) Obviously the order of the result is not meaningful now, but it contains all its original elements, as we seem to want.

But we can't just lose the exception: so we'd have to squirrel it away (as a member of the comparator object, say), for PyList.sort to pick up and throw when the Java library returns.

You've put some good work into this bug already, and I don't have much time for Jython before next weekend. If you thought this an approach you could make work, I'd be happy to see you run with it.
msg11253 (view) Author: James Mudd (jamesmudd) Date: 2017-03-20.09:45:11
@Jeff I think making a Java bug report for this is worthwhile, just to see what they think. Although it's not clear it's a Java bug. At the very least it should be in the doc for Collections.sort, that in the failure case it can result in the list elements being changed, as I don't think that's what users of the API would expect. It is also kind of a regression caused by TimSort, as that wouldn't happen before. I will clean up the Java example and try to get that done tonight.

If I get chance I will have a go at the idea you suggest, I think it can work. We will need to be careful though as I think other test rely on different exceptions during sorting, but hopefully the tests cover them all. Even this approach will cost performance though as we will need a try catch for every comparison.

Thanks for also looking at this.
msg11254 (view) Author: James Mudd (jamesmudd) Date: 2017-03-20.20:33:01
I have submitted a Java bug report for this issue, interestingly with Java 7 this doesn't occur even though it uses TimSort. I will post here if I hear anything.

I have a pull request implementing the fix suggested by Jeff which seems to work well. https://github.com/jythontools/jython/pull/67 we will see if the build changes allow the builds to pass...
msg11262 (view) Author: Jeff Allen (jeff.allen) Date: 2017-03-22.11:56:13
Now considered fixed as of https://hg.python.org/jython/rev/c677bb7414b1

Thanks James. Would you add a link to the Java report you raised, just for interest?
msg11263 (view) Author: Stefan Richthofer (stefan.richthofer) Date: 2017-03-22.12:52:23
Thanks for fixing this, also from me!

However I am a little concerned that the try/catch slows down comparison (at least in theory) and thus sorting. I didn't look it up (yet), but I guess that throwing/raising an exception during comparison is actually undefined behavior in CPython and Java. So maybe it would have been better to adjust the test (at least keep this in mind if the Java-issue gets fixed).

(On the other hand I agree this might not be significant compared to other performance issues in Jython.)
msg11264 (view) Author: Jim Baker (zyasoft) Date: 2017-03-22.14:31:04
Great work!

This use of an exception handler is just the sort of thing that JVMs are optimized for, so it should incur no additional cost unless an exception happens. Of course it would be straightforward to do the performance analysis to verify my assertion.
msg11265 (view) Author: Jeff Allen (jeff.allen) Date: 2017-03-22.17:15:39
Try ... catch certainly makes no impact on the bytecode (JVM spec 3.12). Meeting CPython expectations, albethey undocumented, looks essentially free.
msg11267 (view) Author: James Mudd (jamesmudd) Date: 2017-03-22.21:11:08
First on the performance issue, I was interested to see so quickly adapted the script I had for reproducing the failure into a crude benchmark, attached. The results surprised me:
    With new try catch 33.7049999237 secs
    without 33.9839999676 secs

It sorts a 10000 element list 1000 times, within error about 1 sec they are exactly the same so it does indeed seem the JVM is very efficient with try catch which is nice to know. If anyone else wants to try it that would be good.

On the Java bug report, I submitted it via http://bugreport.java.com at the end of that process they say they will have a look and let you know. I haven't heard anything yet. Should I have submitted it by some other way?
msg11269 (view) Author: James Mudd (jamesmudd) Date: 2017-03-23.09:11:30
This has been accepted as a bug in Java. You can see the bug tickets here:
http://bugs.java.com/bugdatabase/view_bug.do?bug_id=JDK-8177443
https://bugs.openjdk.java.net/browse/JDK-8177443

So this process takes about 3 days. It has been assigned P3 priority which means "Major loss of function".

If this gets fixed in Java I think the change I made should be reverted, as it prevents fail-fast behaviour during sorts.

I have also updated the Java example with the version submitted with the bug report.
History
Date User Action Args
2017-03-23 09:11:31jamesmuddsetfiles: + TestSort.java
messages: + msg11269
2017-03-23 09:07:22jamesmuddsetfiles: - TestSortJava.java
2017-03-22 21:11:09jamesmuddsetfiles: + sort_benchmark.py
messages: + msg11267
2017-03-22 17:15:39jeff.allensetmessages: + msg11265
2017-03-22 14:31:04zyasoftsetmessages: + msg11264
2017-03-22 12:52:23stefan.richthofersetmessages: + msg11263
2017-03-22 11:56:13jeff.allensetstatus: open -> closed
messages: + msg11262
2017-03-20 20:33:01jamesmuddsetmessages: + msg11254
2017-03-20 09:45:11jamesmuddsetmessages: + msg11253
2017-03-20 08:36:06jeff.allensetmessages: + msg11251
2017-03-19 12:29:18jamesmuddsetmessages: + msg11246
2017-03-19 12:10:14jamesmuddsetfiles: + TestSortJava.java
messages: + msg11245
2017-03-19 10:49:31jeff.allensetmessages: + msg11244
2017-03-18 18:30:52jeff.allensetmessages: + msg11243
2017-03-18 16:59:31jamesmuddsetmessages: + msg11242
2017-03-18 15:15:26jamesmuddsetfiles: + test_sort_example_failure.py
nosy: + jamesmudd
messages: + msg11241
2017-02-16 22:40:08jeff.allensetmessages: + msg11099
2017-02-15 20:31:51stefan.richthofersetpriority: normal
type: behaviour
messages: + msg11098
nosy: + stefan.richthofer
2016-02-04 01:08:36zyasoftsetmilestone: Jython 2.7.2
2015-09-22 17:41:05zyasoftsetresolution: accepted
2015-09-22 17:40:54zyasoftsetnosy: + zyasoft
messages: + msg10272
2015-09-14 21:27:38jeff.allencreate