Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(210)

Side by Side Diff: net/docs/crash-course-in-net-internals.md

Issue 2501113002: Improve net-internals crash course. (Closed)
Patch Set: Nit. Created 4 years ago
Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.
Jump to:
View unified diff | Download patch
« no previous file with comments | « no previous file | no next file » | no next file with comments »
Toggle Intra-line Diffs ('i') | Expand Comments ('e') | Collapse Comments ('c') | Show Comments Hide Comments ('s')
OLDNEW
1 # A Crash Course in Debugging with about:net-internals 1 # A Crash Course in Debugging with about:net-internals
2 2
3 This document is intended to help get people started debugging network errors 3 This document is intended to help get people started debugging network errors
4 with about:net-internals, with some commonly useful tips and tricks. This 4 with about:net-internals, with some commonly useful tips and tricks. This
5 document is aimed more at how to get started using some of its features to 5 document is aimed more at how to get started using some of its features to
6 investigate bug reports, rather than as a feature overview. 6 investigate bug reports, rather than as a feature overview.
7 7
8 It would probably be useful to read 8 It would probably be useful to read
9 [life-of-a-url-request.md](life-of-a-url-request.md) before this document. 9 [life-of-a-url-request.md](life-of-a-url-request.md) before this document.
10 10
11 # What Data Net-Internals Contains 11 # What Data Net-Internals Contains
12 12
13 about:net-internals provides a view of browser activity from net/'s perspective. 13 about:net-internals provides a view of browser activity from net/'s perspective.
14 For this reason, it lacks knowledge of tabs, navigation, frames, resource types, 14 For this reason, it lacks knowledge of tabs, navigation, frames, resource types,
15 etc. 15 etc.
16 16
17 The top level network stack object is the URLRequestContext. The Events View 17 The leftmost column presents a list of views. Most debugging is done with the
18 Events view, which will be all this document covers.
19
20 The top level network stack object is the URLRequestContext. The Events view
18 has information for all Chrome URLRequestContexts that are hooked up to the 21 has information for all Chrome URLRequestContexts that are hooked up to the
19 single, global, ChromeNetLog object. This includes both incognito and non- 22 single, global, ChromeNetLog object. This includes both incognito and
20 incognito profiles, among other things. The Events view only shows events for 23 non-incognito profiles, among other things. The Events view only shows events
21 the period that net-internals was open and running, and is incrementally updated 24 for the period that net-internals was open and running, and is incrementally
22 as events occur. The code attempts to add a top level event for URLRequests 25 updated as events occur. The code attempts to add a top level event for
23 that were active when the tab was opened, to help debug hung requests, but 26 URLRequests that were active when the about:net-internals tab was opened, to
24 that's best-effort only, and only includes requests for the current profile and 27 help debug hung requests, but that's best-effort only, and only includes
25 the system URLRequestContext. 28 requests for the current profile and the system URLRequestContext.
26 29
27 The other views are all snapshots of the current state of the main 30 The other views are all snapshots of the current state of the main
28 URLRequestContext's components, and are updated on a 5 second timer. These will 31 URLRequestContext's components, and are updated on a 5 second timer. These will
29 show objects that were created before about:net-internals was opened. Most 32 show objects that were created before about:net-internals was opened.
30 debugging is done with the Events view (which will be all this document
31 covers), but it's good to be aware of this distinction.
32 33
33 # Events vs Sources 34 # Events vs Sources
34 35
35 The Event View shows events logged by the NetLog. The NetLog model is that 36 The Events view shows events logged by the NetLog. The NetLog model is that
36 long-lived network stack objects, called sources, emit events over their 37 long-lived network stack objects, called sources, emit events over their
37 lifetime. When looking at the code, a "NetLogWithSource" object contains a sour ce 38 lifetime. A NetLogWithSource object contains a source ID, a NetLogSourceType,
38 ID, and a pointer to the NetLog the source emits events to. Some events have a 39 and a pointer to the NetLog the source emits events to.
39 beginning and end point (during which other subevents may occur), and some only 40
40 occur at a single point in time. Generally only one event can be occuring for a 41 The Events view has a list of sources in a column adjacent to the list of views.
41 source at a time. If there can be multiple events doing completely independent 42 Sources that include an event with a net_error parameter with negative value
42 thing, the code often uses new sources to represent the parallelism. 43 (that is, some kind of ERR_) are shown with red background. Sources whose
44 opening event has not ended yet are shown with white background. Other events
45 have green background. The search queries corresponding to the first two kinds
46 are `is:error` and `is:active`.
47
48 When one or more sources are selected, corresponding events show up in another
49 column to the right, sorted by source, and by time within each source. There
50 are two time values: t is measured from some reference point common to all
51 sources, and st is measured from the first event for each source. Time is
52 displayed in milliseconds.
53
54 Since the network stack is asynchronous, events from different sources will
55 often be interlaced in time, but Events view does not feature showing events fro m
56 different sources ordered by time. Large time gaps in the event list of a
57 single source usually mean that time is spent in the context of another source.
58
59 Some events come in pairs: a beginning and end event, between which other events
60 may occur. They are shown with + and - prefixes, respectively. The begin event
61 has a dt value which shows the duration. If the end event was captured, then
62 duration is calculated as the time difference between the begin and the end
63 events. Otherwise the time elapsed from the begin event until capturing
64 was stopped is displayed (a lower bound for actual duration), followed by a +
65 sign (for example, "dt=120+").
66
67 If there are no other events in between the begin and end, and the end event has
68 no parameters, then they are collapsed in a single line without a sign prefix.
69
70 Some other events only occur at a single point in time, and will not have either
71 a sign prefix, or a dt duration value.
72
73 Generally only one event can be occuring for a source at a time. If there can
74 be multiple events doing completely independent things, the code often uses new
75 sources to represent the parallelism.
76
77 Most, but not all events correspond to a source. Exceptions are global events,
78 which have no source, and show up as individual entries in the source list.
79 Examples of global events include NETWORK_CHANGED, DNS_CONFIG_CHANGED, and
80 PROXY_CONFIG_CHANGED.
81
82 # Common source types
43 83
44 "Sources" correspond to certain net objects, however, multiple layers of net/ 84 "Sources" correspond to certain net objects, however, multiple layers of net/
45 will often log to a single source. Here are the main source types and what they 85 will often log to a single source. Here are the main source types and what they
46 include (Excluding HTTP2 [SPDY]/QUIC): 86 include (excluding HTTP2 [SPDY]/QUIC):
47 87
48 * URL_REQUEST: This corresponds to the URLRequest object. It includes events 88 * URL_REQUEST: This corresponds to the URLRequest object. It includes events
49 from all the URLRequestJobs, HttpCache::Transactions, NetworkTransactions, 89 from all the URLRequestJobs, HttpCache::Transactions, NetworkTransactions,
50 HttpStreamFactoryImpl::Requests, HttpStream implementations, and 90 HttpStreamFactoryImpl::Requests, HttpStream implementations, and
51 HttpStreamParsers used to service a response. If the URL_REQUEST follows HTTP 91 HttpStreamParsers used to service a response. If the URL_REQUEST follows HTTP
52 redirects, it will include each redirect. This is a lot of stuff, but generally 92 redirects, it will include each redirect. This is a lot of stuff, but generally
53 only object is doing work at a time. This event source includes the full URL 93 only one object is doing work at a time. This event source includes the full
54 and generally includes the request / response headers (Except when the cache 94 URL and generally includes the request / response headers (except when the cache
55 handles the response). 95 handles the response).
56 96
57 * HTTP_STREAM_JOB: This corresponds to HttpStreamFactoryImpl::Job (Note that 97 * HTTP_STREAM_JOB: This corresponds to HttpStreamFactoryImpl::Job (note that
58 one Request can have multiple Jobs). It also includes its proxy and DNS 98 one Request can have multiple Jobs). It also includes its proxy and DNS
59 lookups. HTTP_STREAM_JOB log events are separate from URL_REQUEST because 99 lookups. HTTP_STREAM_JOB log events are separate from URL_REQUEST because two
60 two stream jobs may be created and races against each other, in some cases - 100 stream jobs may be created and races against each other, in some cases -- one
61 one for one for QUIC, and one for HTTP. One of the final events of this source 101 for QUIC, and one for HTTP.
62 indicates how an HttpStream was created (Reusing an existing SOCKET / 102
63 HTTP2_SESSION / QUIC_SESSION, or creating a new one). 103 One of the final events of this source, before the
104 HTTP_STREAM_JOB_BOUND_TO_REQUEST event, indicates how an HttpStream was
105 created:
106
107 + A SOCKET_POOL_BOUND_TO_CONNECT_JOB event means that a new TCP socket was
108 created, whereas a SOCKET_POOL_REUSED_AN_EXISTING_SOCKET event indicates tha t
109 an existing TCP socket was reused for a non-HTTP/2 request.
110
111 + An HTTP2_SESSION_POOL_IMPORTED_SESSION_FROM_SOCKET event indicates that a
112 new HTTP/2 session was opened by this Job.
113
114 + An HTTP2_SESSION_POOL_FOUND_EXISTING_SESSION event indicates that the requ est
115 was served on a preexisting HTTP/2 session.
116
117 + An HTTP2_SESSION_POOL_FOUND_EXISTING_SESSION_FROM_IP_POOL event means that
118 the request was pooled to a preexisting HTTP/2 session which had a different
119 SpdySessionKey, but DNS resolution resulted in the same IP, and the
120 certificate matches.
121
122 + There are currently no events logged for opening new QUIC sessions or
123 reusing existing ones.
64 124
65 * \*_CONNECT_JOB: This corresponds to the ConnectJob subclasses that each socke t 125 * \*_CONNECT_JOB: This corresponds to the ConnectJob subclasses that each socke t
66 pool uses. A successful CONNECT_JOB return a SOCKET. The events here vary a 126 pool uses. A successful CONNECT_JOB returns a SOCKET. The events here vary a
67 lot by job type. Their main event is generally either to create a socket, or 127 lot by job type. Their main event is generally either to create a socket, or
68 request a socket from another socket pool (Which creates another CONNECT_JOB) 128 request a socket from another socket pool (which creates another CONNECT_JOB)
69 and then do some extra work on top of that - like establish an SSL connection on 129 and then do some extra work on top of that -- like establish an SSL connection o n
70 top of a TCP connection. 130 top of a TCP connection.
71 131
72 * SOCKET: These correspond to TCPSockets, but may also have other classes 132 * SOCKET: These correspond to TCPSockets, but may also have other classes
73 layered on top of them (Like an SSLClientSocket). This is a bit different from 133 layered on top of them (like an SSLClientSocket). This is a bit different from
74 the other classes, where the name corresponds to the topmost class, instead of 134 the other classes, where the name corresponds to the topmost class, instead of
75 the bottommost one. This is largely an artifact of the fact the socket is 135 the bottommost one. This is largely an artifact of the fact the socket is
76 created first, and then SSL (Or a proxy connection) is layered on top of it. 136 created first, and then SSL (or a proxy connection) is layered on top of it.
77 SOCKETs may be reused between multiple requests, and a request may end up 137 SOCKETs may be reused between multiple requests, and a request may end up
78 getting a socket created for another request. 138 getting a socket created for another request.
79 139
80 * HOST_RESOLVER_IMPL_JOB: These correspond to HostResolverImpl::Job. The 140 * HOST_RESOLVER_IMPL_JOB: These correspond to HostResolverImpl::Job. They
81 include information about how long the lookup was queued, each DNS request that 141 include information about how long the lookup was queued, each DNS request that
82 was attempted (With the platform or built-in resolver) and all the other sources 142 was attempted (with the platform or built-in resolver) and all the other sources
83 that are waiting on the job. 143 that are waiting on the job.
84 144
85 When one source depends on another, the code generally logs an event with 145 When one source depends on another, the code generally logs an event at both
86 "source_dependency" value to both sources, which lets you jump between the two 146 sources with a `source_dependency` value pointing to the other source. These
87 related events. 147 are clickable in the UI, adding the referred source to the list of selected
148 sources.
88 149
89 # Debugging 150 # Debugging
90 151
91 When you receive a report from the user, the first thing you'll generally want 152 When you receive a report from the user, the first thing you'll generally want
92 to do find the URL_REQUEST[s] that are misbehaving. If the user gives an ERR_* 153 to do find the URL_REQUEST[s] that are misbehaving. If the user gives an ERR_*
93 code or the exact URL of the resource that won't load, you can just search for 154 code or the exact URL of the resource that won't load, you can just search for
94 it. If it's an upload, you can search for "post", or if it's a redirect issue, 155 it. If it's an upload, you can search for "post", or if it's a redirect issue,
95 you can search for "redirect". However, you often won't have much information 156 you can search for "redirect". However, you often won't have much information
96 about the actual problem. There are two filters in net-internals that can help 157 about the actual problem. There are two filters in net-internals that can help
97 in a lot of cases: 158 in a lot of cases:
98 159
99 * "type:URL_REQUEST is:error" will restrict the list to URL_REQUEST object with 160 * "type:URL_REQUEST is:error" will restrict the source list to URL_REQUEST
100 an error of some sort (red background). Cache errors are often non-fatal, so 161 objects with an error of some sort. Cache errors are often non-fatal, so you
101 you should generally ignore those, and look for a more interesting one. 162 should generally ignore those, and look for a more interesting one.
102 163
103 * "type:URL_REQUEST sort:duration" will show the longest-lived requests first. 164 * "type:URL_REQUEST sort:duration" will show the longest-lived requests first.
104 This is often useful in finding hung or slow requests. 165 This is often useful in finding hung or slow requests.
105 166
106 For a list of other filter commands, you can mouse over the question mark on 167 For a list of other filter commands, you can mouse over the question mark on
107 about:net-internals. 168 about:net-internals.
108 169
109 Once you locate the problematic request, the next is to figure out where the 170 Once you locate the problematic request, the next is to figure out where the
110 problem is - it's often one of the last events, though it could also be related 171 problem is -- it's often one of the last events, though it could also be related
111 to response or request headers. You can use "source_dependency" links to drill 172 to response or request headers. You can use `source_dependency` links to
112 down into other related sources, or up from layers below URL_REQUEST. 173 navigate between related sources. You can use the name of an event to search
113 174 for the code responsible for that event, and try to deduce what went wrong
114 You can use the name of an event to search for the code responsible for that 175 before/after a particular event.
115 event, and try to deduce what went wrong before/after a particular event. Note
116 that the event names used in net-internals are not the entire string names, so
117 you should not do an entire string match.
118 176
119 Some things to look for while debugging: 177 Some things to look for while debugging:
120 178
121 * CANCELLED events almost always come from outside the network stack. 179 * CANCELLED events almost always come from outside the network stack.
122 180
123 * Changing networks and entering / exiting suspend mode can have all sorts of 181 * Changing networks and entering / exiting suspend mode can have all sorts of
124 fun and exciting effects on underway network activity. Network changes log a 182 fun and exciting effects on underway network activity. Network changes log a
125 top level NETWORK_CHANGED event with no source - the event itself is treated as 183 top level NETWORK_CHANGED event. Suspend events are currently not logged.
126 its own source. Suspend events are currently not logged.
127 184
128 * URL_REQUEST_DELEGATE / DELEGATE_INFO events mean a URL_REQUEST is blocked on a 185 * URL_REQUEST_DELEGATE / DELEGATE_INFO events mean a URL_REQUEST is blocked on a
129 URLRequest::Delegate or the NetworkDelegate, which are implemented outside the 186 URLRequest::Delegate or the NetworkDelegate, which are implemented outside the
130 network stack. A request will sometimes be CANCELED here for reasons known only 187 network stack. A request will sometimes be CANCELED here for reasons known only
131 to the delegate. Or the delegate may cause a hang. In general, to debug issues 188 to the delegate. Or the delegate may cause a hang. In general, to debug issues
132 related to delegates, one needs to figure out which method of which object is 189 related to delegates, one needs to figure out which method of which object is
133 causing the problem. The object may be the a NetworkDelegate, a 190 causing the problem. The object may be the a NetworkDelegate, a
134 ResourceThrottle, a ResourceHandler, the ResourceLoader itself, or the 191 ResourceThrottle, a ResourceHandler, the ResourceLoader itself, or the
135 ResourceDispatcherHost. 192 ResourceDispatcherHost.
136 193
137 * Sockets are often reused between requests. If a request is on a stale 194 * Sockets are often reused between requests. If a request is on a stale
138 (reused) socket, what was the previous request that used the socket, how long 195 (reused) socket, what was the previous request that used the socket, how long
139 ago was it made? 196 ago was it made? (Look at SOCKET_IN_USE events, and the HTTP_STREAM_JOBS they
197 point to via the `source_dependency` value.)
140 198
141 * SSL negotation is a process fraught with peril, particularly with broken 199 * SSL negotation is a process fraught with peril, particularly with broken
142 proxies. These will generally stall or fail in the SSL_CONNECT phase at the 200 proxies. These will generally stall or fail in the SSL_CONNECT phase at the
143 SOCKET layer. 201 SOCKET layer.
144 202
145 * Range requests have magic to handle them at the cache layer, and are often 203 * Range requests have magic to handle them at the cache layer, and are often
146 issued by the media and PDF code. 204 issued by the media and PDF code.
147 205
148 * Late binding: HTTP_STREAM_JOBs are not associated with any CONNECT_JOB until 206 * Late binding: HTTP_STREAM_JOBs are not associated with any CONNECT_JOB until
149 a CONNECT_JOB actually connects. This is so the highest priority pending job 207 a CONNECT_JOB actually connects. This is so the highest priority pending
150 gets the first available socket (Which may be a new socket, or an old one that's 208 HTTP_STREAM_JOB gets the first available socket (which may be a new socket, or
151 freed up). For this reason, it can be a little tricky to relate hung 209 an old one that's freed up). For this reason, it can be a little tricky to
152 HTTP_STREAM_JOBs to CONNECT_JOBs. 210 relate hung HTTP_STREAM_JOBs to CONNECT_JOBs.
153 211
154 * Each CONNECT_JOB belongs to a "group", which has a limit of 6 connections. If 212 * Each CONNECT_JOB belongs to a "group", which has a limit of 6 connections. If
155 all CONNECT_JOBs beling to a group (The CONNECT_JOB's description field) are 213 all CONNECT_JOBs belonging to a group (the CONNECT_JOB's description field) are
156 stalled waiting on an available socket, the group probably has 6 sockets that 214 stalled waiting on an available socket, the group probably has 6 sockets that
157 that are hung - either hung trying to connect, or used by stalled requests and 215 that are hung -- either hung trying to connect, or used by stalled requests and
158 thus outside the socket pool's control. 216 thus outside the socket pool's control.
159 217
160 * There's a limit on number of DNS resolutions that can be started at once. If 218 * There's a limit on number of DNS resolutions that can be started at once. If
161 everything is stalled while resolving DNS addresses, you've probably hit this 219 everything is stalled while resolving DNS addresses, you've probably hit this
162 limit, and the DNS lookups are also misbehaving in some fashion. 220 limit, and the DNS lookups are also misbehaving in some fashion.
163 221
164 # Miscellany 222 # Miscellany
165 223
166 These are just miscellaneous things you may notice when looking through the 224 These are just miscellaneous things you may notice when looking through the
167 logs. 225 logs.
168 226
169 * URLRequests that look to start twice for no obvious reason. These are 227 * URLRequests that look to start twice for no obvious reason. These are
170 typically main frame requests, and the first request is AppCache. Can just 228 typically main frame requests, and the first request is AppCache. Can just
171 ignore it and move on with your life. 229 ignore it and move on with your life.
172 230
173 * Some HTTP requests are not handled by URLRequestHttpJobs. These include 231 * Some HTTP requests are not handled by URLRequestHttpJobs. These include
174 things like HSTS redirects (URLRequestRedirectJob), AppCache, ServiceWorker, 232 things like HSTS redirects (URLRequestRedirectJob), AppCache, ServiceWorker,
175 etc. These generally don't log as much information, so it can be tricky to 233 etc. These generally don't log as much information, so it can be tricky to
176 figure out what's going on with these. 234 figure out what's going on with these.
177 235
178 * Non-HTTP requests also appear in the log, and also generally don't log much 236 * Non-HTTP requests also appear in the log, and also generally don't log much
179 (blob URLs, chrome URLs, etc). 237 (blob URLs, chrome URLs, etc).
180 238
181 * Preconnects create a "HTTP_STREAM_JOB" event that may create multiple 239 * Preconnects create a "HTTP_STREAM_JOB" event that may create multiple
182 CONNECT_JOBs (or none) and is then destroyed. These can be identified by the 240 CONNECT_JOBs (or none) and is then destroyed. These can be identified by the
183 "SOCKET_POOL_CONNECTING_N_SOCKETS" events. 241 "SOCKET_POOL_CONNECTING_N_SOCKETS" events.
OLDNEW
« no previous file with comments | « no previous file | no next file » | no next file with comments »

Powered by Google App Engine
This is Rietveld 408576698