847389 - pdf.js jpeg2000 decoder slow in firefox in comparison with chrome

Status: RESOLVED WORKSFORME

(Core :: JavaScript Engine, defect)

Description

[Yury Delendik (:yury)]

Here is only the jpx decoder portion of the pdf.js:

  http://async5.org/moz/jpx2/

Firefox 22 takes: 8113 msec
Chrome 27 takes: 3049 msec

Comment 1

[Boris Zbarsky [:bzbarsky]]

Hmm. Well over a third of the time is js::InternNonElementId.  

I also see a ton of IC updates, if I'm reading this right.

The JIT inspector says that the hot part (or at least a hot part) seems to be the significance propagation pass, maybe.

Comment 2

[Boris Zbarsky [:bzbarsky]]

Er, I meant InternNonIntElementId.

It looks like we get a ton of js::ToIdOperation calls on vales that are double jsvals... but represent integers.  A typical example:

$1 = (const 'JS::Value' &) @0x7fff5fbf5cc0: {
  data = {
    asBits = 4648726366143905792, 
    debugView = {
      payload47 = 26388279066624, 
      tag = 33031
    }, 
    s = {
      payload = {
        i32 = 0, 
        u32 = 0, 
        why = JS_ELEMENTS_HOLE
      }
    }, 
    asDouble = 627, 
    asPtr = 0x4083980000000000, 
    asWord = 4648726366143905792, 
    asUIntPtr = 4648726366143905792
  }
}
(gdb) p idval.isNumber()
$2 = true
(gdb) p idval.isDouble()
$3 = true
(gdb) p idval.toDouble()
$4 = 627

Converting such a value to an id seems to involve converting it to a string then converting the string to an atom and then converting the atom to an id... or something.

It's not clear to me whether ToIdOperation should be checking for integer-valued doubles, whether InternNonIntElementId should be doing so, or whether TI should somehow be producing integer values for us here.

Comment 3

[Boris Zbarsky [:bzbarsky]]

Oh, the IC updates kinda look like this:

#2  0x000000010128e84b in TypedArrayTemplate<unsigned char>::obj_getElement (cx=0x11c0913e0, tarray={<js::HandleBase<JSObject *>> = {<No data fields>}, ptr = 0x7fff5fbf57f0}, receiver={<js::HandleBase<JSObject *>> = {<No data fields>}, ptr = 0x7fff5fbf57f0}, index=284, vp={<js::MutableHandleBase<JS::Value>> = {<js::MutableValueOperations<JS::MutableHandle<JS::Value> >> = {<js::ValueOperations<JS::MutableHandle<JS::Value> >> = {<No data fields>}, <No data fields>}, <No data fields>}, ptr = 0x7fff5fbf5cf0}) at jstypedarray.cpp:1253
#3  0x00000001010535d9 in JSObject::getElement (cx=0x11c0913e0, obj={<js::HandleBase<JSObject *>> = {<No data fields>}, ptr = 0x7fff5fbf57f0}, receiver={<js::HandleBase<JSObject *>> = {<No data fields>}, ptr = 0x7fff5fbf57f0}, index=284, vp={<js::MutableHandleBase<JS::Value>> = {<js::MutableValueOperations<JS::MutableHandle<JS::Value> >> = {<js::ValueOperations<JS::MutableHandle<JS::Value> >> = {<No data fields>}, <No data fields>}, <No data fields>}, ptr = 0x7fff5fbf5cf0}) at jsobjinlines.h:1193
#4  0x000000010165208f in js::GetObjectElementOperation () at FloatingPoint.h:147
#5  0x000000010164e6a5 in js::GetElementOperation () at IonCaches.cpp:1753
#6  0x000000010164e341 in js::ion::GetElementIC::update (cx=0x11c0913e0, cacheIndex=2, obj={<js::HandleBase<JSObject *>> = {<No data fields>}, ptr = 0x7fff5fbf5d20}, idval={<js::HandleBase<JS::Value>> = {<js::ValueOperations<JS::Handle<JS::Value> >> = {<No data fields>}, <No data fields>}, ptr = 0x7fff5fbf5d28}, res={<js::MutableHandleBase<JS::Value>> = {<js::MutableValueOperations<JS::MutableHandle<JS::Value> >> = {<js::ValueOperations<JS::MutableHandle<JS::Value> >> = {<No data fields>}, <No data fields>}, <No data fields>}, ptr = 0x7fff5fbf5cf0}) at IonCaches.cpp:1743

which is of course total fail too: trying to do an IC on typed array element access just isn't going to work well.

Comment 4

[Brian Hackett [Laid off!]]

(In reply to Boris Zbarsky (:bz) from comment #2)
> It's not clear to me whether ToIdOperation should be checking for
> integer-valued doubles, whether InternNonIntElementId should be doing so, or
> whether TI should somehow be producing integer values for us here.

Ion should emit code to try converting doubles to integers in the TOID.  Right now it just nops integer TOID and calls a stub in other cases.  Similar things are already done for other indexed expressions, TOID is just an oddball that shows up in x[i]++ operations.

TI generating double information instead of integers is a known problem that affects other parts of pdf.js.  IIRC the problem there is that TI needs to capture all possible types that could flow through SSA values, and there are some paths that are never actually executed where a NaN could flow to integer valued variables.  This should be fixable after bug 804676, as then the types computed during MIR construction only need to describe those realized by the MIR values, and paths where NaNs start flowing around can be excluded by bailing out on those edges.

Comment 5

[Hannes Verschore [:h4writer]]

Attachment: Testcase for shell

Made a shell version out of it, easier for me to debug.

$ time js --ion-parallel-compile=on /tmp/jpeg2000.js 

real	0m7.713s
user	0m7.756s
sys	0m0.096s

$ time d8 /tmp/jpeg2000.js 

real	0m3.296s
user	0m3.292s
sys	0m0.016s

Comment 6

[Hannes Verschore [:h4writer]]

Attachment: Tracelogging profile

Tracelogging dumps shows we are mostly running in IonMonkey.
(That's good. That isn't the reason we are slow) 

This dump shows some opportunities:
- some functions should really get inlined. If a function takes < 160 cycles/call it is mostly the overhead of jumping to that function. Inlining helps those big time.

ion_cannon,/tmp/jpeg2000.js:1302 (9%), called: 12152159 , 162 cycles/call
ion_cannon,/tmp/jpeg2000.js:1321 (3%), called: 6378414 , 106 cycles/call
ion_cannon,/tmp/jpeg2000.js:1393 (2%), called: 3651130 , 113 cycles/call
ion_cannon,/tmp/jpeg2000.js:1348 (1%), called: 3280356 , 94 cycles/call
ion_cannon,/tmp/jpeg2000.js:1452 (1%), called: 1827717 , 162 cycles/call
ion_cannon,/tmp/jpeg2000.js:1332 (1%), called: 3087381 , 95 cycles/call

- the most time is spend in the following functions. Therefore improving should look at these. (Note the reported time is the execution time of the function + all inlined functions. Tracelogging doesn't know when functions are inlined in IM):

ion_cannon,/tmp/jpeg2000.js:1590: 7380338516 cycles (36%), called: 20019
ion_cannon,/tmp/jpeg2000.js:1477: 3645350526 cycles (18%), called: 15916
ion_cannon,/tmp/jpeg2000.js:1302: 1972206419 cycles (9%), called: 12152159
ion_cannon,/tmp/jpeg2000.js:1546: 1462541454 cycles (7%), called: 15893

Comment 7

[Hannes Verschore [:h4writer]]

Attachment: Oprofile profile

Operf shows:

66% c++ js functions
27% jitted code

Therefore the problem is probably that we need to take to much IC's in the generated IM code. And we should try to decrease those...

One not related to IC's, but cached my eye is:
8% js::ion::GetElementIC::update(JSContext*, unsigned int, JS::Handle<JSObject*>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>)
That shouldn't take like 8% of our time

Also this report shows the benchmark isn't hitting GC problems. No need to look there.

Comment 8

[Guilherme Lima]

Right now
Nightly 26 - 3815ms
Chrome 29 - 3279ms

Comment 9

[Shu-yu Guo [:shu]]

AWFY shows that we are faster at the moment.

Comment 10

[Guilherme Lima]

Yeah, just tested and Nightly now did it at 2390ms!

Comment 11

[Till Schneidereit [:till]]

Nice! Going to declare victory here, then.