Improve net-internals crash course.

net/docs/crash-course-in-net-internals.md

Index: net/docs/crash-course-in-net-internals.md
diff --git a/net/docs/crash-course-in-net-internals.md b/net/docs/crash-course-in-net-internals.md
index 529c7d2c2a792a484e184d3bb66934bc918101ab..d5dd0d3531393c1126885abd4431bf80aa2d58f6 100644
--- a/net/docs/crash-course-in-net-internals.md
+++ b/net/docs/crash-course-in-net-internals.md
@@ -16,74 +16,118 @@ etc.
 
 The top level network stack object is the URLRequestContext.  The Events View
 has information for all Chrome URLRequestContexts that are hooked up to the
-single, global, ChromeNetLog object.  This includes both incognito and non-
-incognito profiles, among other things.  The Events view only shows events for
-the period that net-internals was open and running, and is incrementally updated
-as events occur.  The code attempts to add a top level event for URLRequests
-that were active when the tab was opened, to help debug hung requests, but
-that's best-effort only, and only includes requests for the current profile and
-the system URLRequestContext.
+single, global, ChromeNetLog object.  This includes both incognito and
+non-incognito profiles, among other things.  The Events view only shows events
+for the period that net-internals was open and running, and is incrementally
+updated as events occur.  The code attempts to add a top level event for
+URLRequests that were active when the about:net-internals tab was opened, to
+help debug hung requests, but that's best-effort only, and only includes
+requests for the current profile and the system URLRequestContext.
 
 The other views are all snapshots of the current state of the main
 URLRequestContext's components, and are updated on a 5 second timer.  These will
 show objects that were created before about:net-internals was opened.  Most
-debugging is done with the Events view (which will be all this document
-covers), but it's good to be aware of this distinction.
+debugging is done with the Events view (which will be all this document covers),
+but it's good to be aware of this distinction.
 
 # Events vs Sources
 
 The Event View shows events logged by the NetLog.  The NetLog model is that
 long-lived network stack objects, called sources, emit events over their
-lifetime.  When looking at the code, a "NetLogWithSource" object contains a source
-ID, and a pointer to the NetLog the source emits events to.  Some events have a
-beginning and end point (during which other subevents may occur), and some only
-occur at a single point in time.  Generally only one event can be occuring for a
-source at a time.  If there can be multiple events doing completely independent
-thing, the code often uses new sources to represent the parallelism.
+lifetime.  When looking at the code, a NetLogWithSource object contains a source
+ID, a NetLogSourceType, and a pointer to the NetLog the source emits events to.
+
+Sources show up in the left column of the Event View.  Sources that include an
+event with a net_error parameter with negative value (that is, some kind of
+ERR_) are shown with red background.  Sources whose opening event has not ended
+yet are shown with white background.  Other events have green background.  The
+search queries corresponding to the first two kinds are `is:error` and
+`is:active`.  The legend for these and other search queries appears if one
+hovers over the (?) next to the filter box on top of the event list.
+
+Events corresponding to selected sources show up in the right column, organized
+by source, and by time within each source.  There are two time values: t is
+measured from some reference point common to all sources, and st is measured
+from the first event for each source.  Time is displayed in milliseconds.
+
+Since the network stack is asynchronous, events from different sources will
+often be interlaced in time, but Event View does not feature showing events from
+different sources ordered by time.  Large time gaps in the event list of a
+single source do not necessarily mean that all that time is spend on that
+source.

[Randy Smith (Not in Mondays), 2016/11/15 23:18:42]

Suggestion (if you agree): I might make a stronger statement, that large time
gaps usually means that the time is being spent in the context of another
source.

[Bence, 2016/11/16 14:12:51]

Done.

+
+Some events come in pair: a beginning and end event, between which other events
+may occur.  They are shown with + and - prefixes, respectively.  The begin event
+has a dt value which shows the duration, the time difference between the begin
+and end.  If there are no other events in between the begin and end, and the end
+event has no parameters, then they are collapsed in a single line.

[Randy Smith (Not in Mondays), 2016/11/15 23:18:42]

Is the dt not present if the end event hasn't yet occurred?

[Bence, 2016/11/16 14:12:51]

I am not sure there is any added value in spelling it out here, but I can add
the following two sentences if you think it is worthwhile:

If the end event is not present and net-log is still capturing, "dt=?" is
displayed.  If capturing was stopped before an end event was logged, a value
followed by a + sign is displayed, for example, "dt=120+", which means that
capturing was stopped 120 ms after the begin event.

Note that strictly speaking the statement "if the end event is present, then the
begin event has a dt value" is correct nonetheless.

[Randy Smith (Not in Mondays), 2016/11/16 14:17:25]

Certainly a fair point (whether or not the extra detail is worth including).  My
inclination is to say that explaining the "dt=n+" syntax is worthwhile but the
dt=? syntax is pretty obvious, but up to you.

[Bence, 2016/11/16 15:04:33]

I agree.  Not mentioning what happens in live view is also more robust against a
potential removal of the live view feature.  :)

+
+Some other events only occur at a single point in time.

[Randy Smith (Not in Mondays), 2016/11/15 23:18:41]

Suggestion: "... and will not have a sign prefix."

[Bence, 2016/11/16 14:12:51]

Done.

+
+Generally only one event can be occuring for a source at a time.  If there can
+be multiple events doing completely independent things, the code often uses new
+sources to represent the parallelism.

[Randy Smith (Not in Mondays), 2016/11/15 23:18:41]

FYI (not actionable): I've repeatedly wished for (and once tried to do as a 20%
project) a visualization where next to the source list would be effectively a
gaant chart showing how long each source was active in relationship to other
sources.   You could imagine extending that to include some graphical indication
of begin/end events within a source.

[Bence, 2016/11/16 14:12:51]

Acknowledged.

+
+Most, but not all events correspond to a source.  Exceptions are global events,
+which have no source, and show up as individual entries in the source list.
+Examples include NETWORK_CHANGED, DNS_CONFIG_CHANGED, and PROXY_CONFIG_CHANGED.
+
+# Common source types
 
 "Sources" correspond to certain net objects, however, multiple layers of net/
 will often log to a single source.  Here are the main source types and what they
-include (Excluding HTTP2 [SPDY]/QUIC):
+include (excluding HTTP2 [SPDY]/QUIC):
 
 * URL_REQUEST:  This corresponds to the URLRequest object.  It includes events
 from all the URLRequestJobs, HttpCache::Transactions, NetworkTransactions,
 HttpStreamFactoryImpl::Requests, HttpStream implementations, and
 HttpStreamParsers used to service a response.  If the URL_REQUEST follows HTTP
 redirects, it will include each redirect.  This is a lot of stuff, but generally
-only object is doing work at a time.  This event source includes the full URL
-and generally includes the request / response headers (Except when the cache
+only one object is doing work at a time.  This event source includes the full
+URL and generally includes the request / response headers (except when the cache
 handles the response).
 
-* HTTP_STREAM_JOB:  This corresponds to HttpStreamFactoryImpl::Job (Note that
+* HTTP_STREAM_JOB:  This corresponds to HttpStreamFactoryImpl::Job (note that
 one Request can have multiple Jobs).  It also includes its proxy and DNS
-lookups.  HTTP_STREAM_JOB log events are separate from URL_REQUEST because
-two stream jobs may be created and races against each other, in some cases -
-one for one for QUIC, and one for HTTP.  One of the final events of this source
-indicates how an HttpStream was created (Reusing an existing SOCKET /
-HTTP2_SESSION / QUIC_SESSION, or creating a new one).
+lookups.  HTTP_STREAM_JOB log events are separate from URL_REQUEST because two
+stream jobs may be created and races against each other, in some cases -- one
+for one for QUIC, and one for HTTP.  One of the final events of this source,

[Randy Smith (Not in Mondays), 2016/11/15 23:18:41]

duplicate "one for"

[Bence, 2016/11/16 14:12:51]

Done.

+before the HTTP_STREAM_JOB_BOUND_TO_REQUEST event, indicates how an HttpStream
+was created: A SOCKET_POOL_BOUND_TO_CONNECT_JOB event means that a new TCP
+socket was created, whereas a SOCKET_POOL_REUSED_AN_EXISTING_SOCKET event
+indicates that an existing TCP socket was reused for a non-HTTP/2 request.  An
+HTTP2_SESSION_POOL_IMPORTED_SESSION_FROM_SOCKET event indicates that a new
+HTTP/2 session was opened by this Job.  A
+HTTP2_SESSION_POOL_FOUND_EXISTING_SESSION event indicates that the request was
+served on a preexisting HTTP/2 session.  A
+HTTP2_SESSION_POOL_FOUND_EXISTING_SESSION_FROM_IP_POOL event means that the
+request was pooled to a preexisting HTTP/2 session which had a different
+SpdySessionKey, but DNS resolution resulted in the same IP, and the certificate
+matches.  There are currently no events logged for opening new QUIC sessions or
+reusing existing ones.

[Randy Smith (Not in Mondays), 2016/11/15 23:18:41]

I'd suggest reformatting this paragraph as a bulleted list.

[Bence, 2016/11/16 14:12:51]

Done.

 
 * CONNECT_JOB:  This corresponds to the ConnectJob subclasses that each socket
-pool uses.  A successful CONNECT_JOB return a SOCKET.  The events here vary a
+pool uses.  A successful CONNECT_JOB returns a SOCKET.  The events here vary a
 lot by job type.  Their main event is generally either to create a socket, or
-request a socket from another socket pool (Which creates another CONNECT_JOB)
-and then do some extra work on top of that - like establish an SSL connection on
+request a socket from another socket pool (which creates another CONNECT_JOB)
+and then do some extra work on top of that -- like establish an SSL connection on
 top of a TCP connection.
 
 * SOCKET:  These correspond to TCPSockets, but may also have other classes
-layered on top of them (Like an SSLClientSocket).  This is a bit different from
+layered on top of them (like an SSLClientSocket).  This is a bit different from
 the other classes, where the name corresponds to the topmost class, instead of
 the bottommost one.  This is largely an artifact of the fact the socket is
-created first, and then SSL (Or a proxy connection) is layered on top of it.
+created first, and then SSL (or a proxy connection) is layered on top of it.
 SOCKETs may be reused between multiple requests, and a request may end up
 getting a socket created for another request.
 
 * HOST_RESOLVER_IMPL_JOB:  These correspond to HostResolverImpl::Job.  The
 include information about how long the lookup was queued, each DNS request that
-was attempted (With the platform or built-in resolver) and all the other sources
+was attempted (with the platform or built-in resolver) and all the other sources
 that are waiting on the job.
 
 When one source depends on another, the code generally logs an event with
-"source_dependency" value to both sources, which lets you jump between the two
+`source_dependency` value to both sources, which lets you jump between the two
 related events.
 
 # Debugging
@@ -96,18 +140,15 @@ you can search for "redirect".  However, you often won't have much information
 about the actual problem.  There are two filters in net-internals that can help
 in a lot of cases:
 
-* "type:URL_REQUEST is:error" will restrict the list to URL_REQUEST object with
-an error of some sort (red background).  Cache errors are often non-fatal, so
-you should generally ignore those, and look for a more interesting one.
+* "type:URL_REQUEST is:error" will restrict the source list to URL_REQUEST
+objects with an error of some sort.  Cache errors are often non-fatal, so you
+should generally ignore those, and look for a more interesting one.
 
 * "type:URL_REQUEST sort:duration" will show the longest-lived requests first.
 This is often useful in finding hung or slow requests.
 
-For a list of other filter commands, you can mouse over the question mark on
-about:net-internals.

[Randy Smith (Not in Mondays), 2016/11/15 23:18:41]

FWIW, I find this a more natural place to mention the "?" hover functionality
than in the event/source discussion.

[Bence, 2016/11/16 14:12:51]

Done.

-
 Once you locate the problematic request, the next is to figure out where the
-problem is - it's often one of the last events, though it could also be related
+problem is -- it's often one of the last events, though it could also be related
 to response or request headers.  You can use "source_dependency" links to drill
 down into other related sources, or up from layers below URL_REQUEST.
 
@@ -122,8 +163,7 @@ Some things to look for while debugging:
 
 * Changing networks and entering / exiting suspend mode can have all sorts of
 fun and exciting effects on underway network activity.  Network changes log a
-top level NETWORK_CHANGED event with no source - the event itself is treated as
-its own source.  Suspend events are currently not logged.
+top level NETWORK_CHANGED event.  Suspend events are currently not logged.
 
 * URL_REQUEST_DELEGATE / DELEGATE_INFO events mean a URL_REQUEST is blocked on a
 URLRequest::Delegate or the NetworkDelegate, which are implemented outside the
@@ -147,14 +187,14 @@ issued by the media and PDF code.
 
 * Late binding:  HTTP_STREAM_JOBs are not associated with any CONNECT_JOB until
 a CONNECT_JOB actually connects.  This is so the highest priority pending job
-gets the first available socket (Which may be a new socket, or an old one that's
+gets the first available socket (which may be a new socket, or an old one that's
 freed up).  For this reason, it can be a little tricky to relate hung
 HTTP_STREAM_JOBs to CONNECT_JOBs.
 
 * Each CONNECT_JOB belongs to a "group", which has a limit of 6 connections.  If
-all CONNECT_JOBs beling to a group (The CONNECT_JOB's description field) are
+all CONNECT_JOBs belonging to a group (the CONNECT_JOB's description field) are
 stalled waiting on an available socket, the group probably has 6 sockets that
-that are hung - either hung trying to connect, or used by stalled requests and
+that are hung -- either hung trying to connect, or used by stalled requests and
 thus outside the socket pool's control.
 
 * There's a limit on number of DNS resolutions that can be started at once.  If