The default bug view has changed. See this FAQ.

Profiling tools for IPC messages

RESOLVED INVALID

Status

()

Core
IPC
RESOLVED INVALID
7 years ago
3 years ago

People

(Reporter: azakai, Assigned: azakai)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(2 attachments, 3 obsolete attachments)

(Assignee)

Description

7 years ago
Created attachment 475618 [details]
Python profiling script

Some tools for profiling IPC messages can be useful.

The attached python script lists messages by number and latency.
(Assignee)

Comment 1

7 years ago
Example output:


                                                     === By total messages ===

                          PContentChild|Msg_GetCharPref [SYNC/RPC]    latency: 0.0006    total: 386.000000
                           PContentChild|Msg_GetIntPref [SYNC/RPC]    latency: 0.0026    total: 254.000000
                          PContentChild|Msg_GetBoolPref [SYNC/RPC]    latency: 0.0027    total: 245.000000
                         PBrowserChild|Msg_AsyncMessage               latency: 0.0040    total:  77.000000
                    PBrowserChild|Msg_NotifyStateChange               latency: 0.0032    total:  57.000000
                   PBrowserChild|Msg_NotifyStatusChange               latency: 0.0017    total:  46.000000
                        PHttpChannelParent|Msg_OnStatus               latency: 0.0730    total:  41.000000
                        PNeckoChild|Msg_HTMLDNSPrefetch               latency: 0.0002    total:  39.000000
                    PContentChild|Msg_StartVisitedQuery               latency: 0.0001    total:  33.000000
                       PContentChild|Msg_TestPermission [SYNC/RPC]    latency: 0.0012    total:  32.000000
                 PHttpChannelParent|Msg_OnDataAvailable               latency: 0.0830    total:  30.000000
                 PBrowserChild|Msg_NotifyProgressChange               latency: 0.0021    total:  30.000000
                      PHttpChannelParent|Msg_OnProgress               latency: 0.0799    total:  29.000000
                        PBrowserParent|Msg_AsyncMessage               latency: 0.2114    total:  13.000000
          PDocumentRendererNativeIDChild|Msg___delete__               latency: 0.0010    total:   9.000000
PBrowserParent|Msg_PDocumentRendererNativeIDConstructor               latency: 0.0868    total:   9.000000
                    PBrowserParent|Msg_LoadRemoteScript               latency: 0.2392    total:   7.000000
                PCookieServiceChild|Msg_GetCookieString [SYNC/RPC]    latency: 0.0006    total:   7.000000
                        PHttpChannelChild|Msg_AsyncOpen               latency: 0.0005    total:   6.000000
                   PHttpChannelParent|Msg_OnStopRequest               latency: 0.0507    total:   6.000000
                PNeckoChild|Msg_PHttpChannelConstructor               latency: 0.0005    total:   6.000000
                  PHttpChannelParent|Msg_OnStartRequest               latency: 0.0411    total:   6.000000
               PContentChild|Msg_GetPrefLocalizedString [SYNC/RPC]    latency: 0.0004    total:   5.000000
                       PHttpChannelChild|Msg___delete__               latency: 0.0009    total:   5.000000
            PContentParent|Msg_NotifyRemotePrefObserver               latency: 0.5101    total:   4.000000
                                PBrowserParent|Msg_Move               latency: 0.2080    total:   3.000000
                         PContentChild|Msg_GetChildList [SYNC/RPC]    latency: 0.0008    total:   3.000000
                             PContentChild|Msg_VisitURI               latency: 0.0002    total:   3.000000
                 PBrowserChild|Msg_NotifyLocationChange               latency: 0.0094    total:   2.000000
                 PBrowserChild|Msg_NotifySecurityChange               latency: 0.0009    total:   2.000000
                       PContentParent|Msg_NotifyVisited               latency: 0.0279    total:   2.000000
                             PBrowserParent|Msg_LoadURL               latency: 0.2865    total:   2.000000
                          PContentParent|Msg_SetOffline               latency: 0.0260    total:   1.000000
                        PBrowserParent|Msg_CreateWidget               latency: 0.0006    total:   1.000000
               PNeckoParent|Msg_PHttpChannelConstructor               latency: 0.0003    total:   1.000000
                  PHttpChannelParent|Msg_Redirect1Begin               latency: 0.0003    total:   1.000000
           PHttpChannelChild|Msg_DocumentChannelCleanup               latency: 0.0114    total:   1.000000
                    PContentChild|Msg_PNeckoConstructor               latency: 0.0005    total:   1.000000
                             PBrowserParent|Msg_Destroy               latency: 0.0165    total:   1.000000
                     PContentChild|Msg_PrefHasUserValue [SYNC/RPC]    latency: 0.0003    total:   1.000000
                 PContentParent|Msg_PBrowserConstructor               latency: 0.0005    total:   1.000000
              PNeckoChild|Msg_PCookieServiceConstructor               latency: 0.0002    total:   1.000000
                  PHttpChannelChild|Msg_Redirect2Result               latency: 0.0049    total:   1.000000
                           PBrowserChild|Msg___delete__               latency: 0.0000    total:   1.000000
                      PContentParent|Msg_RegisterChrome               latency: 0.6041    total:   1.000000
               PHttpChannelParent|Msg_Redirect3Complete               latency: 0.0005    total:   1.000000
                      PHttpChannelParent|Msg___delete__               latency: 0.0343    total:   1.000000




                                                     === By latency ===

                      PContentParent|Msg_RegisterChrome               latency: 0.6041    total:   1.000000
            PContentParent|Msg_NotifyRemotePrefObserver               latency: 0.5101    total:   4.000000
                             PBrowserParent|Msg_LoadURL               latency: 0.2865    total:   2.000000
                    PBrowserParent|Msg_LoadRemoteScript               latency: 0.2392    total:   7.000000
                        PBrowserParent|Msg_AsyncMessage               latency: 0.2114    total:  13.000000
                                PBrowserParent|Msg_Move               latency: 0.2080    total:   3.000000
PBrowserParent|Msg_PDocumentRendererNativeIDConstructor               latency: 0.0868    total:   9.000000
                 PHttpChannelParent|Msg_OnDataAvailable               latency: 0.0830    total:  30.000000
                      PHttpChannelParent|Msg_OnProgress               latency: 0.0799    total:  29.000000
                        PHttpChannelParent|Msg_OnStatus               latency: 0.0730    total:  41.000000
                   PHttpChannelParent|Msg_OnStopRequest               latency: 0.0507    total:   6.000000
                  PHttpChannelParent|Msg_OnStartRequest               latency: 0.0411    total:   6.000000
                      PHttpChannelParent|Msg___delete__               latency: 0.0343    total:   1.000000
                       PContentParent|Msg_NotifyVisited               latency: 0.0279    total:   2.000000
                          PContentParent|Msg_SetOffline               latency: 0.0260    total:   1.000000
                             PBrowserParent|Msg_Destroy               latency: 0.0165    total:   1.000000
           PHttpChannelChild|Msg_DocumentChannelCleanup               latency: 0.0114    total:   1.000000
                 PBrowserChild|Msg_NotifyLocationChange               latency: 0.0094    total:   2.000000
                  PHttpChannelChild|Msg_Redirect2Result               latency: 0.0049    total:   1.000000
                         PBrowserChild|Msg_AsyncMessage               latency: 0.0040    total:  77.000000
                    PBrowserChild|Msg_NotifyStateChange               latency: 0.0032    total:  57.000000
                          PContentChild|Msg_GetBoolPref [SYNC/RPC]    latency: 0.0027    total: 245.000000
                           PContentChild|Msg_GetIntPref [SYNC/RPC]    latency: 0.0026    total: 254.000000
                 PBrowserChild|Msg_NotifyProgressChange               latency: 0.0021    total:  30.000000
                   PBrowserChild|Msg_NotifyStatusChange               latency: 0.0017    total:  46.000000
                       PContentChild|Msg_TestPermission [SYNC/RPC]    latency: 0.0012    total:  32.000000
          PDocumentRendererNativeIDChild|Msg___delete__               latency: 0.0010    total:   9.000000
                 PBrowserChild|Msg_NotifySecurityChange               latency: 0.0009    total:   2.000000
                       PHttpChannelChild|Msg___delete__               latency: 0.0009    total:   5.000000
                         PContentChild|Msg_GetChildList [SYNC/RPC]    latency: 0.0008    total:   3.000000
                          PContentChild|Msg_GetCharPref [SYNC/RPC]    latency: 0.0006    total: 386.000000
                PCookieServiceChild|Msg_GetCookieString [SYNC/RPC]    latency: 0.0006    total:   7.000000
                        PBrowserParent|Msg_CreateWidget               latency: 0.0006    total:   1.000000
                    PContentChild|Msg_PNeckoConstructor               latency: 0.0005    total:   1.000000
                PNeckoChild|Msg_PHttpChannelConstructor               latency: 0.0005    total:   6.000000
                        PHttpChannelChild|Msg_AsyncOpen               latency: 0.0005    total:   6.000000
                 PContentParent|Msg_PBrowserConstructor               latency: 0.0005    total:   1.000000
               PHttpChannelParent|Msg_Redirect3Complete               latency: 0.0005    total:   1.000000
               PContentChild|Msg_GetPrefLocalizedString [SYNC/RPC]    latency: 0.0004    total:   5.000000
                  PHttpChannelParent|Msg_Redirect1Begin               latency: 0.0003    total:   1.000000
                     PContentChild|Msg_PrefHasUserValue [SYNC/RPC]    latency: 0.0003    total:   1.000000
               PNeckoParent|Msg_PHttpChannelConstructor               latency: 0.0003    total:   1.000000
                             PContentChild|Msg_VisitURI               latency: 0.0002    total:   3.000000
              PNeckoChild|Msg_PCookieServiceConstructor               latency: 0.0002    total:   1.000000
                        PNeckoChild|Msg_HTMLDNSPrefetch               latency: 0.0002    total:  39.000000
                    PContentChild|Msg_StartVisitedQuery               latency: 0.0001    total:  33.000000
                           PBrowserChild|Msg___delete__               latency: 0.0000    total:   1.000000
(Assignee)

Comment 2

7 years ago
Created attachment 475621 [details] [diff] [review]
Python profiling script
Attachment #475618 - Attachment is obsolete: true
(Assignee)

Updated

7 years ago
Assignee: nobody → azakai
(Assignee)

Comment 3

7 years ago
Created attachment 475941 [details] [diff] [review]
Patch v2

Turns out that since the parent and child outputs go to the same place, they can overwrite each other, dropping or cutting lines in the middle. So, added an option to redirect the child stdout or stderr to a separate file.

Example output (icanhascheezburger/fennec): http://pastebin.mozilla.org/790209
Attachment #475621 - Attachment is obsolete: true
(Assignee)

Comment 4

7 years ago
Created attachment 478079 [details] [diff] [review]
Patch v3

Now with visualization as well.
Attachment #475941 - Attachment is obsolete: true
(Assignee)

Comment 5

7 years ago
Created attachment 478080 [details]
Example visualization output
(Assignee)

Comment 6

6 years ago
Updated versions of the patch are here:

http://hg.mozilla.org/users/azakai_mozilla.com/patches/file/tip/ipc_profiler
(Assignee)

Comment 7

6 years ago
Updated patch (see link in comment 6) now supports profiling on android devices. See comments in android_prettifier.py for details.

Will post some profiling data in bug 629513 soon.
(Assignee)

Comment 8

3 years ago
This is very obsolete.
Status: NEW → RESOLVED
Last Resolved: 3 years ago
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.