New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 594800 link

Starred by 8 users

Issue metadata

Status: Fixed
Owner:
Closed: Feb 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: All
Pri: 2
Type: Feature



Sign in to add a comment

DevTools: Add server-timing details into Network panel

Project Member Reported by paulir...@chromium.org, Mar 14 2016

Issue description

The Server-Timing spec provides a response header to attach metrics from the server to a request. 

Spec: http://w3c.github.io/server-timing/


There's been discussion to add support to the DevTools to surface these figures along with the existing network timing. 


 
igrigorik@: can we add startTime into events (even though out of sync w/ client)? 

That way we can do a best effort to align the earliest with the beginning of the wait and surface server-side timing in a UI rich waterfall format.
CL is up here https://codereview.chromium.org/1794783006/

Images from the email thread attached.
Screen Shot 2016-03-13 at 2.44.30 PM.png
68.6 KB View Download
Screen Shot 2016-03-13 at 2.44.39 PM.png
227 KB View Download
Screen Shot 2016-03-13 at 2.44.55 PM.png
62.3 KB View Download
@ilya, yeah if we had some idea of a startTime for the metrics we could visually plot them a bit easier.

@steve, without a starttime we should still try to visualize the durations. Mock attached. (But ideally we have startTimes too)
Screen Shot 2016-03-14 at 4.23.22 PM.png
72.1 KB View Download

Comment 4 by srous...@gmail.com, Mar 15 2016

Slightly updated graphic to match latest patch.
Screen Shot 2016-03-14 at 10.16.51 PM.png
58.4 KB View Download

Comment 5 by srous...@gmail.com, Mar 15 2016

It can be a little odd to show bar chart type graph when you don't know how they tie together like the first set. My default is to use a pie chart instead, but hard to label that, and my extension will do that anyhow.

Maybe if the server-time bars are all centered together in the middle of the start-end range. But the total server time had better be less than the waiting and transfer time. :)

Comment 6 by srous...@gmail.com, Mar 15 2016

Screen Shot 2016-03-14 at 10.16.51 PM.png
58.6 KB View Download

Comment 7 by srous...@gmail.com, Mar 15 2016

Actually, now that I have thought about it more, if we want bars in the server timing area, maybe they should be outlines, and not filled in. That would visually distinguish them a bit.

One reason I didn't do the bars at all though, is that the names can be really long since they are not static names, but are user input.
True. That works for me. 
Labels: -Type-Bug Type-Feature
I think StartTime might only be useful in small response structures.

i.e. A developer could have multiple database calls. Do they all "start" at the same time? No, they happen at different times throughout the application lifecycle. So, either you group them all and just do the earliest startTime as a middle-ground or you do multiple DB call displays (for each request) which could easily become unruly.

I think the best solution is to visualize duration as Irish has provided a mockup for. With a bonus for a coloring legend based on the amount of the total service timing used. i.e. Blue for short sections indicating low-impact. Red for things that are taking up a majority of the total server timing. (Maybe orange for an in-between if we want to try to calculate that.)

Comment 10 by srous...@gmail.com, Mar 15 2016

These times are all cumulative. That is, all the time taken in MySQL. All the time dealing with a cache server. All the time taken dealing with the filesystem.

I can add the graphs. It is possible to have the server time headers lie, so I will scale the data to request finish - request sent so it never looks longer then the request recorded by Chrome (this is only if the data returned is greater than what Chrome knows it to be, and should not happen in practice).

To make the graphs comparable, I will need to keep everything in the same table. But to avoid having the graph area too small, I will need to clip the names of the server-timing description. Have a preference for max-width of that column??

The other thought is to represent as a pie chart.
>> These times are all cumulative. That is, all the time taken in MySQL. All the time dealing with a cache server. All the time taken dealing with the filesystem.

Which is sad since not aggregating it could give a much better idea on the flow of events. Such technique is called "structural profiling" as opposed to the "instrumenting profiling". It is based on the high level user markup with the timers. Then we surface this information in the tools and it starts adding much more value.

>> I can add the graphs. It is possible to have the server time headers lie...

Only if we get valid start times for it. Pinging igrigorik@ for it.

Comment 12 by bmau...@fb.com, Mar 15 2016

Labels: DevRel-Facebook
One thing that could be really helpful here is if we could log the time at which the header was received. One extremely challenging problem that we encounter at facebook is that we use chunked encoding to flush the page multiple times. It's hard for people to understand when the client received some set of bytes 

Wrote up some more details here: https://github.com/w3c/server-timing/issues/4

Comment 13 by srous...@gmail.com, Mar 16 2016

My experience with FirePHP where I send a lot more data in the headers is that it breaks Chrome pretty bad after a certain size. Somewhere in Chrome or DevTools, everything just breaks. We have to clip things on the server side.

This having been an issue for a long time (and also an issue on other browsers), a lot of people with custom tools have moved to sending a token in a header, and have their extension call back for more information. This means setting up a data store for this kind of debugging, but it works pretty well. The original author of FirePHP had done something like this, and I would have to guess that z-ray does as well. I was planning at adding it to Illuminations for Developers at one point.

I've thought of using such a token system to pull in web-cachegrind as well, but that profiling information is massive. We don't want hundreds of megabytes going into headers. It is not something to use Server-Timing for.

That said, it would be interesting to condense that data into a format that could be used natively inside DevTools, and use the DevTools checkboxes for profiling to include server side stuff as well. Heck, at that point, chain the call stack from the client to the call stack of the server, etc. Or include a way to plug in server side debug systems like xdebug natively in the browser so you can step "inside" from the client to the server. Actually, this would be easier with nodejs, but might was well wish for anything in the ideal. ;)

Anyhow, back to Server-Timing and its simplicity. There may be other ways to look at marrying the backend and the frontend, but I don't think we need to overload it here.

Comment 14 by srous...@gmail.com, Mar 16 2016

As for chunking, it would be interesting to show that in the timing panel if it were available.

BTW: A rough draft (not even a screenshot) of my server timing extension is here: 
https://chrome.google.com/webstore/detail/server-timing/lhebeopdclghecelfokfapiamfjmifdo
It consolidates all the requests on a page together.
@bmaurer, fwiw the current (experimental) network data on the timeline reveals the timestamps for response headers received and each TCP segment.
Screen Shot 2016-03-15 at 6.59.29 PM.png
65.7 KB View Download

Comment 16 by srous...@gmail.com, Mar 17 2016

So this is how my latest version looks (not uploaded yet). Thoughts?
Screen Shot 2016-03-16 at 9.56.54 PM.png
47.5 KB View Download

Comment 17 by srous...@gmail.com, Mar 17 2016

The server-timing extension on the same page (different run):
Screen Shot 2016-03-16 at 10.06.29 PM.png
128 KB View Download

Comment 18 by srous...@gmail.com, Mar 19 2016

OK, these are the versions I have working:

Comment 19 by srous...@gmail.com, Mar 19 2016

v1 is that is in https://codereview.chromium.org/1794783006

Comment 20 by srous...@gmail.com, Mar 19 2016

I found a hashing algo in devtools and a list of names, so used those (but 50% transparent), and it looks like this:
Screen Shot 2016-03-19 at 3.22.34 PM.png
87.1 KB View Download
We're in the process of nuking all pie charts in the UI. Google `pie charts are bad` for plenty of commentary on why, but the short version is: they make comparison between items very difficult. And for developers, evaluating relative values is often more important than identifying the one largest component. 

Your option 4.png in c#18 is pretty ideal, IMO. Using the color hashing for it seems nice, too. 
sroussey: for your extension. 1) what are the smaller concentric circles? Previous runs? 2) Got a test URL to use that emits server-timing data in production?

Comment 23 by srous...@gmail.com, Mar 20 2016

The extension's summary view of concentric circles are more obvious with an example page, which I need to make public somewhere.

The main one is the sum of the children (or average, depending on your point of view). The inner ones are all the requests of the page. As new requests come in, new inner circles are created, and the outer one adjusts to account for the new information. They are all animated so they are fun to watch.

Thus the table next to it is sum of all the others.

Below are the individual requests. The UI needs work, but I really needed the summary table of all requests.

A stock type column chart might be interesting, showing the range of various requests (that has a non-zero value). Or a stacked column. There are a number of scenarios to play with. I wanted a pie chart for a meeting, to have various teams guess which slice was what.

There is also the part in the concentric circles where you can see that one response was dominated by "Other" -- you wouldn't see that at a glance with a stacked graph.

The summary will be available in the page action menu (which will need to change to a browser action menu unfortunately). It makes a nice concise view.

Comment 24 by srous...@gmail.com, Mar 20 2016

I found the FlameChart consistent hashing color generator, so using that here. Should be easy enough to change the color scheme.
Screen Shot 2016-03-20 at 2.49.51 PM.png
50.6 KB View Download

Comment 25 by srous...@gmail.com, Mar 20 2016

I couldn't stand the total being colored like that. And since "total" would always hash to that color...

Anyhow, it is easy to adjust the color scheme. I can upload the code for this version.
Screen Shot 2016-03-20 at 2.54.10 PM.png
67.6 KB View Download
Seems good. Yeah let's get this iteration in the CL.
Apologies about the delayed response(s). 

pfeldman: startTimes are meaningless because they're coming from a different time source (or multiple - e.g. origin and CDN servers injecting own headers), and with unknown network delays. The only thing we can reason about is the duration.

sroussey: I'm a bit wary of the piechart and the % measures. It's perfectly reasonable for multiple operations to overlap but then be reported as separate ST entries; to be safe, we should assume that ST reports CPU time, not wall-clock time.

Re, firePHP: Chrome's old speedtracer extension took the same approach. ST is an intentionally simplified version of that. Fetching multi-MB reports is not a RUM friendly approach; our goal is not to enable deep server-side tracing, but to enable RUM gathering of high-level server timing metrics.

Implementation questions:
- Looks like "total" name is treated as special, but we don't define any such behavior in the spec. What happens when the user omits it?
- Does the extension work with comma delimited headers, instead of individual headers? If not, it should, because an intermediary is allowed to combine (and split) such headers.

bmaurer: I'll followup on GitHub issue; I think what you're asking for is mostly orthogonal to what's being discussed here. 

Comment 28 by srous...@gmail.com, Mar 21 2016

For DevTools: 

Latest version has a chart, but not a pie chart. No % in there other than visual. 

I don't actually add up the timing information, since, as you said, the total of the metric timings could be more than the total time spent in the request (and why I report a metric with the name total at the bottom). My initial version for this was to have no charting, and only report the numbers.

The total metric, if removed, just means that no line will get the bolded timing.

I'm afraid I don't know what you mean by comma delimited headers. What do you mean by that?
> I'm afraid I don't know what you mean by comma delimited headers. What do you mean by that?

Server-Timing: a=123;"description for A", b=245;"description for B"

vs

Server-Timing: a=123;"description for A"
Server-Timing: b=245;"description for B"

Both are equivalent, valid, and maybe transformed from one representation to the other.

Comment 30 by srous...@gmail.com, Mar 21 2016

For my extension:

Now, for my extension, I can do whatever seems valuable to me. ;) I actually plan to to support something like this:

 Server-Timing: sql-1: 0.1; "MySQL Lookup Server"
 Server-Timing: sql-2: 0.9; "MySQL Shard Server #1"
 Server-Timing: sql-3: 1.2; "Oracle Archive Server"
 Server-Timing: cpu: 2.3; "CPU"

And in the individual request view, I can do the concentric circle thing again, but this time (for the above data) that would look like two circles: one with that would split the donut by cpu vs sql, and an inner pie that would show all four values.

This has nothing to do with the spec, per se, but with a convention on how to use it for this particular extension. More dashes would mean more concentric donut charts, assuming that there was grouping information (for example, if there were only two ST headers like data-sql-mysql and cpu, then it would only do a pie chart since there were no other headers that shared a common prefix ending in a dash).

Comment 31 by srous...@gmail.com, Mar 21 2016

There is something in the DevTools code I forgot to deal with: any timing value greater than the expected time of the full request. Because then the chart is wack since there is no scale. If any value is that high, none should likely be graphed. Or the one with a high number is not graphed. 

An example:

 Server-Timing: preprocessing: 3600.0

In this case, a value related is sent: that pre-processing of a data set had taken an hour. The request itself could take less than a second.

Comment 32 by srous...@gmail.com, Mar 21 2016

Is that an HTTP spec thing? I don't see it explicitly mentioned here:

https://w3c.github.io/server-timing/#dfn-server-timing-header-field

Comment 33 by srous...@gmail.com, Mar 21 2016

I found it in the HTTP spec. I guess my question is, does Chrome de-combine them by the time I get the header values? I guess I will need to test.
For reference: http://httpwg.org/specs/rfc7230.html#abnf.extension

"Decombine": no, it shouldn't, and you shouldn't expect it to.

Comment 35 by srous...@gmail.com, Mar 29 2016

OK, I am now more precise with the regexp "parsing" of the headers. It is a little loose with the quoted string. And now that I know what the # means in the spec, it also does comma delimited headers.

Also, I noticed in the spec that the actual timing value is optional, so I handle that gracefully was well. And if the numbers returned would cause drawing artifacts (the number being too big), then I don't display the bar at all.
Where to go from here?
could you ping me from the most recent relevant CL?
Cc: seththompson@chromium.org
Status: Started (was: Assigned)
CL: https://codereview.chromium.org/1794783006
Status: Fixed (was: Started)
About time we close this ticket, eh?

Thanks again, Steven!
servertiming.png
234 KB View Download

Comment 42 by kayce@google.com, Feb 8 2017

Labels: DevTools-Release-Notes-Feature
Project Member

Comment 43 by bugdroid1@chromium.org, Feb 14 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/968553977ba5cf51409101104a51431d60b051cd

commit 968553977ba5cf51409101104a51431d60b051cd
Author: paulirish <paulirish@chromium.org>
Date: Tue Feb 14 04:26:42 2017

DevTools: Server Timing values should be in milliseconds

This is a breaking change. This feature landed in August, but just announced
this week (twitter.com/paul_irish/status/829090506084749312).
Users discovered the original patch used seconds values, but the Server
Timing spec dictates these as DOMHighResTimeStamp which are milliseconds.

BUG= 594800 

Review-Url: https://codereview.chromium.org/2689833002
Cr-Commit-Position: refs/heads/master@{#450244}

[modify] https://crrev.com/968553977ba5cf51409101104a51431d60b051cd/third_party/WebKit/Source/devtools/front_end/network/RequestTimingView.js
[modify] https://crrev.com/968553977ba5cf51409101104a51431d60b051cd/third_party/WebKit/Source/devtools/front_end/sdk/ServerTiming.js

Sign in to add a comment