962044 - Forward event loop lag messages to Gecko

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::System, defect)

Description

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Attachment: event.loop.observer.patch

Comment 1

[Paul Rouget [:paul]]

/mozilla/B2G/gecko/toolkit/xre/EventTracer.cpp:94: error: 'services' has not been declared

Comment 2

[Gabriele Svelto [:gsvelto] (PTO)]

Comment on attachment 8362920 [details] [diff] [review]
event.loop.observer.patch

Review of attachment 8362920 [details] [diff] [review]:
-----------------------------------------------------------------

A couple of quick notes:

::: toolkit/xre/EventTracer.cpp
@@ +91,5 @@
> +
> +    NS_IMETHODIMP Run()
> +    {
> +      nsCOMPtr<nsIObserverService> obsService = services::GetObserverService();
> +      NS_ENSURE_TRUE(obsService, NS_ERROR_FAILURE);

NS_ENSURE_TRUE() is deprecated, use:

if (!obsService) {
  return NS_ERROR_FAILURE;
}

@@ +93,5 @@
> +    {
> +      nsCOMPtr<nsIObserverService> obsService = services::GetObserverService();
> +      NS_ENSURE_TRUE(obsService, NS_ERROR_FAILURE);
> +      return obsService->NotifyObservers(nullptr, "event-loop-lag",
> +                                         (const char16_t*)(uintptr_t)mLag);

There's at least another place where we pass an integer inside the string pointer but since it's a hack it's better to label it clearly as such.

@@ +170,5 @@
>                  PR_Now() / PR_USEC_PER_MSEC,
>                  int(duration.ToSecondsSigDigits() * 1000));
> +#ifdef MOZ_WIDGET_GONK
> +        NS_DispatchToMainThread(
> +         new EventLoopLagDispatcher(int(duration.ToSecondsSigDigits() * 1000)));

You might want to add the output of ProcessPriorityManager::CurrentProcessIsForeground() to the event so that we can figure out if the process was in the foreground or not. I would suggest checking it before and after the FireAndWaitForTracerEvent() call so that we can detect BG->FG and FG->BG transactions.

Comment 3

[Paul Rouget [:paul]]

s/services/mozilla::services/

Comment 4

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

(In reply to Paul Rouget [:paul] from comment #1)
> /mozilla/B2G/gecko/toolkit/xre/EventTracer.cpp:94: error: 'services' has not
> been declared

I bet this is some GCC fun. I run gcc-4.7 while you have 4.6 :) But sounds cheap to fix, thanks :)

Comment 5

[[:fabrice] Fabrice Desré]

Comment on attachment 8362920 [details] [diff] [review]
event.loop.observer.patch

Review of attachment 8362920 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/xre/EventTracer.cpp
@@ +93,5 @@
> +    {
> +      nsCOMPtr<nsIObserverService> obsService = services::GetObserverService();
> +      NS_ENSURE_TRUE(obsService, NS_ERROR_FAILURE);
> +      return obsService->NotifyObservers(nullptr, "event-loop-lag",
> +                                         (const char16_t*)(uintptr_t)mLag);

Not only that, but that pretty much means that using that observer from JS and reading the data will lead to crashes. We should really avoid that kind of hack. You should instead use a property bag as subject that will hold the lag.

Comment 6

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Attachment: event.loop.observer.patch

The patch still miss the background/foreground information but should not crash anymore (untested).

Comment 7

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

(In reply to Gabriele Svelto [:gsvelto] from comment #2) 
> @@ +170,5 @@
> >                  PR_Now() / PR_USEC_PER_MSEC,
> >                  int(duration.ToSecondsSigDigits() * 1000));
> > +#ifdef MOZ_WIDGET_GONK
> > +        NS_DispatchToMainThread(
> > +         new EventLoopLagDispatcher(int(duration.ToSecondsSigDigits() * 1000)));
> 
> You might want to add the output of
> ProcessPriorityManager::CurrentProcessIsForeground() to the event so that we
> can figure out if the process was in the foreground or not. I would suggest
> checking it before and after the FireAndWaitForTracerEvent() call so that we
> can detect BG->FG and FG->BG transactions.

As discussed on IRC it sounds a good thing to do. Even if it should be trivial I would like to land this patch asap and I'm a bit running out of time to play with the process stuff today.

Comment 8

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Attachment: event.loop.observer.patch

Ted I'm a bit concerned about touching the event loop while we monitor it. For the moment I'm interested in fixing big janks in FFOS but I wonder if there is a better way to forward this information to some Gecko handlers.

Comment 9

[(not currently active) Ted Mielczarek]

I'm curious about what the use case is here. Are you trying to integrate this into some other tool or test suite? It does seem a little unfortunate to send an extra event to get the measurement out, but it's probably not all that bad in the grand scheme of things.

Comment 10

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #9)
> I'm curious about what the use case is here. Are you trying to integrate
> this into some other tool or test suite? It does seem a little unfortunate
> to send an extra event to get the measurement out, but it's probably not all
> that bad in the grand scheme of things.

The goal is to show directly on Gaia when the event loop is not responding. The tool will be turned on most of the time for engineering build and when something goes wrong (event loop lag, reflows, css warnings, js errors) it will starts to display a counter. The current results are something like https://bug960933.bugzilla.mozilla.org/attachment.cgi?id=8364273 (without janks).

The core idea behind that is first to be able to give Gaia devs a instant feedback that something is wrong, and in the medium term to have a nice way to write some tests for that and make sure we don't regress.

Comment 11

[(not currently active) Ted Mielczarek]

Okay. We currently have profiler hooks in the responsiveness instrumentation, so if you piggybacked on the profiler you could use it that way. If that's not desirable then we can certainly land this patch.

Comment 12

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #11)
> Okay. We currently have profiler hooks in the responsiveness
> instrumentation, so if you piggybacked on the profiler you could use it that
> way. If that's not desirable then we can certainly land this patch.

One of the goal here is to be able to have some infos even when the profiler is not running. You can see that as some kinds of alerts telling you instantly that something is wrong. And then you will likely need to take your profiler and use it to have more details.

Comment 13

[(not currently active) Ted Mielczarek]

Comment on attachment 8365542 [details] [diff] [review]
event.loop.observer.patch

Review of attachment 8365542 [details] [diff] [review]:
-----------------------------------------------------------------

Okay, let's get this in then.

::: toolkit/xre/EventTracer.cpp
@@ +87,5 @@
> +class EventLoopLagDispatcher : public nsRunnable
> +{
> +  public:
> +    explicit EventLoopLagDispatcher(int aLag)
> +      :mLag(aLag) {}

nit: space after the colon.

@@ +178,5 @@
>                  now,
>                  duration.ToMilliseconds());
> +#ifdef MOZ_WIDGET_GONK
> +        NS_DispatchToMainThread(
> +         new EventLoopLagDispatcher(int(duration.ToSecondsSigDigits() * 1000)));

Note that we explicitly switched to using fractional milliseconds in the log messages to avoid aliasing issues. If you're planning on doing any math with the resulting values you might want to follow suit.

Comment 14

[Paul Rouget [:paul]]

Does this need to be gonk only?

Comment 15

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

https://hg.mozilla.org/integration/b2g-inbound/rev/12e538213354

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/12e538213354