Closed Bug 1288912 Opened 3 years ago Closed 3 years ago

native messaging is slow

Categories

(WebExtensions :: Untriaged, defect, P2)

50 Branch
defect

Tracking

(firefox50 fixed)

RESOLVED FIXED
mozilla50
Tracking Status
firefox50 --- fixed

People

(Reporter: jon.jwilkes, Assigned: kmag)

References

Details

(Whiteboard: [native messaging] triaged)

Attachments

(2 files)

Attached file native-messenger.zip
User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:47.0) Gecko/20100101 Firefox/47.0
Build ID: 20160630070928

Steps to reproduce:

I created an extension to test the RTT and throughput of native messaging.


Actual results:

As of this writing, RTT and throughput are poorer than expected.  On my Phenom II machine, throughput is ~90 ms / message and average RTT is about 60 ms / message.


Expected results:

On my machine chromium's throughput is 4.5 ms / message with an average RTT of 1 ms.
Assignee: nobody → kmaglione+bmo
Depends on: 1276390
Priority: -- → P2
Whiteboard: [native messaging] triaged
Jon, when you originally reported this on IRC you also reported that the RTT increased the longer your extension ran, are you still seeing that?
Flags: needinfo?(jon)
Attachment #8775859 - Flags: review?(aswan) → review+
Comment on attachment 8775859 [details]
Bug 1288912: Add tests for native messaging round trip time.

https://reviewboard.mozilla.org/r/67920/#review65104

::: toolkit/components/extensions/test/xpcshell/test_ext_native_messaging.js:128
(Diff revision 1)
> +                          `${REGKEY}\\${script.name}`, "", manifestPath);
> +      }
> +      break;
> +
> +    default:
> +      ok(false, `Native messaing is not supported on ${AppConstants.platform}`);

You copied my typo over verbatim :-)
https://reviewboard.mozilla.org/r/67920/#review65104

> You copied my typo over verbatim :-)

Eh. I think it adds charm. Gives the place a nice, lived-in look.
Blocks: 1290598
https://hg.mozilla.org/mozilla-central/rev/657d86828018
https://hg.mozilla.org/mozilla-central/rev/6d35194aa0f1
Status: UNCONFIRMED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla50
It's better but still a little wobbly.

> Jon, when you originally reported this on IRC you also reported that
> the RTT increased the longer your extension ran, are you still
> seeing that?

The linear increase in RTT I reported in IRC was caused by simply stuffing messages in a queue faster than Firefox could process them (thus increasing the RTT for the messages that had to wait for all the messages ahead in the queue to be processed).  It was an artifact of the *real* bug, which is that each message took too long to process.

After the above fixes, I now see:

    firefox nightly:
    # of messages 1000 messages
    total time    8134.81 ms
    throughput    8.13 ms per message
    minimum RTT   1.57 ms
    maximum RTT   54 ms
    average RTT   3.97 ms
    standard dev  3.38
    weirdos  0

    chromium 51.0.2704.106:
    # of messages 1000 messages
    total time    5231.91 ms
    throughput    5.23 ms per message
    minimum RTT   0.49 ms
    maximum RTT   3.54 ms
    average RTT   1.02 ms
    standard dev  0.19
    weirdos  0

I.e., firefox is now at least in the same ballpark as chromium.

But there's still some wobble.  The standard deviation for firefox shows that some messages other than the first few take longer than expected.  Using the attached sample code and a value of 500 for bookend size, I see, for example that while most messages are processed quickly, some messages took 53 or 54 milliseconds to complete.

    .
    .
    .
    6.06 ms
    4.24 ms
    4.08 ms
    53.32 ms
    54 ms
    7.06 ms
    3.65 ms
    4.15 ms
    .
    .
    .

I notice Kris Maglione's tests contain:

    const MAX_ROUND_TRIP_TIME_MS = AppConstants.DEBUG || AppConstants.ASAN ? 36 : 18;

If I'm right about the wobble, the tests may fail on occasion, depending on the machine.
Flags: needinfo?(jon)
(In reply to Jon Wilkes from comment #8)
> I notice Kris Maglione's tests contain:
> 
>     const MAX_ROUND_TRIP_TIME_MS = AppConstants.DEBUG || AppConstants.ASAN ?
> 36 : 18;
> 
> If I'm right about the wobble, the tests may fail on occasion, depending on
> the machine.

I believe that is the threshold for the average response time of 1000 messages, but you're just seeing individual outliers, not consistently highly RTTs that would pull the average up that high.
(In reply to Jon Wilkes from comment #8)
> But there's still some wobble.  The standard deviation for firefox shows
> that some messages other than the first few take longer than expected. 
> Using the attached sample code and a value of 500 for bookend size, I see,
> for example that while most messages are processed quickly, some messages
> took 53 or 54 milliseconds to complete.

That's not unexpected. Extensions currently run in the main browser process.
Things like GC and other code executing in the same event loop will cause
aberrations.

> I notice Kris Maglione's tests contain:
> 
>     const MAX_ROUND_TRIP_TIME_MS = AppConstants.DEBUG || AppConstants.ASAN ?
> 36 : 18;
> 
> If I'm right about the wobble, the tests may fail on occasion, depending on
> the machine.

Those numbers have a lot of built-in padding. But even so, the timing in
xpcshell tests is pretty consistent.
Using Kris Maglione's snazzy sans-setTimeout technique, the discrepancy between throughput and average RTT disappeared.  For the record, here are the new numbers from my machine for Firefox and Chromium:

    Firefox nightly
    # of messages   1000 messages
    total time      2986.02 ms
    1/throughput    2.99 ms per message
    minimum RTT     1.54 ms
    maximum RTT     85.77 ms
    average RTT     2.98 ms
    standard dev    3.35

    Chromium 51.0.2704.106
    # of messages   1000 messages
    total time      422.94 ms
    1/throughput    0.42 ms per message
    minimum RTT     0.22 ms
    maximum RTT     8.15 ms
    average RTT     0.42 ms
    standard dev    0.33
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.