RFR 8140685: Fix backtrace building to not rely on constant pool merging

[Coleen Phillimore]

On 11/2/15 4:55 AM, Stefan Karlsson wrote:
> Hi Coleen,
>
> I remember this from our earlier discussions about the Backtraces.

Stefan,
Yes, it's back again.   My original change for this was 2012.   All the 
complicated changes we made to avoid this were turning into something of 
a kludge tower and are preventing further improvements.
>
> On 2015-10-30 23:01, Coleen Phillimore wrote:
>> Summary: Save Throwable in a list which is a weak GC root for walking 
>> during MetadataOnStackMark
>>
>> This was the original implementation that I had for finding Method* 
>> in backtraces but it was slow because I had used jweak to save the 
>> Throwable object.
>
> It wasn't the jweak handles that made it slow for the GC. Maybe it 
> made it slower for the runtime?

Yes, it was jweak handles that made it slow for the runtime.  During the 
javac benchmark, the cost of creating these jni handles (taking out a 
lock and adding to a global data structure) was too expensive for all 
the backtraces that the benchmark created.  Most of the backtraces are 
unused but we don't know that when the exceptions are thrown of course.

We didn't measure jweak handling for the GC though.  I suspect that 
wasn't free for GC performance either.
>
>> Using internal vm weak GC roots, this does not cause a performance 
>> regression in refWorkload.  This fix is more straightforward and does 
>> not rely on the constant pool index of the merged constant pool 
>> during redefinition to find the method's name.
>> This is one fix that enables removing merged constant pools during 
>> redefinition (work in progress).  It also is would be used as a model 
>> for JEP 259: Stack Walking API
>> https://bugs.openjdk.java.net/browse/JDK-8043814.
>>
>> The code that registers MemberNames for replacing Method* during 
>> redefinition may need to use the same mechanism for performance, if 
>> MemberName arrays are used for the Stack Walking API.
>>
>> I assume this will generate comments from the GC group.
>
> If you run the following small test program, you'll see some of the 
> problems this patch introduces for the GC. It's a contrived test case 
> to make it obvious what the problems with this patch are, but I'd not 
> be surprised if you would see effects from this patch if you looked at 
> the GC pause times from test runs with larger tests.
>
> public class BT {
>   public static void main(String [] args) {
>     while (true) {
>       try {
>         f0(10);
>       } catch (RuntimeException e) {
>         e.fillInStackTrace();
>       }
>     }
>   }
>
>   public static boolean f0(int v) {
>     throw new RuntimeException();
>   }
>   public static boolean f1(int v) { return f0(v);}
>   public static boolean f2(int v) { return f1(v);}
>   public static boolean f3(int v) { return f2(v);}
>   public static boolean f4(int v) { return f3(v);}
>   public static boolean f5(int v) { return f4(v);}
>   public static boolean f6(int v) { return f5(v);}
>   public static boolean f7(int v) { return f6(v);}
>   public static boolean f8(int v) { return f7(v);}
>   public static boolean f9(int v) { return f8(v);}
>   public static boolean fa(int v) { return f9(v);}
>   public static boolean fb(int v) { return fa(v);}
>   public static boolean fc(int v) { return fb(v);}
>   public static boolean fd(int v) { return fc(v);}
>   public static boolean fe(int v) { return fd(v);}
>   public static boolean ff(int v) { return fe(v);}
> }
>
> Running without the patch:
> $ java -Xmx1g -Xms1g -Xmn100m -XX:+PrintGC -cp . BT
> #0: [GC pause (G1 Evacuation Pause) (young) 100M->352K(1024M), 
> 0.0197192 secs]
> #1: [GC pause (G1 Evacuation Pause) (young) 99M->354K(1024M), 
> 0.0096909 secs]
> #2: [GC pause (G1 Evacuation Pause) (young) 99M->366K(1024M), 
> 0.0022548 secs]
> #3: [GC pause (G1 Evacuation Pause) (young) 99M->360K(1024M), 
> 0.0141840 secs]
> #4: [GC pause (G1 Evacuation Pause) (young) 99M->355K(1024M), 
> 0.0037668 secs]
> #5: [GC pause (G1 Evacuation Pause) (young) 99M->370K(1024M), 
> 0.0027435 secs]
> #6: [GC pause (G1 Evacuation Pause) (young) 99M->358K(1024M), 
> 0.0243332 secs]
> ... and it continues like that ...
>
> Running with the patch:
> $ java -Xmx1g -Xms1g -Xmn100m -XX:+PrintGC -cp . BT
> #0: [GC pause (G1 Evacuation Pause) (young) 100M->52M(1024M), 
> 0.3144429 secs]
> #1: [GC pause (G1 Evacuation Pause) (young) 139M->98M(1024M), 
> 0.2848108 secs]
> #2: [GC pause (G1 Evacuation Pause) (young) 185M->143M(1024M), 
> 0.2894741 secs]
> #3: [GC pause (G1 Evacuation Pause) (young) 230M->188M(1024M), 
> 0.2593455 secs]
> #4: [GC pause (G1 Evacuation Pause) (young) 275M->233M(1024M), 
> 0.1987466 secs]
> #5: [GC pause (G1 Evacuation Pause) (young) 320M->279M(1024M), 
> 0.1580889 secs]
> #6: [GC pause (G1 Evacuation Pause) (young) 366M->324M(1024M), 
> 0.1370179 secs]
> #7: [GC pause (G1 Evacuation Pause) (young) 411M->369M(1024M), 
> 0.1382296 secs]
> #8: [GC pause (G1 Evacuation Pause) (young) 456M->414M(1024M), 
> 0.3050619 secs]
> #9: [GC pause (G1 Evacuation Pause) (young) 501M->459M(1024M), 
> 0.1885095 secs]
> #10: [GC pause (G1 Evacuation Pause) (young) 546M->504M(1024M), 
> 0.1608086 secs]
> #11: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 
> 591M->549M(1024M), 0.1846752 secs]
> #12: [GC concurrent-root-region-scan-start]
> #12: [GC concurrent-root-region-scan-end, 0.0051940 secs]
> #12: [GC concurrent-mark-start]
> #12: [GC concurrent-mark-end, 0.0175889 secs]
> #12: [GC remark, 0.0800191 secs]
> #12: [GC cleanup 564M->90M(1024M), 0.0024635 secs]
> #12: [GC concurrent-cleanup-start]
> #12: [GC concurrent-cleanup-end, 0.0019211 secs]
> #13: [GC pause (G1 Evacuation Pause) (young) 162M->120M(1024M), 
> 0.2551443 secs]
> #14: [GC pause (G1 Evacuation Pause) (young) 207M->165M(1024M), 
> 0.1553368 secs]
> #15: [GC pause (G1 Evacuation Pause) (young) 252M->210M(1024M), 
> 0.2132882 secs]
> #16: [GC pause (G1 Evacuation Pause) (young) 297M->255M(1024M), 
> 0.1187748 secs]
> ...
>
> As can be seen, the young GC pause times increase drastically, and the 
> memory isn't cleaned out until we do a full concurrent cycle (or 
> trigger a Full GC).
>

Good, thank you for the test case and what to look for.  I will run the 
simplified version of this test.  I believe you that the pause times 
would increase for the microbenchmark.  Although, I found that the 
average depth of these stack traces was about 6 in real cases and the 
max was 200.

The question I have, then, is can we process this list in parallel with 
other GC root scanning? It's independent of other things.  We will also 
need a strategy to scan MemberNameTable roots if we find that building 
these with jweaks is too expensive for the new StackWalk API.

In this change, I simply added the backtrace GC scanning to 
SystemDictionary because I didn't have a better idea.   Please help find 
a better place for this!

Thanks,
Coleen
> StefanK
>
>>
>> bug link https://bugs.openjdk.java.net/browse/JDK-8140685
>> local webrev at http://javaweb.us.oracle.com/~cphillim/webrev/8140685.01
>>
>> Tested with RBT quick (former "quick" tests), 
>> jdk/java/lang/instrument tests and the test that I wrote for handling 
>> backtraces with redefinition in hotspot/test/runtime/RedefineTests.
>>
>> Thanks,
>> Coleen
>