1288912 - native messaging is slow

Status: RESOLVED FIXED

(WebExtensions :: Untriaged, defect, P2)

Description

[Jon Wiles]

Attachment: 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.

Comment 1

[Andrew Swan [:aswan]]

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?

Comment 2

[Kris Maglione [:kmag]]

Attachment: Bug 1288912: Add tests for native messaging round trip time.

Review commit: https://reviewboard.mozilla.org/r/67920/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/67920/

Comment 3

[Andrew Swan [:aswan]]

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 :-)

Comment 4

[Kris Maglione [:kmag]]

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.

Comment 5

[Kris Maglione [:kmag]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/657d868280184ce67533c1a5d3116fca607fc143
Bug 1288912: Add tests for native messaging round trip time. r=aswan

Comment 6

[Kris Maglione [:kmag]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/6d35194aa0f1b5618283503ec4aee73891e45f81
Bug 1288912: Follow-up: Skip native messaging tests on Android.

Comment 7

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/657d86828018
https://hg.mozilla.org/mozilla-central/rev/6d35194aa0f1

Comment 8

[Jon Wiles]

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.

Comment 9

[Andrew Swan [:aswan]]

(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.

Comment 10

[Kris Maglione [:kmag]]

(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.

Comment 11

[Jon Wiles]

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