Duplicate DNS resolutions during startup |
|||||
Issue descriptionI'm working on optimizing Chrome startup on Android, so I see tons of startup traces (first 10 seconds). I noticed that sometimes traces have lots of long bars for a task started from StartLookupAttempt (net/dns/host_resolver_impl.cc). Turned out that SystemHostResolverCall() can sometimes take long time on Android. That's one half of the story. The other half is that SystemHostResolverCall() is sometimes called several times for certain addresses. Attached are 3 traces from 20-trace run in the following environment: * Android Go "gobo" device running OMB1.180108.001 * Wi-Fi simulating 3G speeds * Chrome reloads a single https://en.m.wikipedia.org/wiki/California tab Below are SystemHostResolverCall() calls per trace. All times are milliseconds. 3g_master-10s~20_1.html Start Host Duration End ------------------------------------------------------------------------ 1341.383 translate.googleapis.com 534.688 1876.071 1413.656 check.googlezip.net 1018.797 2432.453 1441.992 datasaver.googleapis.com 495.123 1937.115 1483.486 proxy.googlezip.net 1026.36 2509.846 1590.94 datasaver.googleapis.com 511.939 2102.879 1607.649 check.googlezip.net 1010.74 2618.389 1618.378 proxy.googlezip.net 1009.687 2628.065 2046.767 accounts.google.com 939.072 2985.839 2049.389 en.m.wikipedia.org 504.928 2554.317 2051.477 upload.wikimedia.org 8.432 2059.909 2876.663 proxy.googlezip.net 2.227 2878.89 2885.71 login.wikimedia.org 545.627 3431.337 2886.247 meta.wikimedia.org 477.171 3363.418 4752.055 clients4.google.com 579.928 5331.983 5504.16 clients4.google.com 2.049 5506.209 6133.63 www.google.com 482.338 6615.968 6635.624 www.google.com 6.202 6641.826 8286.67 edvphmpruuzvitr 1140.089 9426.759 8293.401 ldqynujntf 1132.702 9426.103 check.googlezip.net: 2 times datasaver.googleapis.com: 2 times proxy.googlezip.net: 3 times clients4.google.com: 2 times 3g_master-10s~20_2.html Start Host Duration End ------------------------------------------------------------------------ 1124.348 translate.googleapis.com 12.391 1136.739 1177.529 check.googlezip.net 14.395 1191.924 1186.857 datasaver.googleapis.com 523.04 1709.897 1231.396 proxy.googlezip.net 8.565 1239.961 1309.607 datasaver.googleapis.com 511.156 1820.763 1360.681 check.googlezip.net 8.055 1368.736 1378.779 proxy.googlezip.net 6.831 1385.61 1548.226 accounts.google.com 986.821 2535.047 1612.326 check.googlezip.net 2.894 1615.22 1622.877 proxy.googlezip.net 7.022 1629.899 1765.136 en.m.wikipedia.org 14.572 1779.708 1765.818 upload.wikimedia.org 25.528 1791.346 2445.126 login.wikimedia.org 4.577 2449.703 2445.723 meta.wikimedia.org 5.222 2450.945 4018.058 clients4.google.com 4.023 4022.081 4287.097 clients4.google.com 6.346 4293.443 5961.221 www.google.com 4.673 5965.894 6212.996 www.google.com 2.458 6215.454 8074.019 crmlbtujcmwwf 1194.684 9268.703 8081.994 pbxcgmiolbbxagm 1186.215 9268.209 8084.832 qkpxrghsdlvw 1181.422 9266.254 check.googlezip.net: 3 times datasaver.googleapis.com: 2 times proxy.googlezip.net: 3 times clients4.google.com: 2 times 3g_master-10s~20_17.html Start Host Duration End ------------------------------------------------------------------------ 1163.735 translate.googleapis.com 11.814 1175.549 1213.123 check.googlezip.net 6031.295 7244.418 1233.851 datasaver.googleapis.com 507.189 1741.04 1263.125 proxy.googlezip.net 9.546 1272.671 1394.55 datasaver.googleapis.com 514.118 1908.668 1431.71 check.googlezip.net 968.089 2399.799 1434.995 proxy.googlezip.net 7.96 1442.955 1684.91 proxy.googlezip.net 8.085 1692.995 1754.436 accounts.google.com 506.993 2261.429 1756.653 en.m.wikipedia.org 18.541 1775.194 1760.524 upload.wikimedia.org 23.557 1784.081 2441.519 check.googlezip.net 5.61 2447.129 2621.487 login.wikimedia.org 7.432 2628.919 2621.89 meta.wikimedia.org 5.593 2627.483 4106.836 clients4.google.com 7.394 4114.23 4357.568 clients4.google.com 1.863 4359.431 5977.235 www.google.com 2.269 5979.504 6231.761 www.google.com 5.962 6237.723 8086.14 ixiaqzor 1027.773 9113.913 8087.558 wkbkjosjwg 1022.138 9109.696 8100.674 rvewufdhmgxwfp 994.23 9094.904 check.googlezip.net: 3 times datasaver.googleapis.com: 2 times proxy.googlezip.net: 3 times clients4.google.com: 2 times Is this by design? I thought we're caching DNS responses?
,
Jan 18 2018
All traces have "NetLog" section in them, with some net-related info (like HTTP_STREAM_REQUEST or HOST_RESOLVER_IMPL_REQUEST) - is it not sufficient?
,
Jan 18 2018
Anyway, here is the log from a sample run.
,
Jan 18 2018
Thanks! Most of the relevant information is technically there in the traces, but I can trivially get information from a netlog that takes time-consuming and error-prone work with a trace. I'll take a look.
,
Jan 19 2018
It's unclear from the first post whether you were worried about this, so just in case: SystemHostResolverCall taking a long time is expected, because it's a blocking call to getaddrinfo(). It's not taking up that much CPU time. Here's what I see in the netlog: clients4.google.com: 2 times First one finishes after about a millisecond. Second one finishes after 3 ms, so the system still had it cached even though we didn't. The reason why we didn't cache it is because the corresponding URLRequest is using the LOAD_DISABLE_CACHE load flag. That's historically been considered WAI, but it's causing other problems so I'm planning to revisit it soon. datasaver.googleapis.com: 2 times First one gets cancelled because the corresponding URLRequest is cancelled. This comes from somewhere outside the net stack. Second one isn't cached because the first one never finished. Not a bug from the net stack's perspective, but possibly a bug somewhere higher up. proxy.googlezip.net: 3 times First one gets cancelled. It's not clear why. Second one has the cache disabled, so third one can't use the cache. www.google.com: 2 times This one is another case of LOAD_DISABLE_CACHE. So it looks like there are two things happening here: some requests get cancelled and restarted, which is somewhere in a layer I don't know about (data reduction proxy, maybe?), and some requests aren't allowed to use the cache. Unfortunately, LOAD_DISABLE_CACHE is used for a lot of different things and it's going to be tricky to untangle, but I'll keep this use case in mind when I try. None of the duplicate requests overlap in time, which is good, at least.
,
Mar 23 2018
,
May 30 2018
|
|||||
►
Sign in to add a comment |
|||||
Comment 1 by mge...@chromium.org
, Jan 18 2018