RFR(XS) 8249719: MethodHandle performance suffers from bad ResolvedMethodTable hash function

[Thomas Stüfe]

Hi Andrei,

I was afraid this might happen, but only occurred to me after the review.

My proposal would be:

- in resolvedMethodTable.cpp, extend the log message in log_insert() and
print out the hashcode too (e.g. "ResolvedMethod entry added for ...
(4711)").

- In the test, start your test as a sub process, give it
-Xlog:membername+table=debug, and scan the output line for "ResolvedMethod
entry added for <your class name> (<hash>)". Extract the hash. Read two or
three lines and compare the hash.

The advantage would be that you do not need to load 200k classes to see
that your regression test works, and it is timing independent. For examples
of sub process spawning and output scanning, there are many jtreg tests
already (e.g. runtime/ErrorHandling has a few).

Just my 5 cent. Maybe the others have different proposals.

Cheers, Thomas




On Mon, Jul 27, 2020 at 7:52 PM Andrei Pangin <andrei.pangin at gmail.com>
wrote:

> Hi,
>
> Coleen, Thomas, thank you for your reviews. It turns out though that my
> new test times out on debug builds (thanks Volker for double-checking).
>
> TestTierPlatformDescription
> runtime/MemberName/ResolvedMethodTableHash.java tier1 linux-aarch64-debug Error:
> Program `...java' timed out (timeout set to ...ms, elapsed time including
> timeout handling was ...ms).
> runtime/MemberName/ResolvedMethodTableHash.java tier1 windows-x64-debug Error:
> Program
> `c\:\\ade\\mesos\\work_dir\\jib-master\\install\\...-07-27-0826248.andrei.pangin.source\\windows-x64-debug.jdk\\jdk-16\\fastdebug\\bin\\java'
> timed out (timeout set to ...ms, elapsed time including timeout handling
> was ...ms).
> runtime/MemberName/ResolvedMethodTableHash.java tier1 macosx-x64-debug Error:
> Program `...java' timed out (timeout set to ...ms, elapsed time including
> timeout handling was ...ms).
>
> Apparently, we can't rely on timing, since this test runs two orders of
> magnitude slower on debug JVM than on product one. I could simply mark the
> test as manual, or is there a better idea? Maybe, adjust the parameters and
> run the test automatically only on product or only on debug JVM? What do
> you think?
>
> Regards,
> Andrei
>
> сб, 25 июл. 2020 г. в 17:34, <coleen.phillimore at oracle.com>:
>
>>
>> Hi Andrei,
>> This looks good.  Thank you for finding this bug.  And thanks to Volker
>> for sponsoring it as well.
>> Nice to see you on the list, Andrei!
>> Coleen
>>
>> On 7/25/20 3:18 AM, Thomas Stüfe wrote:
>>
>> Hi, Andrei,
>>
>> Good find. I played around with a test of generating lots of lambdas and
>> yes, all the hashes are equal. With your patch invocation time went down by
>> half (that was for 10000 lambdas).
>>
>> The test looks fine though the normal way to do this seems to be jcod. I
>> personally don't care since the test is nice and self contained that way,
>> but someone from the Oracle runtime group should confirm this is fine
>> (ccing Coleen).
>>
>> JDK11 seems to be affected too.
>>
>> This probably also affects jruby.
>>
>> +1 from me.
>>
>> ..Thomas
>>
>> On Fri, Jul 24, 2020 at 4:53 PM Andrei Pangin <andrei.pangin at gmail.com>
>> wrote:
>>
>>> Hi,
>>>
>>> Please review a small fix to a not-so-small performance issue that we've
>>> seen when migrating a production application from JDK 8 to JDK 14.
>>>
>>> On certain workloads, where Nashorn produces thousands MethodHandles,
>>> ResolvedMethodTable operations become extremely slow due to degenerate
>>> hashcode. This patch basically fixes hashcode by including the method
>>> holder's name in the computation. More details in the bug report.
>>>
>>> CR: https://bugs.openjdk.java.net/browse/JDK-8249719
>>> Webrev: https://cr.openjdk.java.net/~apangin/8249719/webrev/
>>>
>>> Tested: tier1-2, hotspot*runtime
>>>
>>> I'll be glad if someone could sponsor the patch.
>>>
>>> Thank you,
>>> Andrei Pangin
>>>
>>
>>