Improve net-internals crash course.

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

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

@@ -14,77 +14,138 @@ about:net-internals provides a view of browser activity from net/'s perspective.
 For this reason, it lacks knowledge of tabs, navigation, frames, resource types,
 etc.
 
-The top level network stack object is the URLRequestContext.  The Events View
+The leftmost column presents a list of views.  Most debugging is done with the
+Events view, which will be all this document covers.
+
+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.
+show objects that were created before about:net-internals was opened.
 
 # Events vs Sources
 
-The Event View shows events logged by the NetLog.  The NetLog model is that
+The Events 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.  A NetLogWithSource object contains a source ID, a NetLogSourceType,
+and a pointer to the NetLog the source emits events to.
+
+The Events view has a list of sources in a column adjacent to the list of views.
+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`.
+
+When one or more sources are selected, corresponding events show up in another
+column to the right, sorted 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 Events view does not feature showing events from
+different sources ordered by time.  Large time gaps in the event list of a
+single source usually mean that time is spent in the context of another source.
+
+Some events come in pairs: 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.  If the end event was captured, then
+duration is calculated as the time difference between the begin and the end
+events.  Otherwise the time elapsed from the begin event until capturing
+was stopped is displayed (a lower bound for actual duration), followed by a +
+sign (for example, "dt=120+").
+
+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 without a sign prefix.
+
+Some other events only occur at a single point in time, and will not have either
+a sign prefix, or a dt duration value.
+
+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.
+
+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 of global events 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 QUIC, and one for HTTP.
+
+    One of the final events of this source, 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.
+
+    + An HTTP2_SESSION_POOL_FOUND_EXISTING_SESSION event indicates that the request
+    was served on a preexisting HTTP/2 session.
+
+    + An 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.
 
 * \*_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
+* HOST_RESOLVER_IMPL_JOB:  These correspond to HostResolverImpl::Job.  They
 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
-related events.
+When one source depends on another, the code generally logs an event at both
+sources with a `source_dependency` value pointing to the other source.  These
+are clickable in the UI, adding the referred source to the list of selected
+sources.
 
 # Debugging
 
@@ -96,9 +157,9 @@ 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.
@@ -107,14 +168,11 @@ For a list of other filter commands, you can mouse over the question mark on
 about:net-internals.
 
 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
-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.
-
-You can use the name of an event to search for the code responsible for that
-event, and try to deduce what went wrong before/after a particular event.  Note
-that the event names used in net-internals are not the entire string names, so
-you should not do an entire string match.
+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
+navigate between related sources.  You can use the name of an event to search
+for the code responsible for that event, and try to deduce what went wrong
+before/after a particular event.
 
 Some things to look for while debugging:
 
@@ -122,8 +180,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
@@ -136,7 +193,8 @@ ResourceDispatcherHost.
 
 * Sockets are often reused between requests.  If a request is on a stale
 (reused) socket, what was the previous request that used the socket, how long
-ago was it made?
+ago was it made?  (Look at SOCKET_IN_USE events, and the HTTP_STREAM_JOBS they
+point to via the `source_dependency` value.)
 
 * SSL negotation is a process fraught with peril, particularly with broken
 proxies.  These will generally stall or fail in the SSL_CONNECT phase at the
@@ -146,15 +204,15 @@ SOCKET layer.
 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
-freed up).  For this reason, it can be a little tricky to relate hung
-HTTP_STREAM_JOBs to CONNECT_JOBs.
+a CONNECT_JOB actually connects.  This is so the highest priority pending
+HTTP_STREAM_JOB 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