Hi Serguei, Thanks for looking at it. You are right that there are various ways of doing this:
A) Continue removing the assignments via https://bugs.openjdk.java.net/browse/JDK-8210687 - This requires a few more webrevs but as you've said, we will miss the extra tracing B) Start extending the ExceptionCheckingJni and start propagating that in the vmTestbase already handled in A to bring back the tracing And we can do A + B in parallel so that the time without tracing is reduced. Otherwise we can do: C) Start extending the ExceptionCheckingJni and start propagating that in the vmTestbase already handled in A to bring back the tracing - When propagating in code that is using the NSK_VERIFY macros, we remove the macro at the same time ----------------------- I have no real preference, A is easy to do with my scripts and B will be relatively straightforward now that I've worked out most of the details. C postpones the bug due to just taking more time to roll-out but there was no real rush for it, it's just going to be slower going. Also, the (C) route makes each file changed a bit bigger and less automatic to understand what is going on but not by much. I would imagine the community and reviewers would prefer the (C) route as it is the least disruptive from a test tracing/debugging perspective, no? Let me know, Jc On Tue, Nov 6, 2018 at 12:23 PM <serguei.spit...@oracle.com> wrote: > Okay. > I'm not sure I fully understandd what is current plan. > > My view is that we can do the following steps: > 1) Jc can push what was already reviewed. > With this change we will miss extra tracing for JNI calls and results. > 2) Work on using the ExceptionCheckingJni that will restore > this tracing but in a different fashion. > > Is it correct? > > Thanks, > Serguei > > On 11/6/18 11:57 AM, serguei.spit...@oracle.com wrote: > > > On 11/6/18 11:14 AM, Chris Plummer wrote: > > Hi JC, > > The exception changes looked ok to me, but it would be good to get a > second approval before moving forward with them since they are pretty > significant. > > > The exception changes need to be discussed after a separate RFR is posted. > > Thanks, > Serguei > > thanks, > > Chris > > On 11/2/18 9:09 PM, JC Beyler wrote: > > Hi Chris, > > Yes that is correct, the webrev in this email thread would be postponed > and done differently. > > Most likely we'd have to do smaller changes to extend ExceptionCheckingJni > and work on replacing the NSK*VERIFY macros by using the > ExceptionCheckingJni wrapper using something similar to the change I show > in http://cr.openjdk.java.net/~jcbeyler/exception/. > > I guess the question becomes really: are the changes in > http://cr.openjdk.java.net/~jcbeyler/exception/ seem in theory at least > reasonable? Then I could start working on it but it will most likely be a > slower going process. > > Let me know, > Jc > > On Fri, Nov 2, 2018 at 8:44 PM Chris Plummer <chris.plum...@oracle.com> > wrote: > >> Hi JC, >> >> So assuming the change to move the assignment outside of the conditional >> is already in place, you are changing: >> >> debugeeClass = jni->FindClass(DEBUGEE_CLASS_NAME); >> >> to >> >> ExceptionCheckingJniEnvPtr jni_wrapper(jni); >> ... >> debugeeClass = jni_wrapper->FindClass(DEBUGEE_CLASS_NAME, >> TRACE_JNI_CALL); >> >> But none of your ExceptionCheckingJni changes are pushed yet, right? >> >> thanks, >> >> Chris >> >> On 11/2/18 10:44 AM, JC Beyler wrote: >> >> Hi Chris, >> >> Here is what it would "look like", there is a bit more clean up to make >> it true for all methods, handling the "verbose" flag, etc but it should >> help see what I'm talking about: >> http://cr.openjdk.java.net/~jcbeyler/exception/ >> >> Basically: >> - The test now no longer needs the NSK_JNI_VERIFY but requires a >> TRACE_JNI_CALL as last argument to the JNI calls if you want >> >> http://cr.openjdk.java.net/~jcbeyler/exception/test/hotspot/jtreg/vmTestbase/nsk/jvmti/SetTag/settag001/settag001.cpp.udiff.html >> Note: I left the nsk_setVerboseMode call though this version does >> not care about that flag but I would do it to be conforming of course >> >> - The wrapper class would have a new macro TRACE_JNI_CALL and the >> methods would have new parameters for the line and file that are defaulted >> to -1 and 0 so that we can know if they are used or not: >> >> http://cr.openjdk.java.net/~jcbeyler/exception/test/hotspot/jtreg/vmTestbase/nsk/share/jni/ExceptionCheckingJniEnv.hpp.udiff.html >> >> - Finally, the real change comes from here: >> >> http://cr.openjdk.java.net/~jcbeyler/exception/test/hotspot/jtreg/vmTestbase/nsk/share/jni/ExceptionCheckingJniEnv.cpp.udiff.html >> >> Where we do this: >> a) add a new constructor for the JNIVerifier class for having the >> parameter of the JNI call be passed in for printing the value of, this will >> sadly have to be duplicated by the number of different argument numbers >> since variadic templates is C++11 onwards but that is not a huge problem >> since it is contained to this file >> b) at JNIVerifier construction, we print it out the "before" call >> and this should be protected by the verbose flag like the >> nsk_ltrace/nsk_verify methods do it for compatibility >> c) at JNIVerifier construction, we now can call the print >> parameter methods to pass the values of the call to be printed out >> - again sadly without c++11 we will have to have a few of these >> here but that is limited to this part of the code so should be fine >> d) the JNI wrapper methods get augmented by the line/file >> parameters which default to -1 and 0 >> e) the constructor is now also passing in the JNI method >> parameters >> >> It's mostly boiler plate code but allows us to go from: >> - if (!NSK_JNI_VERIFY(jni, (debugeeClass = >> - jni->FindClass(DEBUGEE_CLASS_NAME)) != NULL)) { >> + debugeeClass = jni_wrapper->FindClass(DEBUGEE_CLASS_NAME, >> TRACE_JNI_CALL); >> + if (debugeeClass != NULL) { >> >> And print out: >> >> Calling JNI method FindClass from >> /usr/local/google/home/jcbeyler/mercurial/jdk12-verify/test/hotspot/jtreg/vmTestbase/nsk/jvmti/SetTag/settag001/settag001.cpp:69 >> >> Calling with these parameter(s): >> nsk/jvmti/SetTag/settag001 >> << Called JNI method FindClass from >> /usr/local/google/home/jcbeyler/mercurial/jdk12-verify/test/hotspot/jtreg/vmTestbase/nsk/jvmti/SetTag/settag001/settag001.cpp:69 >> FATAL ERROR in native method: JNI method FindClass : Return is NULL from >> /usr/local/google/home/jcbeyler/mercurial/jdk12-verify/test/hotspot/jtreg/vmTestbase/nsk/jvmti/SetTag/settag001/settag001.cpp:69 >> >> With the >> and << lines being the "equivalent" to the trace methods and >> the "FATAL ERROR being the equivalent to the NSK_COMPLAIN done in the >> verify method. >> >> Let me know what you think, >> Jc >> >> d) at JNIVerifier destruction, we can print out the "called the >> method" >> >> >> >> >> On Thu, Nov 1, 2018 at 1:24 PM Chris Plummer <chris.plum...@oracle.com> >> wrote: >> >>> Hi JC, >>> >>> I would need to see a webrev with the ExceptionCheckingJni support, new >>> macros, and a few example uses. You don't need to fix everything. I just >>> want to get a better feel for the changes and what the implementation would >>> look like. >>> >>> thanks, >>> >>> Chris >>> >>> On 11/1/18 1:03 PM, JC Beyler wrote: >>> >>> Hi Chris, >>> >>> Thanks for going over my email :) >>> >>> So I skipped over the tracing part for clarity and striving to be brief. >>> But if we can accept: >>> debugeeClass = jni->FindClass(DEBUGEE_CLASS_NAME, >>> TRACE_JNI_CALL); >>> >>> and use a mechanism such as >>> debugeeClass = jni->FindClass(DEBUGEE_CLASS_NAME, >>> TRACE_JNI_CALL); >>> >>> it is actually easy to print out things like: >>> >> JNI FindClass with the following parameters from >>> test/hotspot/jtreg/vmTestbase/nsk/jvmti/SetTag/settag001/settag001.cpp:69: >>> >> "nsk/jvmti/SetTag/settag001" >>> ... >>> << JNI FindClass from >>> test/hotspot/jtreg/vmTestbase/nsk/jvmti/SetTag/settag001/settag001.cpp:69: >>> >>> Before the actual call to the method, allowing to have the full >>> NSK_*_VERIFY system. The hardest question is do we accept to go from: >>> >>> if (!NSK_JNI_VERIFY(jni, (debugeeClass = >>> jni->FindClass(DEBUGEE_CLASS_NAME)) != NULL)) { >>> nsk_jvmti_setFailStatus(); >>> return; >>> } >>> >>> >>> to: >>> >>> #define TRACE_JNI_CALL __LINE__, __FILE__ >>> ... >>> >>> ExceptionCheckingJniEnvPtr jni_wrapper(jni); >>> ... >>> debugeeClass = jni->FindClass(DEBUGEE_CLASS_NAME, >>> TRACE_JNI_CALL); >>> >>> What I would do if this is accepted is postpone the assignment >>> extraction and move the code to migrating the NSK*VERIFY macros to using >>> the exception wrapper and then moving the assignments will be easier and a >>> nop from a debug printout point of view. >>> >>> Thanks, >>> Jc >>> >>> >>> >>> On Thu, Nov 1, 2018 at 12:01 PM Chris Plummer <chris.plum...@oracle.com> >>> wrote: >>> >>>> On 11/1/18 9:53 AM, JC Beyler wrote: >>>> >>>> Hi all, >>>> >>>> Sorry this is a bit of a long reply to myself but I've tried to see >>>> what we have, what we could have, is it better. Here is my analysis of how >>>> to keep the information we currently provide when a test fails at a >>>> NSK*VERIFY point and how we could maintain the level of detail (and even >>>> expand) while still cleaning up the macros/assignments. >>>> >>>> I've been looking at this and am going to go through examples to >>>> provide alternatives :). For this, I'll use the SetTag test and will be >>>> forcing a failure on the line: >>>> >>>> if (!NSK_JNI_VERIFY(jni, (debugeeClass = >>>> jni->FindClass(DEBUGEE_CLASS_NAME)) != NULL)) { >>>> nsk_jvmti_setFailStatus(); >>>> return; >>>> } >>>> >>>> Without a change and with the verbose system set up for the test, the >>>> error message is: >>>> >>>> The following fake exception stacktrace is for failuire analysis. >>>> nsk.share.Fake_Exception_for_RULE_Creation: (settag001.cpp:65) >>>> (debugeeClass = jni->FindClass(DEBUGEE_CLASS_NAME)) != NULL >>>> at nsk_lvcomplain(nsk_tools.cpp:172) >>>> # ERROR: settag001.cpp, 65: (debugeeClass = >>>> jni->FindClass(DEBUGEE_CLASS_NAME)) != NULL >>>> # verified JNI assertion is FALSE >>>> # ERROR: agent_tools.cpp, 282: Debuggee status sync aborted because >>>> agent thread has finished >>>> >>>> I think you are missing something here. This appears to be the output >>>> from nsk_jni_lverify() when the condition indicates failure. However, I >>>> don't see the verbose tracing from nsk_ltrace(), which I think is more >>>> relevant because that's were you are likely to want to see the actual JNI >>>> or JVMTI call being made. >>>> >>>> #define NSK_JNI_VERIFY(jni, action) \ >>>> (nsk_ltrace(NSK_TRACE_BEFORE,__FILE__,__LINE__,"%s\n",#action), \ >>>> nsk_jni_lverify(NSK_TRUE,jni,action,__FILE__,__LINE__,"%s\n",#action)) >>>> >>>> >>>> (Note the typo for failuire, I created JDK-8213246 to fix it). >>>> >>>> With my proposed change to remove the assignment, the code becomes: >>>> debugeeClass = jni->FindClass(DEBUGEE_CLASS_NAME); >>>> if (!NSK_JNI_VERIFY(jni, debuggeeClass != NULL)) { >>>> nsk_jvmti_setFailStatus(); >>>> return; >>>> } >>>> >>>> The following fake exception stacktrace is for failuire analysis. >>>> nsk.share.Fake_Exception_for_RULE_Creation: (settag001.cpp:66) >>>> debugeeClass != NULL >>>> at nsk_lvcomplain(nsk_tools.cpp:172) >>>> # ERROR: settag001.cpp, 66: debugeeClass != NULL >>>> # verified JNI assertion is FALSE >>>> # ERROR: agent_tools.cpp, 282: Debuggee status sync aborted because >>>> agent thread has finished >>>> STDERR: >>>> >>>> In this case, we do lose that the failure seems to have happened in >>>> FindClass, we need to look at the code. >>>> >>>> I think losing the actual call info in the trace for failures is fine. >>>> All we really need is the line number info. I don't think anyone is going >>>> to be trying to debug the root cause based on trace message, which is no >>>> different than the source that can be viewed given the line number info. >>>> >>>> But back to my point above, if you enable tracing, seeing which JVMTI >>>> and JNI calls are being made in the trace output could be useful. You could >>>> scan all logs and see what JVMTI and JNI calls were made, and how often. >>>> Possibly useful for coverage analysis of the tests. However, I don't >>>> consider this critical, and am not opposed to losing it in order to make >>>> the code more readable. >>>> >>>> In any case, a solution would be to have a wrapper script like >>>> NSK_JNI_VERIFY, but just for the purpose of tracing, not error checking: >>>> >>>> debugeeClass = >>>> NSK_JNI_WRAPPER(jni->FindClass(DEBUGEE_CLASS_NAME)); >>>> if (!NSK_JNI_VERIFY(jni, debuggeeClass != NULL)) { >>>> nsk_jvmti_setFailStatus(); >>>> return; >>>> } >>>> >>>> And NSK_JNI_WRAPPER would just to the tracing and execute the passed in >>>> action. >>>> >>>> >>>> However, the ExceptionJNIWrapper that I implemented a little while ago >>>> will provide this information: >>>> FATAL ERROR in native method: FindClass : Return is NULL >>>> >>>> As I mentioned above, I don't consider the API that failed to be all >>>> that useful in error output as long as we have the line number info. At >>>> best maybe it helps identify two separate failures as being the same if the >>>> line numbers were to change. >>>> >>>> >>>> which is not sufficient to really figure out where this happened and >>>> what were the arguments. But we could extend the ExceptionJNIWrapper to >>>> have each JNI call >>>> allow two optional arguments and do this: >>>> >>>> ... >>>> // For tracing purposes. >>>> #define TRACE_JNI_CALL __LINE__, __FILE__ >>>> ... >>>> >>>> ExceptionCheckingJniEnvPtr jni_wrapper(jni); >>>> ... >>>> debugeeClass = jni->FindClass(DEBUGEE_CLASS_NAME, >>>> TRACE_JNI_CALL); >>>> >>>> Where now the JNI call looks "almost" like non-test code and a real JNI >>>> call but with just that optional macro added. Then the >>>> ExceptionCheckingJniEnvPtr can be modified to print out: >>>> >>>> FATAL ERROR in native method: JNI method FindClass : Return is NULL >>>> from >>>> test/hotspot/jtreg/vmTestbase/nsk/jvmti/SetTag/settag001/settag001.cpp:69 >>>> >>>> Which now contains all the same information except what the line looks >>>> like. I'm not sure that is useful, instead, if we wanted to go one step >>>> further, we could add prints to all parameters that are passed in the JNI >>>> methods via the wrapper, which would >>>> then look like something like: >>>> >>>> JNI method FindClass was called from >>>> test/hotspot/jtreg/vmTestbase/nsk/jvmti/SetTag/settag001/settag001.cpp:69 >>>> with these parameters: >>>> "nsk/jvmti/SetTag/settag001" >>>> FATAL ERROR in native method: JNI method FindClass : Return is NULL >>>> from >>>> test/hotspot/jtreg/vmTestbase/nsk/jvmti/SetTag/settag001/settag001.cpp:69 >>>> >>>> I'm not familiar with you ExceptionJNIWrapper changes. The error output >>>> above looks fine, but as I mentioned earlier, I'm ok with just the source >>>> line number info. >>>> >>>> thanks, >>>> >>>> Chris >>>> >>>> >>>> Let me know what you think. >>>> >>>> Thanks, >>>> Jc >>>> >>>> >>>> On Wed, Oct 31, 2018 at 1:54 PM JC Beyler <jcbey...@google.com> wrote: >>>> >>>>> @Claes: you are right, I did not do a grep such as "if.* =$"; by >>>>> adding the space instead of the $, I missed a few :) >>>>> >>>>> I've been meaning to ask if we could deprecate these anyway. Are these >>>>> really being used? And if so, are we saying everything here is useful: >>>>> - Line/File + JNI call? >>>>> >>>>> I ask because I'd like to deprecate the NSK_VERIFY macros but the >>>>> LINE/FILE is a bit annoying to deprecate. >>>>> >>>>> I'd rather be able to remove them entirely but we could do an >>>>> alternative and migrate the NSK_VERIFY to: >>>>> >>>>> testedFieldID = jni->GetStaticFieldID(testedClass, FIELD_NAME, >>>>> FIELD_SIGNATURE); >>>>> if (!testedFieldID) { >>>>> >>>>> where the print out of the jni method and argument values can still be >>>>> done in the JNI wrapper I added (ExceptionCheckingJniEnv.cpp) so we'd have >>>>> the printout of the calls but not the line and filename from where the >>>>> call >>>>> was done. >>>>> >>>>> If lines and filenames are really important, then we could do >>>>> something like: >>>>> testedFieldID = NSK_TRACE(jni->GetStaticFieldID(testedClass, >>>>> FIELD_NAME, FIELD_SIGNATURE)); >>>>> if (!testedFieldID) { >>>>> >>>>> Which would add a line for which line/file is doing the JNI call. The >>>>> verify part can go into the wrapper I was talking about >>>>> (ExceptionCheckingJniEnv.cpp). >>>>> >>>>> Thanks, >>>>> Jc >>>>> >>>>> >>>>> On Wed, Oct 31, 2018 at 11:52 AM Chris Plummer < >>>>> chris.plum...@oracle.com> wrote: >>>>> >>>>>> On 10/31/18 11:30 AM, serguei.spit...@oracle.com wrote: >>>>>> > It prints the FILE/LINE which is enough to identify the error point. >>>>>> Yes, but it also prints the JNI calls. >>>>>> > But I agree that doing the assignments within the NSK_JNI_VERIFY >>>>>> was >>>>>> > intentional as it gives more context. >>>>>> > From the other hand it make the code ugly and less readable. >>>>>> > Not sure, what direction is better to go. >>>>>> Agreed. Somewhat of a tossup now as to whether or not this change >>>>>> should >>>>>> be done. I'm fine either way. >>>>>> >>>>>> Chris >>>>>> > >>>>>> > Thanks, >>>>>> > Serguei >>>>>> > >>>>>> > >>>>>> > On 10/31/18 11:21, Chris Plummer wrote: >>>>>> >> Hi Claes, >>>>>> >> >>>>>> >> It's good that you brought this up. NSK_JNI_VERIFY is always "on", >>>>>> >> but moving the assignment outside of it does slightly change the >>>>>> >> behavior of the macro (although the code still executes >>>>>> "correctly"): >>>>>> >> >>>>>> >> /** >>>>>> >> * Execute action with JNI call, check result for true and >>>>>> >> * pending exception and complain error if required. >>>>>> >> * Also trace action execution if tracing mode enabled. >>>>>> >> */ >>>>>> >> #define NSK_JNI_VERIFY(jni, action) \ >>>>>> >> (nsk_ltrace(NSK_TRACE_BEFORE,__FILE__,__LINE__,"%s\n",#action), \ >>>>>> >> >>>>>> nsk_jni_lverify(NSK_TRUE,jni,action,__FILE__,__LINE__,"%s\n",#action)) >>>>>> >> >>>>>> >> So you will no longer see the JNI call in the trace or error >>>>>> output. >>>>>> >> You will just see the comparison to the JNI result, which gives no >>>>>> >> context as to the source of the result. So I'm now starting to >>>>>> think >>>>>> >> that doing the assignments within the NSK_JNI_VERIFY was >>>>>> intentional >>>>>> >> so we would see the JNI call in the trace output. >>>>>> >> >>>>>> >> Chris >>>>>> >> >>>>>> >> On 10/31/18 3:16 AM, Claes Redestad wrote: >>>>>> >>> Hi, >>>>>> >>> >>>>>> >>> here's a case that your script seems to miss: >>>>>> >>> >>>>>> >>> >>>>>> http://cr.openjdk.java.net/%7Ejcbeyler/8213003/webrev.00/test/hotspot/jtreg/vmTestbase/nsk/jvmti/GetClassLoaderClasses/clsldrclss002/clsldrclss002.cpp.udiff.html >>>>>> >>> >>>>>> >>> >>>>>> >>> if (!NSK_JNI_VERIFY(jni, (testedFieldID = >>>>>> >>> jni->GetStaticFieldID(testedClass, FIELD_NAME, >>>>>> >>> FIELD_SIGNATURE)) != NULL)) >>>>>> >>> >>>>>> >>> I'd note that with some of your changes here you're >>>>>> unconditionally >>>>>> >>> executing logic outside of NSK_JNI_VERIFY macros. Does care need >>>>>> be >>>>>> >>> taken to wrap the code blocks in equivalent macros/ifdefs? Or are >>>>>> >>> the NSK_JNI_VERIFY macros always-on in these tests (and >>>>>> essentially >>>>>> >>> pointless)? >>>>>> >>> >>>>>> >>> /Claes >>>>>> >>> >>>>>> >>> On 2018-10-31 05:42, JC Beyler wrote: >>>>>> >>>> Hi all, >>>>>> >>>> >>>>>> >>>> I worked on updating my script and handling more assignments so >>>>>> I >>>>>> >>>> redid a second pass on the same files to get all the cases. Now, >>>>>> on >>>>>> >>>> those files the regex "if.* = " no longer shows any cases we >>>>>> would >>>>>> >>>> want to fix. >>>>>> >>>> >>>>>> >>>> Could I get a review for this webrev: >>>>>> >>>> Webrev: http://cr.openjdk.java.net/~jcbeyler/8213003/webrev.00/ >>>>>> >>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8213003 >>>>>> >>>> >>>>>> >>>> I tested this on my dev machine by passing all the tests that >>>>>> were >>>>>> >>>> modified. >>>>>> >>>> >>>>>> >>>> Thanks! >>>>>> >>>> Jc >>>>>> >>> >>>>>> >> >>>>>> >> >>>>>> > >>>>>> >>>>>> >>>>>> >>>>> >>>>> -- >>>>> >>>>> Thanks, >>>>> Jc >>>>> >>>> >>>> >>>> -- >>>> >>>> Thanks, >>>> Jc >>>> >>>> >>>> >>> >>> -- >>> >>> Thanks, >>> Jc >>> >>> >>> >> >> -- >> >> Thanks, >> Jc >> >> >> > > -- > > Thanks, > Jc > > > > > -- Thanks, Jc
