search

firefox-devtools / profiler

Firefox Profiler — Web app for Firefox performance analysis
https://profiler.firefox.com
Mozilla Public License 2.0
1.2k stars 390 forks source link

Network chart shows loading sub-phases in the wrong place sometimes #1681

Closed mstange closed 5 years ago

mstange commented 5 years ago

In this profile, look at the light gray piece inside the bar for the request to https://aax.amazon-adsystem.com/e/dtb/bid?src=3079&u=...: The piece is at the very start of the bar.

However, in the parent process you can see that nothing happens at that time. I think this means that that light gray piece is drawn in the wrong spot.

screen shot 2019-01-24 at 11 30 12 am screen shot 2019-01-24 at 11 30 49 am

The cause for this is known, too: The outer box starts at marker.data.startTime: https://github.com/devtools-html/perf.html/blob/f7a938c1b8efbe08e61862f02ba839e364948319/src/components/network-chart/index.js#L199 whereas the empty space before the gray piece, which is taken up by the requestQueue box, thinks the start is at marker.start: https://github.com/devtools-html/perf.html/blob/f7a938c1b8efbe08e61862f02ba839e364948319/src/components/network-chart/NetworkChartRow.js#L90

And those two values can apparently be different. I think we need to understand exactly what they mean and when they can be different. I'm also extremely confused by some of the variable names in the NetworkChartRowBar component, I think they could use a cleanup.

julienw commented 5 years ago

See https://github.com/devtools-html/perf.html/issues/1685#issuecomment-463256698, I think this is also valid here.

To answer the specific question above: start and startTime can be different because of the merging markers algorithm. I believe startTime should be updated as well though.

In https://github.com/devtools-html/perf.html/issues/1715 I wrote that the merging algorithm should also happen elsewhere. Maybe we can make it more solid by redoing it it deriveMarkersFromRawMarkerTable.

julienw commented 5 years ago

This may be fixed in https://github.com/firefox-devtools/profiler/pull/1746 but I'd like to keep it open until I fix #1715 too.

julienw commented 5 years ago

So this isn't fixed, neither by #1746 or by my WIP patch in #1715. Though as far as I understand, it's being painted properly from the markers we get in the profile.

Here's the pair of markers in the parent process:

[
  {
    "type": "Network",
    "startTime": 412963.286353,
    "endTime": 412969.141353,
    "id": 126521146607351,
    "status": "STATUS_START",
    "cache": "Unresolved",
    "pri": 20,
    "URI": "https://aax.amazon-adsystem.com/e/dtb/bid?src=3079&u=https%3A%2F%2Fm.imgur.com%2Fgallery%2FZ6ojwdK&pid=8727201622851548270054996&cb=8333420437721548270354056&ws=360x512&v=7.24.00&t=2000&slots=%5B%7B%22sd%22%3A%22004054a9-57bf-4222-828a-227c06aac8ca%22%2C%22s%22%3A%5B%22300x250%22%5D%2C%22sn%22%3A%22%2F4761660%2FMWeb4.1_300x250%22%7D%5D&pj=%7B%22apse%22%3A%7B%22chunkRequests%22%3Afalse%2C%22shouldSampleLatency%22%3Afalse%7D%7D&st=%7B%22917%22%3A%220%22%7D&gdprl=%7B%22status%22%3A%22cmp-error%22%7D"
  },
  {
    "type": "Network",
    "startTime": 412969.141353,
    "endTime": 413204.904061,
    "id": 126521146607351,
    "status": "STATUS_STOP",
    "cache": "Missed",
    "pri": 20,
    "count": 367,
    "URI": "https://aax.amazon-adsystem.com/e/dtb/bid?src=3079&u=https%3A%2F%2Fm.imgur.com%2Fgallery%2FZ6ojwdK&pid=8727201622851548270054996&cb=8333420437721548270354056&ws=360x512&v=7.24.00&t=2000&slots=%5B%7B%22sd%22%3A%22004054a9-57bf-4222-828a-227c06aac8ca%22%2C%22s%22%3A%5B%22300x250%22%5D%2C%22sn%22%3A%22%2F4761660%2FMWeb4.1_300x250%22%7D%5D&pj=%7B%22apse%22%3A%7B%22chunkRequests%22%3Afalse%2C%22shouldSampleLatency%22%3Afalse%7D%7D&st=%7B%22917%22%3A%220%22%7D&gdprl=%7B%22status%22%3A%22cmp-error%22%7D",
    "requestStart": 412990.322655,
    "responseStart": 413199.781405,
    "responseEnd": 413201.305363
  },
]

And here is the pair of markers in the content process:

[
  {
    "type": "Network",
    "startTime": 408333.27306348435,
    "endTime": 408334.0895224844,
    "id": 126521146607351,
    "status": "STATUS_START",
    "pri": 20,
    "URI": "https://aax.amazon-adsystem.com/e/dtb/bid?src=3079&u=https%3A%2F%2Fm.imgur.com%2Fgallery%2FZ6ojwdK&pid=8727201622851548270054996&cb=8333420437721548270354056&ws=360x512&v=7.24.00&t=2000&slots=%5B%7B%22sd%22%3A%22004054a9-57bf-4222-828a-227c06aac8ca%22%2C%22s%22%3A%5B%22300x250%22%5D%2C%22sn%22%3A%22%2F4761660%2FMWeb4.1_300x250%22%7D%5D&pj=%7B%22apse%22%3A%7B%22chunkRequests%22%3Afalse%2C%22shouldSampleLatency%22%3Afalse%7D%7D&st=%7B%22917%22%3A%220%22%7D&gdprl=%7B%22status%22%3A%22cmp-error%22%7D"
  },
  {
    "type": "Network",
    "startTime": 408334.0895224844,
    "endTime": 413251.0552494844,
    "id": 126521146607351,
    "status": "STATUS_STOP",
    "pri": 20,
    "count": 701,
    "URI": "https://aax.amazon-adsystem.com/e/dtb/bid?src=3079&u=https%3A%2F%2Fm.imgur.com%2Fgallery%2FZ6ojwdK&pid=8727201622851548270054996&cb=8333420437721548270354056&ws=360x512&v=7.24.00&t=2000&slots=%5B%7B%22sd%22%3A%22004054a9-57bf-4222-828a-227c06aac8ca%22%2C%22s%22%3A%5B%22300x250%22%5D%2C%22sn%22%3A%22%2F4761660%2FMWeb4.1_300x250%22%7D%5D&pj=%7B%22apse%22%3A%7B%22chunkRequests%22%3Afalse%2C%22shouldSampleLatency%22%3Afalse%7D%7D&st=%7B%22917%22%3A%220%22%7D&gdprl=%7B%22status%22%3A%22cmp-error%22%7D",
    "requestStart": 412990.3221764844,
    "responseStart": 413199.7809264844,
    "responseEnd": 413201.3048844844
  },
]

We clearly see that the first marker in the content process starts much earlier. If that's not expected then there's rather a problem in Gecko.

Also I don't know why count is different between parent and content... Maybe another bug?

cc @jesup

mstange commented 5 years ago

We clearly see that the first marker in the content process starts much earlier. If that's not expected then there's rather a problem in Gecko.

It is expected - it is unfortunate but it accurately reflects what happened. (The reason it took so long for the parent process to hear about this request is that the request went through multiple back and forth bounces between the content process main thread and a service worker thread in the content process, before it was passed on to the parent process.)

julienw commented 5 years ago

@mstange, so is the rendering actually correct here ? or is the problem that the grey subpart shouldn't be completely at the left ?

mstange commented 5 years ago

The problem is that the grey subpart shouldn't be completely at the left.

julienw commented 5 years ago

I see! Looking at the code I think I know why this happens and I started a fix.

julienw commented 5 years ago

In the profile, I see there are some markers that look wrong, for example look at this search-filtered marker table view => the id in the name seems to be off (I also checked the "id' field in the json payload, they seem different as well).

@mstange I'd be interested to have the URL you captured here to see if this specific issue can be reproduced.