Closed Bug 475456 Opened 16 years ago Closed 16 years ago

GMail spends a lot of time in the trace recorder

Categories

(Core :: JavaScript Engine, defect)

Product:
Core
Component:
JavaScript Engine
Platform:
x86
macOS
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED DUPLICATE of bug 475127

People

(Reporter: roc, Unassigned)

Details

My trunk debug build (no more than a couple of days old) is being really slow in GMail. Actions like "Archive" that should be fast take several seconds to complete. It's possible that GMail has changed, but turning off the JIT fixes it completely. I did some poor-man's debugging with gdb and consistently got stack traces implicating avmplus::List via TraceRecorder::addName:

#0  0xffff0f20 in __memcpy ()
#1  0x0031ddf7 in avmplus::List<nanojit::LIns*, (avmplus::ListElementType)0>::insert (this=0xa27024, index=28356, value=0xf31ccf8, count=1) at avmplus.h:605
#2  0x003322bd in avmplus::SortedMap<nanojit::LIns*, nanojit::LirNameMap::Entry*, (avmplus::ListElementType)1>::put (this=0xa27024, k=0xf31ccf8, v=0x27f41600) at avmplus.h:781
#3  0x0032e918 in nanojit::LirNameMap::addName (this=0xa26ff0, i=0xf31ccf8, name=0x27f415f0) at /Users/roc/mozilla-checkin/js/src/nanojit/LIR.cpp:1698
#4  0x0032ea2b in nanojit::LirNameMap::addName (this=0xa26ff0, i=0xf31ccf8, name=0x36f184 "eor") at /Users/roc/mozilla-checkin/js/src/nanojit/LIR.cpp:1705
#5  0x003163bb in TraceRecorder::addName (this=0x27ed1b50, ins=0xf31ccf8, name=0x36f184 "eor") at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1149
#6  0x00304474 in TraceRecorder::TraceRecorder (this=0x27ed1b50, cx=0xe3fbc00, _anchor=0x0, _fragment=0x8b00f50, ti=0x26230260, ngslots=30, globalTypeMap=0x9e8c7f0 "\004", stackTypeMap=0x286d3860 "", innermostNestedGuard=0x0, outerToBlacklist=0x0) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1062
#7  0x003046ec in TraceRecorder::TraceRecorder (this=0x27ed1b50, cx=0xe3fbc00, _anchor=0x0, _fragment=0x8b00f50, ti=0x26230260, ngslots=30, globalTypeMap=0x9e8c7f0 "\004", stackTypeMap=0x286d3860 "", innermostNestedGuard=0x0, outerToBlacklist=0x0) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1088
#8  0x003047a7 in js_StartRecorder (cx=0xe3fbc00, anchor=0x0, f=0x8b00f50, ti=0x26230260, ngslots=30, globalTypeMap=0x9e8c7f0 "\004", stackTypeMap=0x286d3860 "", expectedInnerExit=0x0, outer=0x0) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:2772
#9  0x00304fd6 in js_RecordTree (cx=0xe3fbc00, tm=0xf1103c, f=0x8b00f50, outer=0x0, demotes=0x0) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:3086
#10 0x00314db4 in js_MonitorLoopEdge (cx=0xe3fbc00, inlineCallCount=@0xbfff7738) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:3824
#11 0x0023d86d in js_Interpret (cx=0xe3fbc00) at /Users/roc/mozilla-checkin/js/src/jsinterp.cpp:3700

#0  0xffff0f14 in __memcpy ()
#1  0x0033214b in avmplus::List<nanojit::LirNameMap::Entry*, (avmplus::ListElementType)1>::insert (this=0xa27030, index=449448, value=0x290ec3d0, count=1) at avmplus.h:605
#2  0x003322dc in avmplus::SortedMap<nanojit::LIns*, nanojit::LirNameMap::Entry*, (avmplus::ListElementType)1>::put (this=0xa27024, k=0x2362bd04, v=0x290ec3d0) at avmplus.h:782
#3  0x0032e918 in nanojit::LirNameMap::addName (this=0xa26ff0, i=0x2362bd04, name=0x290ec3b0) at /Users/roc/mozilla-checkin/js/src/nanojit/LIR.cpp:1698
#4  0x0032ea2b in nanojit::LirNameMap::addName (this=0xa26ff0, i=0x2362bd04, name=0x36e799 "OP(&js_ObjectOps)") at /Users/roc/mozilla-checkin/js/src/nanojit/LIR.cpp:1705
#5  0x003163bb in TraceRecorder::addName (this=0x2a113c70, ins=0x2362bd04, name=0x36e799 "OP(&js_ObjectOps)") at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1149
#6  0x002fdc4c in TraceRecorder::map_is_native (this=0x2a113c70, map=0x2a12a3a0, map_ins=0x2362bcec, ops_ins=@0xbfff92a8, op_offset=16) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:5035
#7  0x002fdd5b in TraceRecorder::guardElemOp (this=0x2a113c70, obj=0x8a261e0, obj_ins=0x2362ba24, id=116388156, op_offset=16, vp=0xbfff934c) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:5481
#8  0x003023e4 in TraceRecorder::record_JSOP_GETELEM (this=0x2a113c70) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:6549
#9  0x0030b47e in TraceRecorder::monitorRecording (cx=0xdbc2e00, tr=0x2a113c70, op=JSOP_GETELEM) at jsopcode.tbl:176
#10 0x00235024 in js_Interpret (cx=0xdbc2e00) at /Users/roc/mozilla-checkin/js/src/jsinterp.cpp:2838

#0  0xffff0f1a in __memcpy ()
#1  0x0033214b in avmplus::List<nanojit::LirNameMap::Entry*, (avmplus::ListElementType)1>::insert (this=0xa27030, index=37748, value=0x24f0d5f0, count=1) at avmplus.h:605
#2  0x003322dc in avmplus::SortedMap<nanojit::LIns*, nanojit::LirNameMap::Entry*, (avmplus::ListElementType)1>::put (this=0xa27024, k=0xe820694, v=0x24f0d5f0) at avmplus.h:782
#3  0x0032e918 in nanojit::LirNameMap::addName (this=0xa26ff0, i=0xe820694, name=0x24f0d5e0) at /Users/roc/mozilla-checkin/js/src/nanojit/LIR.cpp:1698
#4  0x0032ea2b in nanojit::LirNameMap::addName (this=0xa26ff0, i=0xe820694, name=0x36e795 "ops") at /Users/roc/mozilla-checkin/js/src/nanojit/LIR.cpp:1705
#5  0x003163bb in TraceRecorder::addName (this=0x24d39d40, ins=0xe820694, name=0x36e795 "ops") at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1149
#6  0x002fdbaa in TraceRecorder::map_is_native (this=0x24d39d40, map=0xd817840, map_ins=0xe820688, ops_ins=@0xbfff6f9c, op_offset=16) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:5027
#7  0x002fe380 in TraceRecorder::test_property_cache (this=0x24d39d40, obj=0x78b8660, obj_ins=0x21f99cb8, obj2=@0xbfff7050, pcval=@0xbfff704c) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:5084
#8  0x002ff200 in TraceRecorder::record_JSOP_CALLPROP (this=0x24d39d40) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:8259
#9  0x00311e50 in TraceRecorder::monitorRecording (cx=0x212a5400, tr=0x24d39d40, op=JSOP_CALLPROP) at jsopcode.tbl:431
#10 0x00235024 in js_Interpret (cx=0x212a5400) at /Users/roc/mozilla-checkin/js/src/jsinterp.cpp:2838

#0  0xffff0f26 in __memcpy ()
#1  0x0033214b in avmplus::List<nanojit::LirNameMap::Entry*, (avmplus::ListElementType)1>::insert (this=0xa27030, index=280177, value=0x230d6230, count=1) at avmplus.h:605
#2  0x003322dc in avmplus::SortedMap<nanojit::LIns*, nanojit::LirNameMap::Entry*, (avmplus::ListElementType)1>::put (this=0xa27024, k=0xe9bbd30, v=0x230d6230) at avmplus.h:782
#3  0x0032e918 in nanojit::LirNameMap::addName (this=0xa26ff0, i=0xe9bbd30, name=0x230d6220) at /Users/roc/mozilla-checkin/js/src/nanojit/LIR.cpp:1698
#4  0x0032ea2b in nanojit::LirNameMap::addName (this=0xa26ff0, i=0xe9bbd30, name=0xbfff7490 "$Rka.f") at /Users/roc/mozilla-checkin/js/src/nanojit/LIR.cpp:1705
#5  0x003163bb in TraceRecorder::addName (this=0x20eec930, ins=0xe9bbd30, name=0xbfff7490 "$Rka.f") at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1149
#6  0x002ea2ce in TraceRecorder::import (this=0x20eec930, base=0xe9bbbc8, offset=-96, p=0x2157dabc, t=@0xffd2e66, prefix=0x36c4a1 "vars", index=1, fp=0x2157da44) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1581
#7  0x002ea811 in TraceRecorder::import (this=0x20eec930, treeInfo=0x984e860, sp=0xe9bbbc8, ngslots=32, callDepth=0, globalTypeMap=0x8184700 "\004\004\004", stackTypeMap=0xffd2e60 "") at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1621
#8  0x003044bd in TraceRecorder::TraceRecorder (this=0x20eec930, cx=0x91bd200, _anchor=0x0, _fragment=0x86ce920, ti=0x984e860, ngslots=32, globalTypeMap=0x8184700 "\004\004\004", stackTypeMap=0xffd2e60 "", innermostNestedGuard=0x0, outerToBlacklist=0x0) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1065
#9  0x003046ec in TraceRecorder::TraceRecorder (this=0x20eec930, cx=0x91bd200, _anchor=0x0, _fragment=0x86ce920, ti=0x984e860, ngslots=32, globalTypeMap=0x8184700 "\004\004\004", stackTypeMap=0xffd2e60 "", innermostNestedGuard=0x0, outerToBlacklist=0x0) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:1088
#10 0x003047a7 in js_StartRecorder (cx=0x91bd200, anchor=0x0, f=0x86ce920, ti=0x984e860, ngslots=32, globalTypeMap=0x8184700 "\004\004\004", stackTypeMap=0xffd2e60 "", expectedInnerExit=0x0, outer=0x0) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:2772
#11 0x00304fd6 in js_RecordTree (cx=0x91bd200, tm=0xf1103c, f=0x86ce920, outer=0x0, demotes=0x0) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:3086
#12 0x00314db4 in js_MonitorLoopEdge (cx=0x91bd200, inlineCallCount=@0xbfff7bd8) at /Users/roc/mozilla-checkin/js/src/jstracer.cpp:3824
#13 0x0023d86d in js_Interpret (cx=0x91bd200) at /Users/roc/mozilla-checkin/js/src/jsinterp.cpp:3700

Here's part of the JS stack for the first stack trace:

(gdb) p ::DumpJSStack()
0 $1A(
DataRequestQueue info:
  1 data requests outstanding:
  Data request 0 started 0.624 seconds ago, data request, state=PROCESSED, has csrequest
Primary CsRequestQueue info:
  Queue state is READY
  No cs Requests outstanding
Out-of-band CsRequestQueue info:
  Queue state is ACTIVE
  2 cs requests outstanding:
, [object Object], "Out-of-band CsRequestQueue", "  ", 1233007604130) ["https://mail.google.com/mail/?ui=2&view=js&name=js&ver=tqhAa3scUpk.LG&am=R-AwhcT38CCJDd9i2R-0EcE&random=1232487308900":691]
    u = undefined
    n = undefined
    l = undefined
    j = 0
    h = [object Object],[object Object]
    this = [object Object]
1 $_A([object Object]) ["https://mail.google.com/mail/?ui=2&view=js&name=js&ver=tqhAa3scUpk.LG&am=R-AwhcT38CCJDd9i2R-0EcE&random=1232487308900":688]
    c = "  "
    b = 
DataRequestQueue info:
  1 data requests outstanding:
  Data request 0 started 0.624 seconds ago, data request, state=PROCESSED, has csrequest
Primary CsRequestQueue info:
  Queue state is READY
  No cs Requests outstanding
Out-of-band CsRequestQueue info:
  Queue state is ACTIVE
  2 cs requests outstanding:

    a = 1233007604130
    this = [object Object]
2 $Lb(a = [object Object]) ["https://mail.google.com/mail/?ui=2&view=js&name=js&ver=tqhAa3scUpk.LG&am=R-AwhcT38CCJDd9i2R-0EcE&random=1232487308900":139]
    this = [object Object]
3 Oba(b = [object Object], a = [object Object]) ["https://mail.google.com/mail/?ui=2&view=js&name=js&ver=tqhAa3scUpk.LG&am=R-AwhcT38CCJDd9i2R-0EcE&random=1232487308900":52]
    c = undefined
    this = [object Window @ 0x87e11d0 (native @ 0x87e0030)]
4 ve([object Object], "drqchanged", false, [object Object]) ["https://mail.google.com/mail/?ui=2&view=js&name=js&ver=tqhAa3scUpk.LG&am=R-AwhcT38CCJDd9i2R-0EcE&random=1232487308900":51]
    u = [object Object]
    n = 0
    l = 1
    j = [object Object]
    h = 10
    this = [object Window @ 0x87e11d0 (native @ 0x87e0030)]
5 Pba([object Object], [object Object]) ["https://mail.google.com/mail/?ui=2&view=js&name=js&ver=tqhAa3scUpk.LG&am=R-AwhcT38CCJDd9i2R-0EcE&random=1232487308900":53]
    x = [object Object]
    u = undefined
    n = undefined
    l = true
    j = false
    this = [object Window @ 0x87e11d0 (native @ 0x87e0030)]
6 $hc(a = "drqchanged") ["https://mail.google.com/mail/?ui=2&view=js&name=js&ver=tqhAa3scUpk.LG&am=R-AwhcT38CCJDd9i2R-0EcE&random=1232487308900":151]
    this = [object Object]
7 $GD(a = [object Object]) ["https://mail.google.com/mail/?ui=2&view=js&name=js&ver=tqhAa3scUpk.LG&am=R-AwhcT38CCJDd9i2R-0EcE&random=1232487308900":733]
    this = [object Object]
This is debug only, a know regression in consolidating LIR buffers, resulting in a big shared name map nanojit thingie with non-constant lookup time.

/be
Flags: blocking1.9.1?
Yeah, I just noticed that TraceRecorder::addName is only non-trivial in debug builds. Still, it sucks for those of us trying to dogfood with debug builds.
Status: NEW → RESOLVED
Closed: 16 years ago
Resolution: --- → DUPLICATE
(In reply to comment #3)
> 
> *** This bug has been marked as a duplicate of bug 457127 ***

Wrong bug number?

/be
Flags: blocking1.9.1?
You need to log in before you can comment on or make changes to this bug.