RFR: 8141564: Convert TraceItables and PrintVtables to Unified Logging

Thu Jan 7 17:15:04 UTC 2016

Hi, David,

Thanks for that. I've corrected the issue in interpreterRuntime.cpp as 
well as in klassVtable.cpp. Did you look at all the code - shall I count 
you as a reviewer?

Updated webrev: http://cr.openjdk.java.net/~rprotacio/8141564.04/

Rachel

On 12/8/2015 11:05 PM, David Holmes wrote:
> Hi Rachel,
>
> src/share/vm/interpreter/interpreterRuntime.cpp
>
> The ResourceMark is now used outside of the actual logging code. If a 
> ResourceMark is needed then I think we need to use the "if 
> (log_is_enabled(...)" form.
>
> Thanks,
> David
>
>
>
> On 9/12/2015 4:46 AM, Rachel Protacio wrote:
>> Hi,
>>
>> On 12/8/2015 12:28 PM, Karen Kinnear wrote:
>>> Rachel,
>>>
>>> Thank you for the updates.
>>> Can you please sanity check one thing for me - the log_tables boolean
>>> “overrides” appears to
>>> be set correctly in the callers, to mean “yes, this overrides”.
>>> In log_vtables, is it possible the choice of what to print is reversed?
>>>
>>> And perhaps add a check to your tests for example that “NOT
>>> overriding” catches the right case?
>> Oh, good catch. Thank you - this is fixed now.
>>>
>>> And yes please on the assertion (I have seen null method bugs in
>>> development and this code is an early
>>> opportunity to catch that problem).
>>>
>>> I don’t need to see an updated web rev and you don’t need to rerun all
>>> the tests to fix
>>> the printed string.
>> Great. Thanks again, Karen and Coleen! Will commit the change.
>> Rachel
>>> thanks,
>>> Karen
>>>
>>>> On Dec 7, 2015, at 1:37 PM, Coleen Phillimore
>>>> <coleen.phillimore at oracle.com> wrote:
>>>>
>>>>
>>>>
>>>> On 12/4/15 6:00 PM, Rachel Protacio wrote:
>>>>> Hi, Karen,
>>>>>
>>>>> Thanks for the review. Updated webrev:
>>>>> http://cr.openjdk.java.net/~rprotacio/8141564.02/
>>>>>
>>>>> Since I never listed the tests I ran even the first time, here are
>>>>> all of them:
>>>>>
>>>>> * jtreg
>>>>> * JPRT
>>>>> * jck vm, lang, & api/java_lang
>>>>> * rbt quick and non-colo (which now includes defmeth)
>>>>> * invoke*
>>>>>
>>>>> Replies inline.
>>>>>
>>>>> On 12/3/2015 4:56 PM, Karen Kinnear wrote:
>>>>>> Rachel,
>>>>>>
>>>>>> Thank you so much for doing (and redoing) this.
>>>>>>
>>>>>> Couple of questions/comments.
>>>>>>
>>>>>> 1. thank you so much for the transitive overriding test - not easy
>>>>>> to figure out how to generate one!
>>>>>>
>>>>> Lois walked me through doing that one :)
>>>>>> 2. I missed the list of what you have tested for the first web rev
>>>>>> and the other tests for this one
>>>>>> I will assume in parallel with the code review you are running
>>>>>> (without tracing)
>>>>>> vm quick & nocolo, jck vm & lang
>>>>>> defmeth, invoke*
>>>>> Yeah, I totally forgot to email what tests I had run. Sorry about
>>>>> that! And just learned how to run the jck tests.
>>>>>> There might be value in running your new tests with old tracing vs.
>>>>>> new and eyeballing the files - to see if they
>>>>>> get essentially the same information.
>>>>>>
>>>>> Yup!
>>>>>> 3. klassVtable.cpp lines 154-156 …
>>>>>> Would it make any sense to do if !klass()->is_array_klass() and
>>>>>> then just use the log_develop_debug and
>>>>>> not do the extra develop_log_is_enabled check? No big deal.
>>>>>>
>>>>> That makes sense. Changed as suggested.
>>>>>> 4. thank you so much for extracting the print_linkage_flags - I
>>>>>> should have done that earlier - the information
>>>>>> just grew incrementally.
>>>>>>
>>>>>> 5. klassVtable.cpp line 1047 -
>>>>>>    I think you want an if (m != NULL) here  before dereferencing to
>>>>>> print_linkage_flags.
>>>>>>    I see we miss that check for other dereferences -feel free to
>>>>>> add small checks.
>>>>>>    Don’t completely skip logic paragraphs except for printing ones.
>>>>> Well, when I was making my change, we saw that it wouldn't be
>>>>> possible for m to be null at that point in the code. There are
>>>>> multiple places above it where it is dereferenced already, not to
>>>>> mention the fact that it is theoretically initialized to be a valid
>>>>> method. Would you like to me to add an assert after the declaration
>>>>>     assert(m != NULL, "methods can never be null");
>>>>> just to be safe?
>>>> In the code here:
>>>> http://cr.openjdk.java.net/~rprotacio/8141564.02/src/share/vm/oops/klassVtable.cpp.udiff.html 
>>>>
>>>> <http://cr.openjdk.java.net/~rprotacio/8141564.02/src/share/vm/oops/klassVtable.cpp.udiff.html> 
>>>>
>>>>
>>>>
>>>> Yes, Method* m = method->at(i); can never return NULL or else the
>>>> whole VM would crash everywhere.  I suspect the logging code here was
>>>> copied from other instances where 'm' could be null.   This line
>>>> would crash first:
>>>>
>>>> if (interface_method_needs_itable_index(m)) {
>>>>
>>>>
>>>> Can you clean up this line also to not check for NULL:
>>>>
>>>> const char* sig = (m != NULL) ? m->name_and_sig_as_C_string() :
>>>> "<NULL>";
>>>>
>>>>
>>>> And add the assert if Karen agrees if it's needed.
>>>>
>>>> The rest of the changes look good.   I don't need to see another
>>>> revision.
>>>>
>>>> Thanks,
>>>> Coleen
>>>>>>     Thank you for leaving the null check in fill_in_miranda and
>>>>>> print_method_at.
>>>>>>
>>>>>> 6. log_vtables
>>>>>> The logic in update_inherited_vtables is quite complex.
>>>>>> So the value of allocate_new is not really the right conditional to
>>>>>> pass in to determine if there
>>>>>> was an override.
>>>>>>    The first paragraph applies both for allocate_new=true and
>>>>>> allocate_new=false (see !target_method()->is_package_private())
>>>>>>    so they would have allocate_new = true AND be overriding.
>>>>>>
>>>>>> So, perhaps you could add a boolean that says “overrides” or
>>>>>> “overriding” or whatever : default it to false, and set it to true
>>>>>> right after the put_method_at line (that iswhere the override
>>>>>> occurs) and set it to false in the “else” clause?
>>>>>> And pass that argument in to log_vtables ? And remove the
>>>>>> allocate_new comment from log_vtables as well?
>>>>>>
>>>>> Done, too.
>>>>>
>>>>> Thanks!!
>>>>> Rachel
>>>>>> And the comment in the “else” is not accurate since I put the
>>>>>> package_private fix in - so removing
>>>>>> it was a good idea.
>>>>>>
>>>>>> many thanks,
>>>>>> Karen
>>>>>>
>>>>>>> On Dec 3, 2015, at 2:23 PM, Rachel Protacio
>>>>>>> <rachel.protacio at oracle.com <mailto:rachel.protacio at oracle.com>
>>>>>>> <mailto:rachel.protacio at oracle.com
>>>>>>> <mailto:rachel.protacio at oracle.com>>> wrote:
>>>>>>>
>>>>>>> Hi,
>>>>>>> Thanks for the comments! Updated
>>>>>>> webrev:http://cr.openjdk.java.net/~rprotacio/8141564.01/
>>>>>>> <http://cr.openjdk.java.net/~rprotacio/8141564.01/><http://cr.openjdk.java.net/%7Erprotacio/8141564.01/ 
>>>>>>>
>>>>>>> <http://cr.openjdk.java.net/%7Erprotacio/8141564.01/>>(Builds and
>>>>>>> passes logging jtreg tests.)
>>>>>>>
>>>>>>> Replies inline.
>>>>>>>
>>>>>>> On 12/2/2015 2:34 PM, Coleen Phillimore wrote:
>>>>>>>> Rachel, There are a lot of changes here.  I have several comments
>>>>>>>> and more suggested cleanup that should be done with this work.
>>>>>>>>
>>>>>>>> Inhttp://cr.openjdk.java.net/~rprotacio/8141564/src/share/vm/interpreter/linkResolver.cpp.udiff.html 
>>>>>>>>
>>>>>>>> <inhttp://cr.openjdk.java.net/~rprotacio/8141564/src/share/vm/interpreter/linkResolver.cpp.udiff.html><http://cr.openjdk.java.net/%7Erprotacio/8141564/src/share/vm/interpreter/linkResolver.cpp.udiff.html 
>>>>>>>>
>>>>>>>> <http://cr.openjdk.java.net/%7Erprotacio/8141564/src/share/vm/interpreter/linkResolver.cpp.udiff.html>> 
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> I did the original refactoring for trace_method_resolution. What
>>>>>>>> I think would be better is to make it an internal static function
>>>>>>>> in linkResolver.cpp and not defined in the linkResolver.hpp.
>>>>>>>> Make the call unconditional and pass vtable index in the last
>>>>>>>> parameter as a default parameter with default value -1 so the
>>>>>>>> last line in the function is the tty->cr() that I had outside the
>>>>>>>> function call (that was pretty icky). And put all the
>>>>>>>> ResourceMark and logstream logic inside the
>>>>>>>> trace_method_resolution function.  It would never print to tty so
>>>>>>>> doesn't need an outputStream parameter for other callers.
>>>>>>>>
>>>>>>>> So there would be only the one line
>>>>>>>> trace_method_resolution(params) in the regular code.
>>>>>>> Thanks for the advice! I still have to call the function from
>>>>>>> within the conditional because it's develop level only and because
>>>>>>> I need to specify in the call whether it's for itables or vtables.
>>>>>>> Otherwise, I've followed your suggestions.
>>>>>>>> http://cr.openjdk.java.net/~rprotacio/8141564/src/share/vm/logging/logTag.hpp.udiff.html 
>>>>>>>>
>>>>>>>> <http://cr.openjdk.java.net/~rprotacio/8141564/src/share/vm/logging/logTag.hpp.udiff.html><http://cr.openjdk.java.net/%7Erprotacio/8141564/src/share/vm/logging/logTag.hpp.udiff.html 
>>>>>>>>
>>>>>>>> <http://cr.openjdk.java.net/%7Erprotacio/8141564/src/share/vm/logging/logTag.hpp.udiff.html>> 
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> Can you put these tags near each other?
>>>>>>>>
>>>>>>> I have them sorted alphabetically, which I think is more useful in
>>>>>>> the long run.
>>>>>>>> http://cr.openjdk.java.net/~rprotacio/8141564/src/share/vm/oops/klassVtable.cpp.udiff.html 
>>>>>>>>
>>>>>>>> <http://cr.openjdk.java.net/~rprotacio/8141564/src/share/vm/oops/klassVtable.cpp.udiff.html><http://cr.openjdk.java.net/%7Erprotacio/8141564/src/share/vm/oops/klassVtable.cpp.udiff.html 
>>>>>>>>
>>>>>>>> <http://cr.openjdk.java.net/%7Erprotacio/8141564/src/share/vm/oops/klassVtable.cpp.udiff.html>> 
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> One of the things that Markus Gronlund's made me think that we
>>>>>>>> should do with his cleanup is to stop declaring functions as
>>>>>>>> members of classes if they don't need external linkage. From his
>>>>>>>> RFR(L): 8140485: Class load and creation clean up:
>>>>>>>>
>>>>>>>> "Comment: In my opinion, we should attempt to break the pattern
>>>>>>>> of having private functions declared in header files when the
>>>>>>>> private function does not need to reach inside "this"."
>>>>>>>>
>>>>>>>> I think the function log_vtables should follow this and be
>>>>>>>> declared as a static internal function in klassVtable.cpp above
>>>>>>>> the function where it's used.
>>>>>>>>
>>>>>>>> It's true that you don't see this very much in the hotspot 
>>>>>>>> sources.
>>>>>>>>
>>>>>>>> The refactoring of log_vtables is good and very much appreciated.
>>>>>>>>
>>>>>>>> In each of the logging blocks of code, there are about 6 lines
>>>>>>>> that are about the same, that print the access flags and whether
>>>>>>>> it's a default or overpass method.  (Karen and Lois should give
>>>>>>>> you a TOI about what that means!)  Can you add a method to
>>>>>>>> method.hpp that's something like print_flags(outputStream* st)
>>>>>>>> and move this printing there, and make those blocks call your new
>>>>>>>> function?  That would shorten many of these logging blocks of
>>>>>>>> code and would be nice.  You could call this from the
>>>>>>>> linkResolver.cpp trace_method_resolution() function too.
>>>>>>> Done.
>>>>>>>> http://cr.openjdk.java.net/~rprotacio/8141564/test/runtime/logging/p1/A.java.html 
>>>>>>>>
>>>>>>>> <http://cr.openjdk.java.net/~rprotacio/8141564/test/runtime/logging/p1/A.java.html><http://cr.openjdk.java.net/%7Erprotacio/8141564/test/runtime/logging/p1/A.java.html 
>>>>>>>>
>>>>>>>> <http://cr.openjdk.java.net/%7Erprotacio/8141564/test/runtime/logging/p1/A.java.html>> 
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> These classes have missing copyrights.
>>>>>>> Fixed.
>>>>>>> Thanks!
>>>>>>> Rachel
>>>>>>>> Thanks!
>>>>>>>> Coleen
>>>>>>>>
>>>>>>>>
>>>>>>>> On 12/1/15 5:58 PM, Rachel Protacio wrote:
>>>>>>>>> Hi,
>>>>>>>>>
>>>>>>>>> Please review this changeset that converts -XX:+TraceItables and
>>>>>>>>> -XX:+PrintVtables flags to -Xlog:itables and -Xlog:vtables.
>>>>>>>>>
>>>>>>>>> Open webrev: http://cr.openjdk.java.net/~rprotacio/8141564/
>>>>>>>>> <http://cr.openjdk.java.net/~rprotacio/8141564/>
>>>>>>>>> <http://cr.openjdk.java.net/%7Erprotacio/8141564/
>>>>>>>>> <http://cr.openjdk.java.net/%7Erprotacio/8141564/>>
>>>>>>>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8141564
>>>>>>>>> <https://bugs.openjdk.java.net/browse/JDK-8141564>
>>>>>>>>>
>>>>>>>>> In case it's not clear, the changes in oops/klassVtable.cpp
>>>>>>>>> around 462-498 are a refactoring of the duplicate code from a
>>>>>>>>> conditional to a function with a boolean argument.
>>>>>>>>>
>>>>>>>>> Thank you,
>>>>>>>>> Rachel
>>