Re: RFR: 8227269: Slow class loading when running JVM in debug mode

[serguei.spit...@oracle.com]

On 3/24/20 14:47, Chris Plummer wrote:

On 3/24/20 2:46 PM, serguei.spit...@oracle.com wrote:

On 3/24/20 14:39, Chris Plummer wrote:

On 3/24/20 1:45 PM, Roman Kennke wrote:

I assume JVMTI maintains separate tagging data for each agent so having two agents doing tagging won't result in confusion. I didn't actually find this in the spec. Would be nice to confirm that it is the case. However, your implementation does seem to conflict with other uses of

tagging in the debug agent:

The tagging data is per-jvmtiEnv. We create and use our own env (private to class-tracking), so this wouldn't conflict with other uses of tags. Could it be a problem that we have a single trackingEnv per JVM, though?

/me scratches head.

Ok. This is an area I'm not familiar with, but the spec does say:

"Each call to GetEnv creates a new JVM TI connection and thus a new JVM

TI environment."

So it looks like what you are doing should be ok. I still think you have

a bug where you are not deallocating signatures of classes that are
unloaded. If you think otherwise please point out where this is done.

Signatures that make it out of processUnloading() are deallocated in
eventHandler.c, in synthesizeUnload(), right after it has been used.

http://hg.openjdk.java.net/jdk/jdk/file/b9562cc25fc0/src/jdk.jdwp.agent/share/native/libjdwp/eventHandler.c#l527

Ok. Good to know. Not the best of designs, but that's not your fault. I'll make another pass over the changes, but I think in general it looks good. I don't think I've seen another reviewer yet, so hopefully someone jumps in.

As I understand, Roman already resolved my previous comments.
So, I will do another pass for v6.

I think it's pretty much a rewrite since you last reviewed it.

Yes, I'm expecting this as some performance related issues were discovered.

Thanks,
Serguei

Chris

Thanks,
Serguei

Chris

Pending signatures on debug-agent-disconnect are deallocated in
classTrack.c, in the reset() routine.

Thanks,
Roman

thanks,

Chris

What would cause classTrack_addPreparedClass() to be called for a Class you've already seen? I don't understand the need for the "tag != 0l"

check.

It's probably not needed, may be a left-over from previous installments of this implementation. I will check it, and turn into an assert or so.

Thanks,
Roman

thanks,

Chris

On 3/20/20 12:52 PM, Chris Plummer wrote:

On 3/20/20 8:30 AM, Roman Kennke wrote:

I believe I came up with a much simpler solution that also solves the

problems of the existing one, and the ones I proposed earlier.

It turns out that we can take advantage of the fact that we can use

*anything* as tags in JVMTI, even pointers to stuff (this is
explicitely

mentioned in the JVMTI spec). This means we can simply stick a pointer

to the signature of a class into the tag, and pull it out again
when we
get notified that the class gets unloaded.

This means we don't need an extra data-structure to keep track of

classes and signatures, and it also makes the story around locking *much* simpler. Performance-wise this is O(1), i.e. no scanning of all classes needed (as in the current implementation) and no searching of

table needed (like in my previous attempts).

Please review this new revision:
http://cr.openjdk.java.net/~rkennke/JDK-8227269/webrev.06/

I'll have a look at this.

(Notice that there still appears to be a performance bottleneck with class-unloading when an actual debugger is attached. This doesn't seem to be related to the classTrack.c implementation though, but looks

like

a consequence of getting all those class-unload notifications over the wire. My testcase generates 1000s of them, and it's clogging up the

buffers.)

At least this is only a one-shot hit when the classes are unloaded,

and the performance hit is based on the number of classes being

unloaded. The main issue is happening every GC, and is O(n) where n is

the number of loaded classes.

I am not sure why jdb needs to enable class-unload listener always. A

simple hack disables it, and performance is brilliant, even when
jdb is
attached:

http://cr.openjdk.java.net/~rkennke/disable-jdk-class-unload.patch

This is JDI, not jdb. It looks like it needs ClassUnload events so it

can maintain typesBySignature, which is used by public APIs like

allClasses(). So we have caching of loaded classes both in the debug

agent and in JDI.

Chris

But this is not in the scope of this bug.)

Roman


On 3/16/20 8:05 AM, serguei.spit...@oracle.com wrote:

Sorry, forgot to complete my comments at the end (see below).


On 3/15/20 23:57, serguei.spit...@oracle.com wrote:

Hi Roman,

Thank you for the update and sorry for the latency in review.

Some comments are below.

http://cr.openjdk.java.net/~rkennke/JDK-8227269/webrev.05/src/jdk.jdwp.agent/share/native/libjdwp/classTrack.c.frames.html

87 cbTrackingObjectFree(jvmtiEnv* jvmti_env, jlong tag)
     88 {
89 debugMonitorEnter(deletedSignatureLock);
90 if (currentClassTag == -1) {
91 // Class tracking not initialized, nobody's interested
92 debugMonitorExit(deletedSignatureLock);
93 return;
     94     }
Just a question:

     Q1: Should the ObjectFree events be disabled for the jvmtiEnv

that does
         the class tracking if class tracking has not been
initialized?

70 static jlong currentClassTag; I'm thinking if the name is
better to
be something like: lastClassTag or highestClassTag.

99 KlassNode* klass = *klass_ptr;
100 102 while (klass != NULL && klass->klass_tag != tag) { 103
klass_ptr = &klass->next; 104 klass = *klass_ptr;
105 } 106 if (klass != NULL || klass->klass_tag != tag) { //
klass not
found - ignore.
107 debugMonitorExit(deletedSignatureLock);
108 return;
    109     }
    It seems to me, something is wrong in the condition at L106
above.
    Should it be? :
       if (klass == NULL || klass->klass_tag != tag)

    Otherwise, how can the second check ever work correctly as the

return
will always happen when (klass != NULL)?

    There are several places in this file with the the indent:
90 if (currentClassTag == -1) {
91 // Class tracking not initialized, nobody's interested
92 debugMonitorExit(deletedSignatureLock);
93 return;
     94     }
    ...
152 if (currentClassTag == -1) {
153 // Class tracking not initialized yet, nobody's interested
154 debugMonitorExit(deletedSignatureLock);
155 return;
    156     }
    ...
161 if (error != JVMTI_ERROR_NONE) {

162 EXIT_ERROR(error, "Unable to GetTag with class trackingEnv");

    163     }
164 if (tag != 0l) {
165 debugMonitorExit(deletedSignatureLock);
166 return; // Already added
    167     }
    ...
281 cleanDeleted(void *signatureVoid, void *arg)
282 {
283 char* sig = (char*)signatureVoid;
284 jvmtiDeallocate(sig);
285 return JNI_TRUE;
    286 }
    ...
    291 void
    292 classTrack_reset(void)
    293 {
294 int idx;
295 debugMonitorEnter(deletedSignatureLock);
296
297 for (idx = 0; idx < CT_SLOT_COUNT; ++idx) {
298 KlassNode* node = table[idx];
299 while (node != NULL) {
300 KlassNode* next = node->next;
301 jvmtiDeallocate(node->signature);
302 jvmtiDeallocate(node);
303 node = next;
304 }
305 }
306 jvmtiDeallocate(table);
307
308 bagEnumerateOver(deletedSignatureBag, cleanDeleted, NULL);
309 bagDestroyBag(deletedSignatureBag);
310
311 currentClassTag = -1;
312
313

(void)JVMTI_FUNC_PTR(trackingEnv,DisposeEnvironment)(trackingEnv);

314 trackingEnv = NULL;
315
316 debugMonitorExit(deletedSignatureLock);

Could you, please, fix several comments below?
63 * The JVMTI tracking env to keep track of klass tags, for
class-unloads
    The comma is not needed.
    Would it better to replace: klass tags => klass_tag's ?

73 * Lock to keep table, currentClassTag and deletedSignatureBag

consistent
    Maybe: Lock to guard ... or lock to keep integrity of ...

84 * Callback when classes are freed, Finds the signature and

remembers it in deletedSignatureBag. Would be better to use words

like

"store" or "record", "Find" should not start from capital letter:

Invoke the callback when classes are freed, find and record the
signature in deletedSignatureBag.

96 // Find deleted KlassNode 133 // Class tracking not initialized,

nobody's interested 153 // Class tracking not initialized yet,
nobody's interested 158 /* Check this is not a duplicate */
Missed dot

at the end. 106 if (klass != NULL || klass->klass_tag != tag) { //

klass not found - ignore. In opposite, dot is not needed as the
comment does not start from a capital letter. 111 // At this
point we
have the KlassNode corresponding to the tag
112 // in klass, and the pointer to it in klass_node.

    The comment above can be better. Maybe, something like:
      " At this point, we found the KlassNode matching the klass
tag(and it is
linked).

113 // Remember the unloaded signature.

    Better: Record the signature of the unloaded class and unlink it.

Thanks,
Serguei

Thanks,
Serguei

On 3/9/20 05:39, Roman Kennke wrote:

Hello all,

Can I please get reviews of this change? In the meantime, we've

done

more testing and also field-/torture-testing by a customer who is

happy
now. :-)

Thanks,
Roman

Hi Serguei,

Thanks for reviewing!

I updated the patch to reflect your suggestions, very good!
It also includes a fix to allow re-connecting an agent after
disconnect,

namely move setup of the trackingEnv and deletedSignatureBag to

_activate() to ensure have those structures after re-connect.

http://cr.openjdk.java.net/~rkennke/JDK-8227269/webrev.05/

Let me know what you think!
Roman

Hi Roman,

Thank you for taking care about this scalability issue!

I have a couple of quick comments.

http://cr.openjdk.java.net/~rkennke/JDK-8227269/webrev.04/src/jdk.jdwp.agent/share/native/libjdwp/classTrack.c.frames.html

72 /*
73 * Lock to protect deletedSignatureBag
74 */
75 static jrawMonitorID deletedSignatureLock; 76 77 /*
78 * A bag containing all the deleted classes' signatures.
Must be
accessed under
79 * deletedTagLock,
     80  */
81 struct bag* deletedSignatureBag;

     The comments contradict to each other.
     I guess, the lock name at line 79 has to be
deletedSignatureLock
instead of deletedTagLock.
     Also, comma at the end must be replaced with dot.


101 // Tag not found? Ignore.
102 if (klass == NULL) {
103 debugMonitorExit(deletedSignatureLock);
104 return;
105 }
    106
107 // Scan linked-list.
108 jlong found_tag = klass->klass_tag;
109 while (klass != NULL && found_tag != tag) {
110 klass_ptr = &klass->next;
111 klass = *klass_ptr;
112 found_tag = klass->klass_tag;
    113     }
114
115 // Tag not found? Ignore.
116 if (found_tag != tag) {
117 debugMonitorExit(deletedSignatureLock);
118 return;
    119     }

    The code above can be simplified, so that the lines 101-105

are not
needed anymore.
    It can be something like this:

// Scan linked-list.
while (klass != NULL && klass->klass_tag != tag) {
klass_ptr = &klass->next;
klass = *klass_ptr;
        }
if (klass == NULL || klass->klass_tag != tag) { // klass not
found - ignore.
debugMonitorExit(deletedSignatureLock);
return;
        }

It will take more time when I get a chance to look at the rest.

Thanks,
Serguei




On 12/21/19 13:24, Roman Kennke wrote:

Here comes an update that resolves some races that happen when

disconnecting an agent. In particular, we need to take the
lock on

basically every operation, and also need to check whether or not class-tracking is active and return an appropriate result (e.g.

an empty
list) when we're not.

Updated webrev:
http://cr.openjdk.java.net/~rkennke/JDK-8227269/webrev.04/

Thanks,
Roman

So, here comes the O(1) implementation:

- Whenever a class is 'prepared', it is registered with a tag,

and we
set-up a listener to get notified when it is unloaded.
- Prepared classes are kept in a datastructure that is a
table, which

each entry being the head of a linked-list of KlassNode*. The

table is

indexed by tag % slot-count, and then simply prepend the new

KlassNode*.
This is O(1) operation.

- When we get notified of unloading a class, we look up the

signature of

the reported tag in that table, and remember it in a bag. The

KlassNode*

is then unlinked from the table and deallocated. This is ~O(1)

operation

too, depending on the depth of the table. In my testcase which

hammered

the code with class-loads and unloads, I usually see depths of

like 2-3,
but not usually more. It should be ok.

- when processUnloads() gets called, we simply hand out that

bag, and
allocate a new one.
- I also added cleanup-code in classTrack_reset() to avoid
leaking the

signatures and KlassNode* etc when debug agent gets detached

and/or
re-attached (was missing before).

- I also added locks around data-structure-manipulation (was

missing
before).
- Also, I only activate this whole process when an actual
listener gets

registered on EI_GC_FINISH. This seems to happen right when

attaching a

jdb, not sure why jdb does that though. This may be something

to improve
in the future?

In my tests, the performance of class-tracking itself looks

really good.
The bottleneck now is clearly actual synthesizing the
class-unload
events. I don't see how this can be helped when the debug
agent asks for it?

Updated webrev:
http://cr.openjdk.java.net/~rkennke/JDK-8227269/webrev.03/

Please let me know what you think of it.

Thanks,
Roman

Alright, the perfectionist in me got me. I am implementing

the even more

efficient ~O(1) class tracking. Please hold off reviewing for

now.

Thanks,Roman

    Hi Chris,

I'll have a look at this, although it might not be for a

few days. In
the meantime, maybe you can describe your new
implementation in

classTrack.c so it's easier to look through the changes.

Sure.

The purpose of this class-tracking is to be able to
determine the
signatures of unloaded classes when GC/class-unloading
happened, so that
we can generate the appropriate JDWP event.

The current implementation does so by maintaining a table of

currently

prepared classes by building that table when classTrack is

initialized,

and then add new classes whenever a class gets loaded. When

unloading

occurs, that cache is rebuilt into a new table, and compared

with the

old table, and whatever is in the old, but not in the new

table gets
returned. The problem is that when GCs happen frequently
and/or many
classes get loaded+unloaded, this amounts to
O(classCount*gcCount)
complexity.

The new implementation keeps a linked-list of prepared
classes, and also
tracks unloads via the listener cbTrackingObjectFree().
Whenever an

unload/GC occurs, the list of prepared classes is scanned,

and classes
that are also in the deletedTagBag are unlinked (thus
maintaining the
prepared-classes-list) and its signature put in the list
that gets returned.

The implementation is not perfect. In order to determine
whether or not
a class is unloaded, it needs to scan the deletedTagBag.
That process is

therefore still O(unloadedClassCount). The assumption here

is that
unloadedClassCount << classCount. In my experiments this
seems to be
true, and also reasonable to expect.

(I have some ideas how to improve the implementation to
~O(1) but it
would be considerably more complex: have to maintain a
(hash)table that

maps tags -> KlassNode*, unlink them directly upon unload,

and build the

unloaded-signatures list there, but I don't currently see

that it's
worth the effort).

In addition to all that, this process is only activated when

there's an
actual listener registered for EI_GC_FINISH.

Thanks,
Roman

Chris

On 12/18/19 5:05 AM, Roman Kennke wrote:

Hello all,

Issue:
https://bugs.openjdk.java.net/browse/JDK-8227269

I am proposing what amounts to a rewrite of classTrack.c.

It avoids
throwing away the class cache on GC, and instead keeps
track of
loaded/unloaded classes one-by-one.

In addition to that, it avoids this whole dance until an

agent
registers interest in EI_GC_FINISH.

Webrev:

http://cr.openjdk.java.net/~rkennke/JDK-8227269/webrev.01/

Testing: manual testing of provided test scenarios and
timing.

Eg with the testcase provided here:
https://bugzilla.redhat.com/show_bug.cgi?id=1751985

I am getting those numbers:
unpatched: no debug: 84s with debug: 225s
patched:   no debug: 85s with debug: 95s

I also tested successfully through jdk/submit repo

Can I please get a review?

Thanks,
Roman