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
