1398149 - waterfall timing is broken

Status: RESOLVED FIXED

(DevTools :: Netmonitor, defect, P3)

Description

[Ruturaj Vartak]

Attachment: timing.png

STR:
1. Open http://output.jsbin.com/qefefiyi/9/quiet
2. Open Network tab, do a hard reload

Expected results:
What we see in chrome (left half of attachment#1 [details] [diff] [review]).

What is broken:
The 2nd resource takes ~2.Xs which is evident in 2531ms (right half - firefox), but rendering of the bar is not correct, same is expected of the last 2 resources.

I've checked against the Nightly build as well.

Comment 1

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Thanks for the report!

I can reproduce the problem.


Honza

Comment 2

[Ruturaj Vartak]

Attachment: WIP-1398149-1.patch

This is WIP patch.

There were 2 problems that I've tried to fix
- The `lastEndedMillis` was not updated in UPDATE_REQUEST action
- The flex box seems erroneous (I'm still new to it). A simple inline-block does wonders

Comment 3

[Ruturaj Vartak]

Attachment: screenshot-WIP-1398149-1.png

This is how it now looks for the given test url. The only thing that seems incorrect are the last set of requests' timing text gets clipped !

Comment 4

[Ricky Chien [:rickychien] (inactive)]

Comment on attachment 8942487 [details] [diff] [review]
WIP-1398149-1.patch

Thanks for investigating this! Timeline issue is a bit complex than we think. I believe there is nothing wrong in lastEndedMillis but the way we use `display: flex;` in .requests-list-timings causes this issue.


We should remove `display: flex`, `flex: none;` & `align-items: center;` and then the each request timeline block would be correct. But the last requests timeline blocks are still wrong due to the way we shrinking the timeline.

transform: scaleX(var(--timings-scale))
transform: scaleX(var(--timings-rev-scale)) in requests-list-timings-total

If you look into the width of the div of requests-list-timings-total carefully, it turns out that the current scaleX value seems wrong. The width of requests-list-timings-total div doesn't count in because we're using --timings-rev-scale to enlarge its size but it doesn't included in requests-list-timings div.

You have to tweak the way we apply to scaleX. Maybe only apply scaleX to requests-list-timings-box div individually.

Comment 5

[Ruturaj Vartak]

Attachment: WIP-1398149-2.patch

Hey Ricky,

Thanks for the review. This patch...

- I've commented out request's endTime inclusion
- Commented out CSS from `.requests-list-timings` as u requested
- added 50px width to `requests-list-timings-total`
- excluded this 50px from scale computation in `getWaterfallScale`

The output for `./mach build` 'seems' fine.

Comment 6

[Ruturaj Vartak]

Attachment: launchpad-op.png

The computation of launchpad based netmonitor vs the compiled o/p seems different. The launchpad based o/p differs when I include the request's completion time  vs. not including it (the original code)

Could you provide me link to resources why the request's end time is NOT included in totalTime computation  ?

- Thanks

Comment 7

[Ricky Chien [:rickychien] (inactive)]

Honza, do you have any idea of that?

Comment 8

[Ricky Chien [:rickychien] (inactive)]

Comment on attachment 8942820 [details] [diff] [review]
WIP-1398149-2.patch

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

::: devtools/client/netmonitor/src/assets/styles/RequestList.css
@@ +520,5 @@
>    font-weight: 600;
>  }
>  
>  .requests-list-timings {
> +/*  display: flex;

You should remove the code instead of commenting out once you're sure we don't need it anymore.

::: devtools/client/netmonitor/src/reducers/requests.js
@@ +88,5 @@
>        request = {
>          ...request,
>          ...processNetworkUpdates(action.data),
>        };
> +      // let requestEndTime = request.startedMillis + request.eventTimings.totalTime;

You should remove the code instead of commenting out once you're sure we don't need it anymore.

@@ +94,5 @@
>        return {
>          ...state,
>          requests: mapSet(state.requests, action.id, request),
> +        // lastEndedMillis: requestEndTime > lastEndedMillis ?
> +        //   requestEndTime : lastEndedMillis

likewise above

::: devtools/client/netmonitor/src/selectors/ui.js
@@ +29,2 @@
>    return Math.min(Math.max(
> +    (ui.waterfallWidth - REQUESTS_WATERFALL.LABEL_WIDTH - 50) / longestWidth,

oh, I don't think this works. Visiting your example site and then I can still see truncated numbers.

Comment 9

[Ruturaj Vartak]

Attachment: 50px.png

Hi,

The 50px code is working on linux build env. Can't check others.

It doesn't work in launchpad-based setup if request's lastEndedTime isn't incorporated (attachment#8942821 [details])

Comment 10

[Ruturaj Vartak]

Attachment: fix-1398149-1.patch

- removed unused code in comments
- currently, retaining the 50px buffer for .requests-list-timings-total [Seems to be working in `./mach build on linux`]

Doesn't work as expected in launchpad (as mentioned in comment#6)

Comment 11

[Ricky Chien [:rickychien] (inactive)]

Forward review request to Honza since he has better knowledge on how timeline implementation.

Comment 12

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Comment on attachment 8943258 [details] [diff] [review]
fix-1398149-1.patch

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

Thanks for the patch Ruturaj!

Looks good, just some inline questions/comments, before R+

Honza

::: devtools/client/netmonitor/src/assets/styles/RequestList.css
@@ +577,5 @@
>    font-weight: 600;
>    white-space: nowrap;
>    /* This node should not be scaled - apply a reversed transformation */
>    transform: scaleX(var(--timings-rev-scale));
> +  width: 50px;

How did you calculate this value?
Why is it actually set?

::: devtools/client/netmonitor/src/selectors/ui.js
@@ +24,5 @@
>                                     timingMarkers.firstDocumentDOMContentLoadedTimestamp,
>                                     timingMarkers.firstDocumentLoadTimestamp);
>    const longestWidth = lastEventMillis - requests.firstStartedMillis;
> +
> +  // Reduce 50px for the last request's requests-list-timings-total

This represents the gap between the time label and right browser margin, correct? If yes, let's save some more space and use 20. I think it should be enough.

Comment 13

[Ruturaj Vartak]

Thanks Honza for the review.

> +  width: 50px;
> How did you calculate this value?
> Why is it actually set?

Ya that 50px was for some margin/padding that would be generated by reducing available width for the div[s]. However the `width` css was unnecessary.

The bars still overflow in the launchpad mode (strangely it doesn't happen in ./mach build). I had initially suggested inclusion of the request's endTime (attachment #8942487 [details] [diff] [review]) in the calculation as well (which ensured it looked fine in launchpad). Donno why it renders differently in launchpad based setup vs. ./mach build. Would love to fix that here if its in the scope of this bug.

Thanks

Comment 14

[Ruturaj Vartak]

The `width` was initially added to give some "space" to the totals, However if there is enough available space for the div to "grow" the width would be redundant.

Comment 15

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(In reply to Ruturaj Vartak from comment #13)
> The bars still overflow in the launchpad mode (strangely it doesn't happen
> in ./mach build). I had initially suggested inclusion of the request's
> endTime (attachment #8942487 [details] [diff] [review] [diff] [review]) in the calculation
> as well (which ensured it looked fine in launchpad).
I tried the attachment #8942487 [details] [diff] [review], but no luck, still broken.
Can you update the current patch? 

> Donno why it renders
> differently in launchpad based setup vs. ./mach build. Would love to fix
> that here if its in the scope of this bug.
Yes, I think this bug should fix both, the Toolbox and the Launchpad
since the issue is tightly related to both.

Could the difference between Toolbox and Launchpad be the hidden
in the scaling logic?

Honza

Comment 16

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Also, there is a patch in bug 1431457 that fixes the Launchpad for Net monitor. Not sure what is your setup, but you might need the patch if you are experiencing some troubles when `yarn start`ing the Launchpad.

Honza

Comment 17

[Ruturaj Vartak]

Attachment: fix-1398149-2.patch

Thanks for the reply.

I've updated the patch, that patch now has..

- request's EndTime inclusion in width calc.
- reducing the avail width for div by 20px

I didn't have any problem with launchpad, just that the o/p of launchpad differed that from ./mach build.

Comment 18

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Comment on attachment 8944395 [details] [diff] [review]
fix-1398149-2.patch

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

Thanks for the patch!

R+, but please see my inline comments.

Honza

::: devtools/client/netmonitor/src/assets/styles/RequestList.css
@@ +577,5 @@
>    font-weight: 600;
>    white-space: nowrap;
>    /* This node should not be scaled - apply a reversed transformation */
>    transform: scaleX(var(--timings-rev-scale));
> +  /*width: 20px;*/

Any reason why the width prop is still here?
If you want to keep it, please add a comment explaining why it's commented out.

::: devtools/client/netmonitor/src/reducers/requests.js
@@ +88,5 @@
>        request = {
>          ...request,
>          ...processNetworkUpdates(action.data),
>        };
> +      let requestEndTime = request.startedMillis + request.eventTimings.totalTime;

`request.enventTimings` can be null since this info is fetched from the backend lazily (only when needed)

You might do something like as follows:

let requestEndTime = request.startedMillis +
  (request.eventTimings ? request.eventTimings.totalTime : 0);

Comment 19

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Try push:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=bf228b636e4cf19588134796c8983ea24b3564d4

Honza

Comment 20

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Also, needs to be rebased on top of m-c head.

Honza

Comment 21

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(In reply to Jan Honza Odvarko [:Honza] from comment #19)
> Try push:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=bf228b636e4cf19588134796c8983ea24b3564d4
I am seeing some eslint failures.

Honza

Comment 22

[Ruturaj Vartak]

Attachment: fix-1398149-3.patch

- rebased master
- removed commented width of 20px
- checked eslint errors
```
$ ./mach eslint devtools/client/netmonitor/src/
✖ 0 problems (0 errors, 0 warnings)
```

Comment 23

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Comment on attachment 8945405 [details] [diff] [review]
fix-1398149-3.patch

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

Thanks for the update!

The timeline looks a lot better now, but I can see yet one problem. The first request (with start time == 0) doesn't start at the beginning. 
It's nicely visible with a simple page (e.g. html with one css), you might also try google.com
Screenshot coming...

Honza

Comment 24

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Attachment: timeline.png

Comment 25

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Btw. there is a Bug 1432834 that breaks rendering of the vertical lines (with patch attached),
so you might want to use it to see nice Net panel content.

Honza

Comment 26

[Ruturaj Vartak]

Attachment: fix-1398149-4.patch

Nice Catch! I couldn't get it :(

- removed the culprit 'text-align: center' in .requests-list-column.

Things look good now.

I looked at Bug#1398149, yes post the patch application it looks fine. However I haven't included the patch as its already been pushed and will get merged.

Comment 27

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Comment on attachment 8945433 [details] [diff] [review]
fix-1398149-4.patch

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

Looks great!
R+

Thanks Ruturaj,
Honza

Comment 28

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/da2822509229
Waterfall timing is broken. r=Honza

Comment 29

[Arthur Iakab [arthur_iakab]]

https://hg.mozilla.org/mozilla-central/rev/da2822509229