1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. 2 // Use of this source code is governed by a BSD-style license that can be 3 // found in the LICENSE file. 4 5 #include "chrome/browser/net/url_info.h" 6 7 #include <ctype.h> 8 #include <math.h> 9 10 #include <algorithm> 11 #include <string> 12 13 #include "base/format_macros.h" 14 #include "base/lazy_instance.h" 15 #include "base/logging.h" 16 #include "base/metrics/histogram.h" 17 #include "base/strings/stringprintf.h" 18 19 using base::Time; 20 using base::TimeDelta; 21 using base::TimeTicks; 22 23 namespace chrome_browser_net { 24 25 namespace { 26 27 // The number of OS cache entries we can guarantee(?) before cache eviction 28 // might likely take place. 29 const int kMaxGuaranteedDnsCacheSize = 50; 30 31 // Common low end TTL for sites is 5 minutes. However, DNS servers give us the 32 // remaining time, not the original 5 minutes. Hence it doesn't much matter 33 // whether we found something in the local cache, or an ISP cache, it will on 34 // average be 2.5 minutes before it expires. We could try to model this with 35 // 180 seconds, but simpler is just to do the lookups all the time (wasting OS 36 // calls(?)), and let that OS cache decide what to do (with TTL in hand). We 37 // use a small time to help get some duplicate suppression, in case a page has 38 // a TON of copies of the same domain name, so that we don't thrash the OS to 39 // death. Hopefully it is small enough that we're not hurting our cache hit 40 // rate (i.e., we could always ask the OS). 41 const int kDefaultCacheExpirationDuration = 5; 42 43 TimeDelta MaxNonNetworkDnsLookupDuration() { 44 return TimeDelta::FromMilliseconds(15); 45 } 46 47 bool detailed_logging_enabled = false; 48 49 struct GlobalState { 50 GlobalState() { 51 cache_expiration_duration = 52 TimeDelta::FromSeconds(kDefaultCacheExpirationDuration); 53 } 54 TimeDelta cache_expiration_duration; 55 }; 56 57 base::LazyInstance<GlobalState>::Leaky global_state; 58 59 } // anonymous namespace 60 61 // Use command line switch to enable detailed logging. 62 void EnablePredictorDetailedLog(bool enable) { 63 detailed_logging_enabled = enable; 64 } 65 66 // static 67 int UrlInfo::sequence_counter = 1; 68 69 UrlInfo::UrlInfo() 70 : state_(PENDING), 71 old_prequeue_state_(state_), 72 resolve_duration_(NullDuration()), 73 queue_duration_(NullDuration()), 74 sequence_number_(0), 75 motivation_(NO_PREFETCH_MOTIVATION), 76 was_linked_(false) { 77 } 78 79 UrlInfo::~UrlInfo() {} 80 81 bool UrlInfo::NeedsDnsUpdate() { 82 switch (state_) { 83 case PENDING: // Just now created info. 84 return true; 85 86 case QUEUED: // In queue. 87 case ASSIGNED: // It's being resolved. 88 case ASSIGNED_BUT_MARKED: // It's being resolved. 89 return false; // We're already working on it 90 91 case NO_SUCH_NAME: // Lookup failed. 92 case FOUND: // Lookup succeeded. 93 return !IsStillCached(); // See if DNS cache expired. 94 95 default: 96 NOTREACHED(); 97 return false; 98 } 99 } 100 101 // Used by test ONLY. The value is otherwise constant. 102 // static 103 void UrlInfo::set_cache_expiration(TimeDelta time) { 104 global_state.Pointer()->cache_expiration_duration = time; 105 } 106 107 // static 108 TimeDelta UrlInfo::get_cache_expiration() { 109 return global_state.Get().cache_expiration_duration; 110 } 111 112 void UrlInfo::SetQueuedState(ResolutionMotivation motivation) { 113 DCHECK(PENDING == state_ || FOUND == state_ || NO_SUCH_NAME == state_); 114 old_prequeue_state_ = state_; 115 state_ = QUEUED; 116 queue_duration_ = resolve_duration_ = NullDuration(); 117 SetMotivation(motivation); 118 GetDuration(); // Set time_ 119 DLogResultsStats("DNS Prefetch in queue"); 120 } 121 122 void UrlInfo::SetAssignedState() { 123 DCHECK(QUEUED == state_); 124 state_ = ASSIGNED; 125 queue_duration_ = GetDuration(); 126 DLogResultsStats("DNS Prefetch assigned"); 127 UMA_HISTOGRAM_TIMES("DNS.PrefetchQueue", queue_duration_); 128 } 129 130 void UrlInfo::RemoveFromQueue() { 131 DCHECK(ASSIGNED == state_); 132 state_ = old_prequeue_state_; 133 DLogResultsStats("DNS Prefetch reset to prequeue"); 134 const TimeDelta kBoundary = TimeDelta::FromSeconds(2); 135 if (queue_duration_ > kBoundary) { 136 UMA_HISTOGRAM_MEDIUM_TIMES("DNS.QueueRecycledDeltaOver2", 137 queue_duration_ - kBoundary); 138 return; 139 } 140 // Make a custom linear histogram for the region from 0 to boundary. 141 static const size_t kBucketCount = 52; 142 static base::HistogramBase* histogram(NULL); 143 if (!histogram) 144 histogram = base::LinearHistogram::FactoryTimeGet( 145 "DNS.QueueRecycledUnder2", TimeDelta(), kBoundary, kBucketCount, 146 base::HistogramBase::kUmaTargetedHistogramFlag); 147 histogram->AddTime(queue_duration_); 148 } 149 150 void UrlInfo::SetPendingDeleteState() { 151 DCHECK(ASSIGNED == state_ || ASSIGNED_BUT_MARKED == state_); 152 state_ = ASSIGNED_BUT_MARKED; 153 } 154 155 void UrlInfo::SetFoundState() { 156 DCHECK(ASSIGNED == state_); 157 state_ = FOUND; 158 resolve_duration_ = GetDuration(); 159 const TimeDelta max_duration = MaxNonNetworkDnsLookupDuration(); 160 if (max_duration <= resolve_duration_) { 161 UMA_HISTOGRAM_CUSTOM_TIMES("DNS.PrefetchResolution", resolve_duration_, 162 max_duration, TimeDelta::FromMinutes(15), 100); 163 } 164 sequence_number_ = sequence_counter++; 165 DLogResultsStats("DNS PrefetchFound"); 166 } 167 168 void UrlInfo::SetNoSuchNameState() { 169 DCHECK(ASSIGNED == state_); 170 state_ = NO_SUCH_NAME; 171 resolve_duration_ = GetDuration(); 172 #ifndef NDEBUG 173 if (MaxNonNetworkDnsLookupDuration() <= resolve_duration_) { 174 LOCAL_HISTOGRAM_TIMES("DNS.PrefetchNotFoundName", resolve_duration_); 175 } 176 #endif 177 sequence_number_ = sequence_counter++; 178 DLogResultsStats("DNS PrefetchNotFound"); 179 } 180 181 void UrlInfo::SetUrl(const GURL& url) { 182 if (url_.is_empty()) // Not yet initialized. 183 url_ = url; 184 else 185 DCHECK_EQ(url_, url); 186 } 187 188 // IsStillCached() guesses if the DNS cache still has IP data, 189 // or at least remembers results about "not finding host." 190 bool UrlInfo::IsStillCached() const { 191 DCHECK(FOUND == state_ || NO_SUCH_NAME == state_); 192 193 // Default MS OS does not cache failures. Hence we could return false almost 194 // all the time for that case. However, we'd never try again to prefetch 195 // the value if we returned false that way. Hence we'll just let the lookup 196 // time out the same way as FOUND case. 197 198 if (sequence_counter - sequence_number_ > kMaxGuaranteedDnsCacheSize) 199 return false; 200 201 TimeDelta time_since_resolution = TimeTicks::Now() - time_; 202 return time_since_resolution < global_state.Get().cache_expiration_duration; 203 } 204 205 void UrlInfo::DLogResultsStats(const char* message) const { 206 if (!detailed_logging_enabled) 207 return; 208 DVLOG(1) << "\t" << message << "\tq=" << queue_duration().InMilliseconds() 209 << "ms,\tr=" << resolve_duration().InMilliseconds() 210 << "ms,\tp=" << sequence_number_ << "\t" << url_.spec(); 211 } 212 213 //------------------------------------------------------------------------------ 214 // This last section supports HTML output, such as seen in about:dns. 215 //------------------------------------------------------------------------------ 216 217 // Preclude any possibility of Java Script or markup in the text, by only 218 // allowing alphanumerics, '.', '-', ':', and whitespace. 219 static std::string RemoveJs(const std::string& text) { 220 std::string output(text); 221 size_t length = output.length(); 222 for (size_t i = 0; i < length; i++) { 223 char next = output[i]; 224 if (isalnum(next) || isspace(next) || strchr(".-:/", next) != NULL) 225 continue; 226 output[i] = '?'; 227 } 228 return output; 229 } 230 231 class MinMaxAverage { 232 public: 233 MinMaxAverage() 234 : sum_(0), square_sum_(0), count_(0), 235 minimum_(kint64max), maximum_(kint64min) { 236 } 237 238 // Return values for use in printf formatted as "%d" 239 int sample(int64 value) { 240 sum_ += value; 241 square_sum_ += value * value; 242 count_++; 243 minimum_ = std::min(minimum_, value); 244 maximum_ = std::max(maximum_, value); 245 return static_cast<int>(value); 246 } 247 int minimum() const { return static_cast<int>(minimum_); } 248 int maximum() const { return static_cast<int>(maximum_); } 249 int average() const { return static_cast<int>(sum_/count_); } 250 int sum() const { return static_cast<int>(sum_); } 251 252 int standard_deviation() const { 253 double average = static_cast<float>(sum_) / count_; 254 double variance = static_cast<float>(square_sum_)/count_ 255 - average * average; 256 return static_cast<int>(floor(sqrt(variance) + .5)); 257 } 258 259 private: 260 int64 sum_; 261 int64 square_sum_; 262 int count_; 263 int64 minimum_; 264 int64 maximum_; 265 266 // DISALLOW_COPY_AND_ASSIGN(MinMaxAverage); 267 }; 268 269 static std::string HoursMinutesSeconds(int seconds) { 270 std::string result; 271 int print_seconds = seconds % 60; 272 int minutes = seconds / 60; 273 int print_minutes = minutes % 60; 274 int print_hours = minutes/60; 275 if (print_hours) 276 base::StringAppendF(&result, "%.2d:", print_hours); 277 if (print_hours || print_minutes) 278 base::StringAppendF(&result, "%2.2d:", print_minutes); 279 base::StringAppendF(&result, "%2.2d", print_seconds); 280 return result; 281 } 282 283 // static 284 void UrlInfo::GetHtmlTable(const UrlInfoTable& host_infos, 285 const char* description, 286 bool brief, 287 std::string* output) { 288 if (0 == host_infos.size()) 289 return; 290 output->append(description); 291 base::StringAppendF(output, "%" PRIuS " %s", host_infos.size(), 292 (1 == host_infos.size()) ? "hostname" : "hostnames"); 293 294 if (brief) { 295 output->append("<br><br>"); 296 return; 297 } 298 299 output->append("<br><table border=1>" 300 "<tr><th>Host name</th>" 301 "<th>How long ago<br>(HH:MM:SS)</th>" 302 "<th>Motivation</th>" 303 "</tr>"); 304 305 const char* row_format = "<tr align=right><td>%s</td>" // Host name. 306 "<td>%s</td>" // How long ago. 307 "<td>%s</td>" // Motivation. 308 "</tr>"; 309 310 // Print bulk of table, and gather stats at same time. 311 MinMaxAverage queue, when; 312 TimeTicks current_time = TimeTicks::Now(); 313 for (UrlInfoTable::const_iterator it(host_infos.begin()); 314 it != host_infos.end(); it++) { 315 queue.sample((it->queue_duration_.InMilliseconds())); 316 base::StringAppendF( 317 output, 318 row_format, 319 RemoveJs(it->url_.spec()).c_str(), 320 HoursMinutesSeconds(when.sample( 321 (current_time - it->time_).InSeconds())).c_str(), 322 it->GetAsciiMotivation().c_str()); 323 } 324 output->append("</table>"); 325 326 #ifndef NDEBUG 327 base::StringAppendF( 328 output, 329 "Prefetch Queue Durations: min=%d, avg=%d, max=%d<br><br>", 330 queue.minimum(), queue.average(), queue.maximum()); 331 #endif 332 333 output->append("<br>"); 334 } 335 336 void UrlInfo::SetMotivation(ResolutionMotivation motivation) { 337 motivation_ = motivation; 338 if (motivation < LINKED_MAX_MOTIVATED) 339 was_linked_ = true; 340 } 341 342 std::string UrlInfo::GetAsciiMotivation() const { 343 switch (motivation_) { 344 case MOUSE_OVER_MOTIVATED: 345 return "[mouse-over]"; 346 347 case PAGE_SCAN_MOTIVATED: 348 return "[page scan]"; 349 350 case OMNIBOX_MOTIVATED: 351 return "[omnibox]"; 352 353 case STARTUP_LIST_MOTIVATED: 354 return "[startup list]"; 355 356 case NO_PREFETCH_MOTIVATION: 357 return "n/a"; 358 359 case STATIC_REFERAL_MOTIVATED: 360 return RemoveJs(referring_url_.spec()) + "*"; 361 362 case LEARNED_REFERAL_MOTIVATED: 363 return RemoveJs(referring_url_.spec()); 364 365 default: 366 return std::string(); 367 } 368 } 369 370 } // namespace chrome_browser_net 371