860116 - Content process startup (dialer): ipdl::PContent::SendGetXPCOMProcessAttributes may take up to 1.4 sec

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: General, defect)

Description

[Gregor Wagner [:gwagner]]

I got a profile where ipdl::PContent::SendGetXPCOMProcessAttributes takes 1.4 sec during launching the dialer.
We should send this info when we launch the process.

Comment 1

[Justin Lebar (not reading bugmail)]

Is the goal to have zero sync child->parent calls during startup?  We have no reason to believe that this particular sync call is particularly bad, right?

If the master process takes 1.4s to /send/ the message, that indicates to me that either sending is blocking -- which it shouldn't be -- or otherwise the master process is getting starved for CPU.  Either one of those sounds to me like a root problem, not the fact that we're sending a message.

Comment 2

[Gregor Wagner [:gwagner]]

The original profile with 1.4 sec in ipdl::PContent::SendGetXPCOMProcessAttributes was with starting membuster and calling the phone at the same time.

I can also reproduce it with just opening multiple apps at the same time (tabbing on app, back to homescreen, open next app....)
This is a profile (where I remove the SendGetXPCOMProcessAttributes) that shows all the activity for an incoming phone call when the communications app is not loaded with loading a bunch of apps in the background in parallel. The last 1 - 2 sec might be the ringing. The whole profile is around 1300 samples * 10msec so it takes around 10 sec to show the phone call.
Seems like the sync calls take most of the time here:
http://people.mozilla.com/~bgirard/cleopatra/#report=f6b7ae6779b77ba5ba8762fc3056fade5fca315b

Comment 3

[Justin Lebar (not reading bugmail)]

> Seems like the sync calls take most of the time here:
 
Ah, this is the child process.  Okay, that makes a bit more sense.

I understand that the sync messages are taking a long time to process, but the question is, why?  Is the parent too busy to respond to the messages in a timely fashion?  If so, the parent may be so busy that we can't rely on it to do the rest of the work that we need it to do in a timely fashion.  The slow sync messages may be merely a symptom of the problem here.

See also bug 847592 comment 19, if you haven't read it yet.

Comment 4

[Gregor Wagner [:gwagner]]

(In reply to Justin Lebar [:jlebar] from comment #3)
> > Seems like the sync calls take most of the time here:
>  
> Ah, this is the child process.  Okay, that makes a bit more sense.
> 

I tried your git repo but I couldn't get the profiler to run (bug 859928). So the profile from comment 2 is mc with the patch from bug 859928 and gaia master.

Comment 5

[Justin Lebar (not reading bugmail)]

> I tried your git repo but I couldn't get the profiler to run (bug 859928).

Does that bug affect b2g18?  It doesn't look like it to me; I see

> #ifdef MOZ_WIDGET_ANDROID
>     nsCString tmpPath;
>     tmpPath.AppendPrintf("/sdcard/profile_%i_%i.txt", XRE_GetProcessType(), getpid());
> #else

which doesn't count B2G, I think?

Comment 6

[Justin Lebar (not reading bugmail)]

I think it would be worth profiling the master process to see why it's taking forever to reply to this message.

Comment 7

[Ben Turner (not reading bugmail, use the needinfo flag!)]

(In reply to Justin Lebar [:jlebar] from comment #1)
> Is the goal to have zero sync child->parent calls during startup?

That sounds like a good goal to me. Any data that the child really needs at startup could just be sent from parent->child when we launch the app, right? And anything that doesn't have to be on the startup path could just get bumped to be an async message later.

Though I agree that we need to understand why the parent is so slow to respond before we break out the pitchforks and torches.

Comment 8

[Justin Lebar (not reading bugmail)]

> Any data that the child really needs at startup could just be sent from parent->child when we 
> launch the app, right? And anything that doesn't have to be on the startup path could just get 
> bumped to be an async message later.

Yes, I think we in principal ought to be able to eliminate all sync messages on startup.

But to be clear about my concern, the master process may be on the critical path of the "receiving a call" action in ways that aren't related to sync messages.  Much of the RIL stuff happens in the main process, for example.  So even if we did eliminate the sync messages, we might not fix the problem.

Since renicing all of the processes to 20 doesn't fix the problem, and since gwagner says here that we start up the child process relatively quickly and then it takes many seconds to show the on-call screen, it would seem that either

 * renicing isn't working (maybe it doesn't take effect quickly, or maybe the code that I think  renices the processes doesn't actually work), or

 * the master process is busy with work on behalf of the reniced processes.

Profiling the master process would probably help us distinguish between these two cases, although what we really want is a whole-system profiler...

I guess we're in agreement about how to move forward here.

Comment 9

[BMO Automation]

Firefox OS is not being worked on