156365 - LiveConnect Java -> JavaScript communications is slow and noisy.

Status: RESOLVED INCOMPLETE

(Core Graveyard :: Java: OJI, defect)

Description

[Steve K]

Under Linux, visiting the reduced testcase
http://stevek.com/ForMozilla/LiveConnect/test.html results in output like this:

================
OJIPlugin acq Spontaneous pipe=10
Trying to enter spont monitor: 0
 OJIPlugin release for:Thread[thread
applet-Test,4,http://u/dls/work/stevek/LiveConnect/-threadGroup]
OJIPlugin releasePipe - exiting spont monitor
run() called
Current thread:Thread[thread
applet-Test,4,http://u/dls/work/stevek/LiveConnect/-threadGroup]
OJIPlugin: No AThread
================

For each invocation of JSObj.call().  It also seems _very_ expensive to make
these calls.

On other Mozilla platforms, and even on MSIE with the MSVM, these calls are much
less expensive.  On other Mozilla/Sun VM platforms, there is just one patch of
output like that.

It seems that some data structures which ought to be initialized only on calls
to JSObject.getWindow() are being constructed and destructed on each call to
JSObject.call() instead.

So far, the result has only been terrible performance, and not crashes.

Comment 1

[Joe Chou]

Reporter, are you saying that those lines should not have been printed to the
Java console, which would slow down performance?

Comment 2

[Steve K]

I'm guessing that these lines are just debugging information, in which case they
probably ought not to be printed unless there is an error condition to report.

Further, the performance is very bad, as compared to other platforms.  You
probably shouldn't be able to see the individual lines being printed, one-by-one.

With Java_1.4.0 and NS6.2 on WinXP, there are no debug messages (other than the
ones explicit in the Applet), and the lines print much faster.

As I said, my guess is that the Java -> JS connection is being made separately
for each call, when it probably could be kept persistently as long as the
JSObject is in scope.

Comment 3

[Steve K]

*** Bug 165309 has been marked as a duplicate of this bug. ***

Comment 4

[Phil Schwartau]

Confirming bug based on duplicate reports -

Comment 5

[Steve K]

bug 165309 is saying the same thing as this bug.  (kill me if I shouldn't have
duped it).

Upon some reflection, and looking at other related bugs, it appears that the
slowness and the debugging messages are pretty clearly not related, unless
there's just a _huge_ penalty for writing a few lines to the console.

I'm guessing that there's a whole lot of objects being created/destroyed for
every LiveConnect call, which is killing performance.  We've tried many
different combinations of either using a persistent JSObject in our code, or
not, and it doesn't seem to make a difference.  (Currently, we create a new
JSObject for each LiveConnect call, as it appears that it might be less likely
to cause crashes, such as the one in bug 70588, but that doesn't seem to help
too much).

(thanks for confirming this midair, pschwartau!)

Comment 6

[Phil Schwartau]

cc'ing Patrick re Steve's idea in Comment #5 above -

Comment 7

[Michael G Henderson]

When I pass arrays from javascript to java I dont just get a "few messages"
printed to the terminal. I get more like *thousands*. This *has* to be giving me
a huge performance hit. These messages are very liking quite expensive to print...


If you are only getting a few messages and are still experiencing slowness, then
I agree there is something else wrong as well. 

Comment 8

[Michael G Henderson]

To see what I mean: 

    1) start mozilla from a terminal.

    2) Try this LiveConnect enabled page:
http://leadbelly.lanl.gov/ccr/cgi-bin/ccr_plot_choose_3.cgi/20011012/ips_spec/2

    3) Move the cursor around the plot. This drives the applet
       to the right of the plot. Note that every single event is causing
       a spewage of messages. Not a huge number mind you (not yet). But
       a set of messages for every mouse event is pretty excessive and
       likely expensive.


    4) Now click on the plot. This actually does the main initialization of
       the app. It sends over some fairly large arrays. I'd like to just send
       them when the page is visited, but its just too slow for my needs (this
       app is meant to be a quick plot-browsing tool -- so waiting too long
       for the applet to init is no good.) Anyway, note how many messages get
       dumped now. And note that the applet doesnt respond again until all the
       messages have printed. The message printing clearly is very expensive     
       here.


-Mike

Comment 9

[Steve K]

Michael,

Firstly, I don't disagree that LiveConnect is disproportionately slow on
Mozilla, especially under Unix (I think you might be testing against Windows? 
IIRC, windows didn't spew quite so many messages..), especially when compared
with the old Netscape4, or MSIE.  But I think that there may be two problems:

1) It's slow,
2) It prints messages.

I don't think you can show if the printing of the messages makes it slow without
either profiling, or building a plugin that doesn't print the messages, and
testing it.  Assume for a moment the following sequence for each LC call:

1) Print some messages (time = t1)
2) Do lots of slow stuff (time = t2)
3) Print some more messages. (time = t3).

Then, queue up a lot of LC calls.  You'd see exactly the behavior you describe;
namely, the queue would empty slowly, as lots of messages were printed, and
wouldn't empty until all the messages printed.

In this case, removing all the messages would still only remove 2% of the total
time.  We know t1+t2+t3 is way too big, but don't know if the problem is t1 or
t2 or t3, though, we just know that it takes way too long.

We can put numbers on the whole process, though, if we wrote a simple testcase
which accurately timed the execution of, say, 1000 simple LC calls, and ran it
under various browser/java vm combinations.  I'm sure that we'd find that
mozilla/sun was a dog here, but I'm also not sure whether the problems are on
the Mozilla side or the Sun side, not to mention whether or not the excessive
debugging has any effect.

Comment 10

[Michael G Henderson]

I agree that quantifying the various times is an important task. And will point
the way to where the problem(s) might be.

However, from gut feeling (and prior experience), adding "printf()'s" to a
graphical event loop is a very bad thing to do. Although these are just
messages, I suspect they are still pretty expensive (more than 2%). For the
end-user they are totally meaningless and unnecessary and shouldnt be printed at
all (or they could be toggled via a "debug-level" command-line switch or
something like that.) In fact the messages I am referring to wont ever be seen
unless mozilla is invoked via a terminal anyway.

Most of my LiveConnect calls (Javascript calling Java methods), are actually
pretty zippy -- even on Linux/Mozilla (try the www page I pointed out -- the
Java Applet updates pretty quickly when you drag the mouse back and forth over
the plot. Note that every single mouse movement is a liveconnect call to update
the graphics in the Applet). I really run into problems when I attempt to make
calls that pass arrays (especially large arrays -- for example when you click on
the plot, several large data arrays are passed to one of the Applet's methods).
Passing arrays should not be this expensive.

Comment 11

[Steve K]

I made up a simple benchmark set, based on the original URL for this bug.

At http://stevek.com/ForMozilla/TimeJava2JS/timejava2js.html, is a HTML page,
and a java applet.  The java applet
1) calls a "begin" Javascript function, 
2) then makes 1000 calls to a simple function that just increments a counter,
3) calls an "end" JS function which calculates the time per js call.

Results:

IE6/Win98/MS VM:          0.22ms/call
IE5.5/Win98/MS VM:        0.27ms/call
Netscape4/Linux2.4:       0.25ms/call
IE6/WinXP/Sun VM:         0.321ms/call

Netscape7/Win98/Sun VM:           2.63ms/call
Mozilla1.0/Linux2.4/Sun 1.4.1-rc: 3.869ms/call

So, whichever way you slice it, Mozilla is an order of magnitude too slow.

Comment 12

[Steve K]

Ahh, I just realized something here..


There's two different kinds of messages going on here.

JS->Java messages are printing messages to stderr or stdout,  These messages
look like this:

call:35725
rem:Set array arr=4DA1FAA8 start=0 len=1 buf[0]=19
rem:Set array arr=4DA1FAA8 start=1 len=1 buf[0]=23
rem:Set array arr=4DA1FAA8 start=2 len=1 buf[0]=2
rem:Set array arr=4DA1FAA8 start=3 len=1 buf[0]=8
rem:Set array arr=4DA1FAA8 start=4 len=1 buf[0]=16
rem:Set array arr=4DA1FAA8 start=5 len=1 buf[0]=-999

Where the "rem:" lines might be there just for marshalling of data in arrays?

This clear in michael's testcase.

all the OJIPlugin stuff is printed in the Java Console, and is a result of
Java->JS calls (the other way).  These are exemplified in my "testjava2js"
testcase, in my previous comment.

Also, I had tested that testcase in mozilla1.0rc3, which I had been using
myself, and it got the 3.8ms/call number.  Now, using 1.2a, and the same
machine, same Java VM, I'm getting 9.345ms/call, which is a _lot_ worse than it
should be.

I never noticed the stderr/stdout messages before, because I had been launching
mozilla from gnome, (although I didn't see any messages in .xsession-errors).

So, there's definately big problems here, _and_ a big regression.

Also, this testcase seems to have caused my Java Console to lock up, which it
wasn't doing with 1.0rc3.  But for the moment, the browser is still working.

Comment 13

[Steve K]

I did a little more testing:

All on 1.2a/Java 1.4.1-rc/Linux 2.4 on the same machine.

First:  Having stderr/stdout redirected to /dev/null, or not made no discernable
difference (except whether or not I got thousands of these lines: call:26988).

Second: Having the Java Console open or not made a big difference.

With the console closed, running the test gave me ~3.5ms/call, with it open, two
things happened:

1) the test took about 7ms/call,
2) The console crashed.

Grr.

Comment 14

[Joe Chou]

The performance issue here could be due to two reasons:
1) printing too much to the Java console
2) mozilla's JVM on Unix is a seperate process from the browser, whereas on
Windows JVM is in the same process as the browser.

Reason 1) can be resolved by stop printing such messages in commercial builds.
Re-assigning this bug to Java plugin group to turn off the printing.

Reason 2) is tougher. This is another point against putting JVM in a seperate
process. 

Comment 15

[Steve K]

Joe,

It seems, though, that the difference between Win98/Mozilla/Sun VM and
Linux/Mozilla/Sun VM is small compared to the difference between IE/either VM
and Mozilla/(well, just sun VM).  

In other words, it seems that most of the slowdown is in Mozilla, or in the
Mozilla-specific parts of the Java Plugin.

Comment 16

[Patty Mac]

Chris Petersen is a new QA contact for oji component. His email is:
[e-mail]

Comment 17

[Matthias Versen [:Matti]]

fixing small error for [e-mail] (filter with : SPAMMAILSUCKS)

Comment 18

[Joshua Xia]

reassign to me

Comment 19

[Pete Zha]

It's a performance problem. So, adding the "perf" keyword

Comment 20

[Michael G Henderson]

I am wondering if this bug is somehow linked with the "hard freezes" that
occur after using a LiveConnect capable page several times? I.e., if new
objects are continually being created, is there a hard limit on resources
that finally occurs and the browser freezes hard? I have both problems: 1) the
slowness that is the topic of this specific bug and 2) the hard freezes that
occur (I think this is already described as a different bug). The first, I can
live with for now, but the second is a real killer for me... Maybe fixing this
bug will cure the frezze problem too(?).
-Mike

Comment 21

[Joshua Xia]

this bug will be fixed on JEA module (liveconnect redesign),
see bug #193272

Comment 22

[Joshua Xia]

poor performance of old liveconnect design and implement.

->Kyle.

Comment 23

[Rudolf Weber]

The Meseages are realy desturbing.
I scanned the sources (8.3.2004) for the keywords AThread OJIPlugin and so on 
and did't find this. Does it come from the javaplugin ?

The call:xxxx on the Shell are desturbing too.
(I Expected a string like call:%x but I did't find any ???)

Comment 24

[Hish]

I made a few smoke tests (Moz 1.7/WinXP):

Test 1: 
java test() returns String[10000]
var a=document.applets[0].test();
for (var i=0; i<a.length; i++)
  b=a[i]+'';
Result: 5000msec 

Test 2: 
java test() returns single String (10000 x "test"+"|")
var a=document.applets[0].test().split('|');
for (var i=0; i<a.length; i++)
  b=a[i]+'';
Result: 200msec 

Bottomline: Try to return a simple object. As soon as you return an array or a
complex object, it's getting slow.

Comment 25

[Kyle Yuan]

The slowness of liveconnect calls is not due to the executing speed of the
language (Java & JS) itself, it is due to a huge amount of java method
reflection during the first call. 

Comment 26

[Hish]

Maybe we are talking about two problems:
- slowness during first call and
- java wrapper as described in my two test examples.

Comment 27

[Bug Tracker]

Kyle, I have 2.66 Ghz computer and startup time is no better than my old 800Mhz computer. I do not know how many class files are reflected, but it shouldnt take 2-3 seconds on a 2.66 Ghz machine. (Note: using JRE1.5_06).

-> from comment 21: this bug will be fixed on JEA module (liveconnect redesign),

This was more than 2 years ago. is JEA module complete?

Comment 28

[Pete Zha]

mass reassign to Alfred

Comment 29

[Bug Tracker]

>it is due to a huge amount of java method
>reflection during the first call. 

I am having trouble to understand, why would you reflect the whole thing over and over again for every applet on the page? Dont you use some sort of a singleton wrapper for all the classes reflected? and why the delay is almost same for every other machine regardless of the CPU speed?

All I see you guys mass assign live connect bugs to some engineer time to time. Has anybody been actually working to improve this painful experience? It has been 4 years for God's sake.

Comment 30

[Ken Warner]

Environment: Java 1.5.x.x; Mozillia Firefox 1.5.0.11

The first call from Javascript to an applet causes the spew of 

liveconnect: JavaScript: calling Java system code
liveconnect: JavaScript: default security policy = file://
liveconnect: JavaScript: UniversalBrowserRead enabled
liveconnect: JavaScript: default security policy = file://

about a thousand of them or more.  At least 10 seconds wait.  The above output is only shown in the console when trace is set to 5.

SUN's evaluation was that Java uses "...aggressive reflection..." But this problem is not seen in IE with the same plugin that shows the bug in Firefox.

This bug is reported here in bugzilla and on SUN's bug list in various forms for the last 3 years.  Why this hasn't been fixed is a mystery.  I've already lost one contract because the client just threw up his hands.  I'm about to lose another contract.  

No problems with IE and Java 5.  PLEASE FIX THIS BUG!!!

Comment 31

[Benjamin Smedberg]

Mass-closing bugs in the "OJI" component: OJI plugin integration was replaced with npruntime long ago, and these bugs appear to be irrelevant now. If there is in fact a real bug that remains, please file it new in the "Core" product, component "Plug-ins".