81847 - jsdhash performs badly under repeated add+remove of same key

Status: VERIFIED FIXED

(Core :: JavaScript Engine, defect, P1)

Description

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

In looking at performance opening new windows, I noticed a large amount
of time being spent in SearchTable in jsdhash.c (3.5% of new window time 
when opening large numbers of windows).  It's being called (through 
JS_DHashTableOperate) from js_AddRootRT and js_RemoveRoot, which are
being called from AddRefing and Releasing XPCWrappedNative objects
(which I hope we can do less, but that's another issue).

These calls frequently add and remove the same object from the hashtable
hundreds of times, which causes buildup of entries that are marked as
removed.  Each time the entry is added and removed from the hashtable,
another entry marked as removed is added to the sequence of entries that
must be traversed before finding a free position to add the entry or
before finding the entry to remove it.  In other words, the number of
collisions needed to find the location for the entry increases by one
each time the entry is added and removed, until the entire table gets
reallocated.  (I've seen this build up to as many as 260 collisions just
opening a single new window.)

The best solution I can think of for this is to reserve one bit of the
JSDHashEntryHdr (i.e., the low or high bit of of keyHash) to mark
whether an attempt to add an entry collided with the entry being marked.
Then, when removing an entry, if the bit is not set, the entry can be
marked free rather than removed.  This would also reduce reallocations
of the table.

Comment 1

[Brendan Eich [:brendan]]

D'oh -- gordon and I talked about this scenario, and how to solve it with a
magic bit indicating that an entry has had no collisions.  Then the removed
entry could be recycled on add of the same key.

Definite 0.9.2 work.

/be

Comment 2

[Brendan Eich [:brendan]]

Attachment: proposed fix, please review and help test

Comment 3

[Brendan Eich [:brendan]]

Is this a hot-button issue for 0.9.1?

/be

Comment 4

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

When I tried that patch on my hyatt-branch opt build, I crashed on startup:

#0  0x4070bb74 in WrappedNativeProtoMarker ()
   from /builds/hyatt/obj/opt/dist/bin/components/libxpconnect.so
#1  0x4012ff32 in JS_DHashTableEnumerate ()
   from /builds/hyatt/obj/opt/dist/bin/libmozjs.so
#2  0x4070bc25 in XPCWrappedNativeScope::MarkAllWrappedNativesAndProtos ()
   from /builds/hyatt/obj/opt/dist/bin/components/libxpconnect.so
#3  0x406fa6e7 in XPCJSRuntime::GCCallback ()
   from /builds/hyatt/obj/opt/dist/bin/components/libxpconnect.so
#4  0x40b0bc4c in DOMGCCallback ()
   from /builds/hyatt/obj/opt/dist/bin/components/libjsdom.so
#5  0x4013efcb in js_GC () from /builds/hyatt/obj/opt/dist/bin/libmozjs.so

Comment 5

[Brendan Eich [:brendan]]

dbaron mentioned this the other day; I'll get to it soon.

/be

Comment 6

[Brendan Eich [:brendan]]

Attachment: working patch, looking for reviews

Comment 7

[Brendan Eich [:brendan]]

Please ask me anything.  And test, test, test!

/be

Comment 8

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

It would be good to get some testing with the new version in both js and
xpcom/ds, although the current patch does work fine for me.

I think you would probably get further improved performance if you added
new entries on top of removed-entry sentinels by changing SearchTable
from checking:
  if (JS_DHASH_ENTRY_IS_FREE(entry)) {
to
  if (!JS_DHASH_ENTRY_IS_LIVE(entry)) {
and then in the JS_DHASH_ADD case of JS_DHashTableOperate, preserving
the collision flag when initializing the entry by, before calling
initEntry, doing:
  if (entry->keyHash & COLLISION_FLAG)
    keyHash |= COLLISION_FLAG;
Or is there some reason this wouldn't be safe, or would worsen
performance?

Comment 9

[Brendan Eich [:brendan]]

I pointed out to dbaron on irc #mozilla how SearchTable must exhaustively search
to the end of a double-hashed collision chain, for the given key.  It can't stop
at the first non-live (removed or free) entry.  But it could remember the first
removed entry on the chain, and return that, as dbaron proposes.  Then the
JS_DHashTableOperate JS_DHASH_ADD case could preserve COLLISION_FLAG from the
entry returned when filling in keyHash.

In the course of optimizing SearchTable in this way, I found a bug where the
collision flag for newEntry (which -- see the code -- is of course independent
of oldEntry->keyHash & COLLISION_FLAG) was not preserved when newEntry->keyHash
was initialized.

Patch coming up after some testing and metering.

/be

Comment 10

[Brendan Eich [:brendan]]

Nearly done, I've had no time to instrument and do A-B tests, and this shouldn't
hold up 0.9.4 (unless someone speaks quickly and convincingly).  I'll land it as
soon as 0.9.5 opens, after reporting results here.

/be

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

Brendan Eich <[e-mail]> writes:
>Can you re-profile after applying the latest patch in
>http://bugzilla.mozilla.org/show_bug.cgi?id=81847 ?  Thanks,

        On re-profile, JS_DHashTableOperate went from 20 with 3 direct hits
to 4 with 1 direct hit.  Thus the savings would be roughly 16/367 or
4.4% of the time to open 20 windows.  Big win!

Flat data before:

Total hit count: 367
Count %Total  Function Name
 17   4.6     SearchTable
 16   4.4     js_Mark
  7   1.9     chunk_alloc
  6   1.6     js_MarkGCThing
...
  3   0.8     JS_DHashTableOperate

Flat data after:
Total hit count: 358
Count %Total  Function Name
 11   3.1     js_MarkGCThing
 11   3.1     js_Mark
 10   2.8     __pthread_alt_unlock
  8   2.2     pthread_mutex_trylock
  7   2.0     chunk_alloc
  7   2.0     js_MarkScript
  6   1.7     __libc_malloc
  6   1.7     nsCOMPtr_base::~nsCOMPtr_base(void)
  5   1.4     GetChar

Comment 12

[Brendan Eich [:brendan]]

I need some time to turn on metering and do that A-B test, but this patch looks
better and better for 0.9.4, once it shakes out on the trunk.  Cc'ing asa and
asking dbaron for their [e-mail] opinions.

/be

Comment 13

[Brendan Eich [:brendan]]

Attachment: latest patch: reclaims first removed/colliding entry on add

Comment 14

[Brendan Eich [:brendan]]

Upping severity, targeting at 0.9.4.

/be

Comment 15

[Brendan Eich [:brendan]]

Attachment: same semantics as last patch, but better control flow in SearchTable (clearer and more efficient, assuming hits are more common that collisions)

Comment 16

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Comment on attachment 48181 [details] [diff] [review]
same semantics as last patch, but better control flow in SearchTable (clearer and more efficient, assuming hits are more common that collisions)

r=dbaron

Comment 17

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

I've been running with the new patch for a few hours (on a pre-branch build),
and I've crashed two or three times.  I don't think that's a good sign.

Comment 18

[Brendan Eich [:brendan]]

crashed where?  Patch to blame how?  Say more, words and backtraces and stuff
good (grunt!).

/be

Comment 19

[Randell Jesup [:jesup] (needinfo me)]

I ran with the patch a fair bit (looking at jprofs) without problems before the
branch. We the crashed related by stack backtrace to this? I'll throw this into
my main build for more testing.

Comment 20

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

#3  <signal handler called>
#4  0x4006fad4 in SearchTable (table=0x81b4868, key=0x43a64020, 
    keyHash=1113587744, op=JS_DHASH_ADD)
    at /builds/seamonkey/mozilla/js/src/jsdhash.c:278
#5  0x4006fd67 in ChangeTable (table=0x81b4868, deltaLog2=1)
    at /builds/seamonkey/mozilla/js/src/jsdhash.c:375
#6  0x4006fef5 in JS_DHashTableOperate (table=0x81b4868, key=0x436f5a18, 
    op=JS_DHASH_ADD) at /builds/seamonkey/mozilla/js/src/jsdhash.c:430
#7  0x40e5c30c in XPCWrappedNativeProtoMap::Add(XPCWrappedNativeProto*) (
    this=0x81ab288, proto=0x436f5a18)
    at /builds/seamonkey/mozilla/js/src/xpconnect/src/xpcmaps.h:621
#8  0x40e49edf in WNProtoRemover(JSDHashTable*, JSDHashEntryHdr*, unsigned,
void*) (table=0x436d9960, hdr=0x43cdef68, number=0, arg=0x81ab288)
    at
/builds/seamonkey/mozilla/js/src/xpconnect/src/xpcwrappednativescope.cpp:620
#9  0x40070112 in JS_DHashTableEnumerate (table=0x436d9960, 
    etor=0x40e49eb0 <WNProtoRemover(JSDHashTable*, JSDHashEntryHdr*, unsigned,
void*)>, arg=0x81ab288) at /builds/seamonkey/mozilla/js/src/jsdhash.c:516
#10 0x40e5c725 in ClassInfo2WrappedNativeProtoMap::Enumerate(JSDHashOperator (*)
(JSDHashTable*, JSDHashEntryHdr*, unsigned, void*), void*) (this=0x436d9950, 
    f=0x40e49eb0 <WNProtoRemover(JSDHashTable*, JSDHashEntryHdr*, unsigned,
void*)>, arg=0x81ab288)
    at /builds/seamonkey/mozilla/js/src/xpconnect/src/xpcmaps.h:429
#11 0x40e49f4c in XPCWrappedNativeScope::RemoveWrappedNativeProtos() (
    this=0x436d9900)
    at
/builds/seamonkey/mozilla/js/src/xpconnect/src/xpcwrappednativescope.cpp:630
#12 0x40e0ff8e in nsXPConnect::InitClasses(JSContext*, JSObject*) (
    this=0x40e5c9a4, aJSContext=0x436d9630, aGlobalJSObj=0x43679218)
    at /builds/seamonkey/mozilla/js/src/xpconnect/src/nsXPConnect.cpp:373
...

(gdb) frame 4
#4  0x4006fad4 in SearchTable (table=0x81b4868, key=0x43a64020, 
    keyHash=1113587744, op=JS_DHASH_ADD)
    at /builds/seamonkey/mozilla/js/src/jsdhash.c:278
278	    if (JS_DHASH_ENTRY_IS_FREE(entry)) {
(gdb) p entry
$1 = (JSDHashEntryHdr *) 0x56a9ac60
(gdb) p *entry
Cannot access memory at address 0x56a9ac60
(gdb) p *table
$2 = {ops = 0x400e90a0, data = 0x0, hashShift = 0, sizeLog2 = 32, 
  entrySize = 8, entryCount = 4294967293, removedCount = 0, generation = 3, 
  entryStore = 0x43a9ab60 ""}
(gdb) p *(table->ops)
$4 = {allocTable = 0x4006f660 <JS_DHashAllocTable>, 
  freeTable = 0x4006f690 <JS_DHashFreeTable>, 
  getKey = 0x4006f720 <JS_DHashGetKeyStub>, 
  hashKey = 0x4006f740 <JS_DHashVoidPtrKeyStub>, 
  matchEntry = 0x4006f750 <JS_DHashMatchEntryStub>, 
  moveEntry = 0x4006f780 <JS_DHashMoveEntryStub>, 
  clearEntry = 0x4006f7b0 <JS_DHashClearEntryStub>, 
  finalize = 0x4006f7e0 <JS_DHashFinalizeStub>, initEntry = 0}
(gdb) p hash1
$5 = 1113587744
(gdb) p keyHash
$6 = 1113587744
(gdb) frame 5
#5  0x4006fd67 in ChangeTable (table=0x81b4868, deltaLog2=1)
    at /builds/seamonkey/mozilla/js/src/jsdhash.c:375
375	            newEntry = SearchTable(table, getKey(table, oldEntry),
(gdb) p oldLog2
$7 = 31
(gdb) p newLog2
$8 = 32
(gdb) p newCapacity
$9 = 1
(gdb) p oldCapacity
$10 = 2147483648
(gdb) frame 6
#6  0x4006fef5 in JS_DHashTableOperate (table=0x81b4868, key=0x436f5a18, 
    op=JS_DHASH_ADD) at /builds/seamonkey/mozilla/js/src/jsdhash.c:430
430	                table->entryCount + table->removedCount == size - 1) {
(gdb) p table->entryCount
$11 = 4294967293
(gdb) p table->removedCount
$12 = 0

Comment 21

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

4294967293 == -3

Comment 22

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

I suspect this would be fixed either by making the JS_DHASH_REMOVE case of
JS_DHashtableOperate should check JS_DHASH_ENTRY_IS_LIVE rather than
JS_DHASH_ENTRY_IS_BUSY or by making SearchTable only return |firstRemoved| if
|op == JS_DHASH_ADD|.

Comment 23

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

I'm going to run a bit with the change in SearchTable.  (I think it's better to
change it there because it affects which type of entry is returned by a failed
JS_DHASH_LOOKUP.)  That is, I changed:
            return firstRemoved ? firstRemoved : entry;
to
            return (firstRemoved && op == JS_DHASH_ADD) ? firstRemoved : entry;

(It might not be a bad idea to make the change in the JS_DHASH_REMOVE case as
well, though.)

Comment 24

[Brendan Eich [:brendan]]

Comment on attachment 48181 [details] [diff] [review]
same semantics as last patch, but better control flow in SearchTable (clearer and more efficient, assuming hits are more common that collisions)

Bad bad icky bad.

Comment 25

[Brendan Eich [:brendan]]

Attachment: fixed version of last patch (thanks, dbaron)

Comment 26

[Brendan Eich [:brendan]]

Here come some patches to instrument jsdhash.c and pldhash.c, and dump stacks
and stats at {JS,PL}_DHashTableFinish time.  I've also (based on early results
from this instrumentation) fixed a glaring cycle-sink in js_LookupProperty: the
cx->resolving JSDHashTable was being destroyed as soon as the outermost resolve
attempt unwound.  Now it lives till the context is destroyed.  This sames ~26000
JSDHashTable instances.

/be

Comment 27

[Brendan Eich [:brendan]]

Attachment: patch with js_LookupProperty perf fix and NS_TraceStack instrumentation

Comment 28

[Brendan Eich [:brendan]]

Attachment: diff -wu version of last patch

Comment 29

[Brendan Eich [:brendan]]

Attachment: jsdhash.bigdump for browser+mailnews+select-m.jseng-newsgroup, without the firstRemoved optimization in SearchTable

Comment 30

[Brendan Eich [:brendan]]

Attachment: pldhash.bigdump for browser+mailnews+select-m.jseng-newsgroup, without the firstRemoved optimization in SearchTable

Comment 31

[Brendan Eich [:brendan]]

Attachment: jsdhash.bigdump for browser+mailnews+select-m.jseng-newsgroup, with the firstRemoved optimization in SearchTable

Comment 32

[Brendan Eich [:brendan]]

Attachment: pldhash.bigdump for browser+mailnews+select-m.jseng-newsgroup, with the firstRemoved optimization in SearchTable

Comment 33

[Brendan Eich [:brendan]]

Cc'ing waterson.  With this awk script:

/^Double hashing statistics:$/    { instats = 1; }
/^ adds that made a new entry: 0/ { waste[stack[1]]++; }
/^[^ ]*/                          { if (!instats) stack[i++] = $0; }
/^$/                              { instats = 0; delete stack; i = 0; }
END {
    for (frame in waste) {
        print(waste[frame], frame);
    }
}

applied to the "with the firstRemoved optimization in SearchTable" attachments
above, I get these culprits of never-added-to {JS,PL}DHashTables:

1
ClassInfo2WrappedNativeProtoMap::~ClassInfo2WrappedNativeProtoMap(void)[/home/brendan/src/trunk/mozilla/dist/bin/components/libxpconnect.so
+0x5D0F8]

75
nsRuleNetwork::Finish(void)[/home/brendan/src/trunk/mozilla/dist/bin/components/libgkcontent.so
+0x3E57C2]
68
nsContentSupportMap::Finish(void)[/home/brendan/src/trunk/mozilla/dist/bin/components/libgkcontent.so
+0x3DCB73]
32
nsTemplateMap::Finish(void)[/home/brendan/src/trunk/mozilla/dist/bin/components/libgkcontent.so
+0x58FACB]

Sorry I blamed XPConnect in my last comment, although the population of its
JSDHashTables may be too low to justify hashing (haven't tweaked the awk script
to say more -- someone humiliate me by writing a does-it-all perl script,
please!).  It looks like the empty PLDHashTables in content-land are more
numerous by far.

/be

Comment 34

[Brendan Eich [:brendan]]

Urgh, that was not the awk script I meant.  Here it is:

/^Double hashing statistics:$/    { instats = 1; }
/^ adds that made a new entry: 0/ { if (match(stack[0], /DHashTableDestroy/)) {
                                      waste[stack[1]]++;
                                    } else {
                                      waste[stack[0]]++;
                                    }
                                  }
/^[^ ]*/                          { if (!instats) stack[i++] = $0; }
/^$/                              { instats = 0; delete stack; i = 0; }
END {
    for (frame in waste) {
        print(waste[frame], frame);
    }
}

/be

Comment 35

[John Bandhauer]

> Sorry I blamed XPConnect in my last comment

Huh? I missed that. The count of items that might go in to various xpconnect
hashtables is highly variable.

> ClassInfo2WrappedNativeProtoMap...

XPConnect makes one of these per global object. It does not know ahead of time
if there are going to be many different classes of objects in use or not. In the
current world that depends mostly on the level of DOM activity in the page. I
still anticipate more objects with nsIClassInfo in the future.

Also, jst might not mention it, but he was looking at the time spent rooting and
unrooting objects as a side effect of the caps code needing to repeatedly get at
the wrapped native of JSObjects. I pointed him at this bug. He saw a significant
improvement in the Quantify numbers due to the decreased malloc/free counts with
today's recent patch in place.

Comment 36

[Brendan Eich [:brendan]]

Looking for review and super-review on the latest patch
(http://bugzilla.mozilla.org/attachment.cgi?id=48527&action=view, edit your
comments and checkmarks with the patch manager, use the diff -wu if you prefer
it: http://bugzilla.mozilla.org/attachment.cgi?id=48528&action=edit).

/be

Comment 37

[Chris Waterson]

We used to assign, now we do a logical-or? Eh?

-            newEntry->keyHash = oldEntry->keyHash;
+            newEntry->keyHash =
+                oldEntry->keyHash | (newEntry->keyHash & COLLISION_FLAG);


Might be worth assert()-ing that |keyHash & COLLISION_FLAG == 0| upon entry into
SearchTable().

The rest looks okay to me. r/sr=waterson

Comment 38

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Comment on attachment 48528 [details] [diff] [review]
diff -wu version of last patch

r=dbaron on everything except the cx->resolving bits (jscntxt.c, jsobj.c), which I'd rather have someone who knows what it is review.  Also, you have a bit of merging in nsTraceMalloc.c to do before you check in. :-)

Comment 39

[Brendan Eich [:brendan]]

waterson: SearchTable does not set keyHash to claim the entry, so ChangeTable
must do so.  But it failed to preserve the new entry's collision flag.  Note
well that the old entry's collision flag is cleared to avoid confusion.

I didn't assert as you suggest because my tiny brain thought this file was small
enough to keep that invariant obvious, but look what happened.  Adding, patch
coming up.

/be

Comment 40

[Johnny Stenback (:jst)]

r/sr=jst for the jscntxt.c and jsobj.c changes.

Comment 41

[Brendan Eich [:brendan]]

Attachment: final patch, for the record

Comment 42

[Brendan Eich [:brendan]]

Comment on attachment 49009 [details] [diff] [review]
final patch, for the record

Urgh, nsTraceMalloc.c's TM_ENTER_MONITOR and TM_EXIT_MONITOR are not quite right.

/be

Comment 43

[Brendan Eich [:brendan]]

Attachment: final patch, dbaron please re-review nsTraceMalloc.c

Comment 44

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Comment on attachment 49010 [details] [diff] [review]
final patch, dbaron please re-review nsTraceMalloc.c

r=dbaron on the merged nsTraceMalloc.c changes (although there was
one place where you didn't change |#if XP_UNIX| to |#ifdef XP_UNIX|)

Comment 45

[Brendan Eich [:brendan]]

Checked into trunk.  Leaving open in case this is wanted on the 0.9.4 branch.

/be

Comment 46

[Brendan Eich [:brendan]]

"Nice move, Fokker!" - _Meet The Parents_

Seems I've regressed something horribly, as bug 99442 attests.  More in a bit.

/be

Comment 47

[Brendan Eich [:brendan]]

Attachment: cvs diff -wu of changes joined to the 0.9.4 branch

Comment 48

[Brendan Eich [:brendan]]

Cc'ing cathleen and dp.  The attachment 49308 [details] [diff] [review] contains all the fixes for this
bug and for bug 99442, joined to the MOZILLA_0_9_4_BRANCH.  If you guys can get
the PDT to approve this patch for checkin, I'll gladly do the deed.  You might
want to wait a few days for the trunk version of these changes to prove good --
I'm pretty sure it will, after today's fiasco led to well-reviewed and doubly
tested fixes.

/be

Comment 49

[Suresh Duddi (gone)]

In lay terms, how much perf improvement on new window will this provide ?

Comment 50

[Brendan Eich [:brendan]]

dp, see rjesup's before/after jprof hit counts and timing estimates in the
comment dated 2001-09-04 08:49.

/be

Comment 51

[Brendan Eich [:brendan]]

Attachment: diff -wu of changes joined to the 0.9.4 branch (nsTraceMalloc.[ch] trunk sync-up)

Comment 52

[grega]

I very interested in getting this on the branch.  Would one of you come to the
pit at noon tomorrow to discuss?  Marking nsbranch+ to get on the radar.

Comment 53

[Jaime Rodriguez, Jr.]

Pls update status of patch with "has-super-review".

5% gain is good, check it into the branch - PDT+.

Comment 54

[Brendan Eich [:brendan]]

Fix is on the MOZILLA_0_9_4_BRANCH.

/be

Comment 55

[Phil Schwartau]

Marking Verified -