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
<mailto: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
<mailto: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
<mailto:chris.plum...@oracle.com>> wrote:
On 10/31/18 11:30 AM,
serguei.spit...@oracle.com
<mailto: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/
<http://cr.openjdk.java.net/%7Ejcbeyler/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
