OLD | NEW |
| (Empty) |
1 // Copyright (c) 2013 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 "net/quic/quic_connection_logger.h" | |
6 | |
7 #include <algorithm> | |
8 #include <string> | |
9 | |
10 #include "base/bind.h" | |
11 #include "base/callback.h" | |
12 #include "base/metrics/histogram.h" | |
13 #include "base/metrics/sparse_histogram.h" | |
14 #include "base/profiler/scoped_tracker.h" | |
15 #include "base/strings/string_number_conversions.h" | |
16 #include "base/values.h" | |
17 #include "net/base/net_log.h" | |
18 #include "net/base/net_util.h" | |
19 #include "net/cert/cert_verify_result.h" | |
20 #include "net/cert/x509_certificate.h" | |
21 #include "net/quic/crypto/crypto_handshake_message.h" | |
22 #include "net/quic/crypto/crypto_protocol.h" | |
23 #include "net/quic/quic_address_mismatch.h" | |
24 #include "net/quic/quic_socket_address_coder.h" | |
25 | |
26 using base::StringPiece; | |
27 using std::string; | |
28 | |
29 namespace net { | |
30 | |
31 namespace { | |
32 | |
33 // We have ranges-of-buckets in the cumulative histogram (covering 21 packet | |
34 // sequences) of length 2, 3, 4, ... 22. | |
35 // Hence the largest sample is bounded by the sum of those numbers. | |
36 const int kBoundingSampleInCumulativeHistogram = ((2 + 22) * 21) / 2; | |
37 | |
38 base::Value* NetLogQuicPacketCallback(const IPEndPoint* self_address, | |
39 const IPEndPoint* peer_address, | |
40 size_t packet_size, | |
41 NetLog::LogLevel /* log_level */) { | |
42 base::DictionaryValue* dict = new base::DictionaryValue(); | |
43 dict->SetString("self_address", self_address->ToString()); | |
44 dict->SetString("peer_address", peer_address->ToString()); | |
45 dict->SetInteger("size", packet_size); | |
46 return dict; | |
47 } | |
48 | |
49 base::Value* NetLogQuicPacketSentCallback( | |
50 const SerializedPacket& serialized_packet, | |
51 EncryptionLevel level, | |
52 TransmissionType transmission_type, | |
53 size_t packet_size, | |
54 QuicTime sent_time, | |
55 NetLog::LogLevel /* log_level */) { | |
56 base::DictionaryValue* dict = new base::DictionaryValue(); | |
57 dict->SetInteger("encryption_level", level); | |
58 dict->SetInteger("transmission_type", transmission_type); | |
59 dict->SetString("packet_sequence_number", | |
60 base::Uint64ToString(serialized_packet.sequence_number)); | |
61 dict->SetInteger("size", packet_size); | |
62 dict->SetInteger("sent_time_us", | |
63 static_cast<int>(sent_time.ToDebuggingValue())); | |
64 return dict; | |
65 } | |
66 | |
67 base::Value* NetLogQuicPacketRetransmittedCallback( | |
68 QuicPacketSequenceNumber old_sequence_number, | |
69 QuicPacketSequenceNumber new_sequence_number, | |
70 NetLog::LogLevel /* log_level */) { | |
71 base::DictionaryValue* dict = new base::DictionaryValue(); | |
72 dict->SetString("old_packet_sequence_number", | |
73 base::Uint64ToString(old_sequence_number)); | |
74 dict->SetString("new_packet_sequence_number", | |
75 base::Uint64ToString(new_sequence_number)); | |
76 return dict; | |
77 } | |
78 | |
79 base::Value* NetLogQuicPacketHeaderCallback(const QuicPacketHeader* header, | |
80 NetLog::LogLevel /* log_level */) { | |
81 base::DictionaryValue* dict = new base::DictionaryValue(); | |
82 dict->SetString("connection_id", | |
83 base::Uint64ToString(header->public_header.connection_id)); | |
84 dict->SetInteger("reset_flag", header->public_header.reset_flag); | |
85 dict->SetInteger("version_flag", header->public_header.version_flag); | |
86 dict->SetString("packet_sequence_number", | |
87 base::Uint64ToString(header->packet_sequence_number)); | |
88 dict->SetInteger("entropy_flag", header->entropy_flag); | |
89 dict->SetInteger("fec_flag", header->fec_flag); | |
90 dict->SetInteger("fec_group", static_cast<int>(header->fec_group)); | |
91 return dict; | |
92 } | |
93 | |
94 base::Value* NetLogQuicStreamFrameCallback(const QuicStreamFrame* frame, | |
95 NetLog::LogLevel /* log_level */) { | |
96 base::DictionaryValue* dict = new base::DictionaryValue(); | |
97 dict->SetInteger("stream_id", frame->stream_id); | |
98 dict->SetBoolean("fin", frame->fin); | |
99 dict->SetString("offset", base::Uint64ToString(frame->offset)); | |
100 dict->SetInteger("length", frame->data.TotalBufferSize()); | |
101 return dict; | |
102 } | |
103 | |
104 base::Value* NetLogQuicAckFrameCallback(const QuicAckFrame* frame, | |
105 NetLog::LogLevel /* log_level */) { | |
106 base::DictionaryValue* dict = new base::DictionaryValue(); | |
107 dict->SetString("largest_observed", | |
108 base::Uint64ToString(frame->largest_observed)); | |
109 dict->SetInteger( | |
110 "delta_time_largest_observed_us", | |
111 static_cast<int>(frame->delta_time_largest_observed.ToMicroseconds())); | |
112 dict->SetInteger("entropy_hash", | |
113 frame->entropy_hash); | |
114 dict->SetBoolean("truncated", frame->is_truncated); | |
115 | |
116 base::ListValue* missing = new base::ListValue(); | |
117 dict->Set("missing_packets", missing); | |
118 const SequenceNumberSet& missing_packets = frame->missing_packets; | |
119 for (SequenceNumberSet::const_iterator it = missing_packets.begin(); | |
120 it != missing_packets.end(); ++it) { | |
121 missing->AppendString(base::Uint64ToString(*it)); | |
122 } | |
123 | |
124 base::ListValue* revived = new base::ListValue(); | |
125 dict->Set("revived_packets", revived); | |
126 const SequenceNumberSet& revived_packets = frame->revived_packets; | |
127 for (SequenceNumberSet::const_iterator it = revived_packets.begin(); | |
128 it != revived_packets.end(); ++it) { | |
129 revived->AppendString(base::Uint64ToString(*it)); | |
130 } | |
131 | |
132 base::ListValue* received = new base::ListValue(); | |
133 dict->Set("received_packet_times", received); | |
134 const PacketTimeList& received_times = frame->received_packet_times; | |
135 for (PacketTimeList::const_iterator it = received_times.begin(); | |
136 it != received_times.end(); ++it) { | |
137 base::DictionaryValue* info = new base::DictionaryValue(); | |
138 info->SetInteger("sequence_number", static_cast<int>(it->first)); | |
139 info->SetInteger("received", | |
140 static_cast<int>(it->second.ToDebuggingValue())); | |
141 received->Append(info); | |
142 } | |
143 | |
144 return dict; | |
145 } | |
146 | |
147 base::Value* NetLogQuicRstStreamFrameCallback( | |
148 const QuicRstStreamFrame* frame, | |
149 NetLog::LogLevel /* log_level */) { | |
150 base::DictionaryValue* dict = new base::DictionaryValue(); | |
151 dict->SetInteger("stream_id", frame->stream_id); | |
152 dict->SetInteger("quic_rst_stream_error", frame->error_code); | |
153 dict->SetString("details", frame->error_details); | |
154 return dict; | |
155 } | |
156 | |
157 base::Value* NetLogQuicConnectionCloseFrameCallback( | |
158 const QuicConnectionCloseFrame* frame, | |
159 NetLog::LogLevel /* log_level */) { | |
160 base::DictionaryValue* dict = new base::DictionaryValue(); | |
161 dict->SetInteger("quic_error", frame->error_code); | |
162 dict->SetString("details", frame->error_details); | |
163 return dict; | |
164 } | |
165 | |
166 base::Value* NetLogQuicWindowUpdateFrameCallback( | |
167 const QuicWindowUpdateFrame* frame, | |
168 NetLog::LogLevel /* log_level */) { | |
169 base::DictionaryValue* dict = new base::DictionaryValue(); | |
170 dict->SetInteger("stream_id", frame->stream_id); | |
171 dict->SetString("byte_offset", base::Uint64ToString(frame->byte_offset)); | |
172 return dict; | |
173 } | |
174 | |
175 base::Value* NetLogQuicBlockedFrameCallback( | |
176 const QuicBlockedFrame* frame, | |
177 NetLog::LogLevel /* log_level */) { | |
178 base::DictionaryValue* dict = new base::DictionaryValue(); | |
179 dict->SetInteger("stream_id", frame->stream_id); | |
180 return dict; | |
181 } | |
182 | |
183 base::Value* NetLogQuicGoAwayFrameCallback( | |
184 const QuicGoAwayFrame* frame, | |
185 NetLog::LogLevel /* log_level */) { | |
186 base::DictionaryValue* dict = new base::DictionaryValue(); | |
187 dict->SetInteger("quic_error", frame->error_code); | |
188 dict->SetInteger("last_good_stream_id", frame->last_good_stream_id); | |
189 dict->SetString("reason_phrase", frame->reason_phrase); | |
190 return dict; | |
191 } | |
192 | |
193 base::Value* NetLogQuicStopWaitingFrameCallback( | |
194 const QuicStopWaitingFrame* frame, | |
195 NetLog::LogLevel /* log_level */) { | |
196 base::DictionaryValue* dict = new base::DictionaryValue(); | |
197 base::DictionaryValue* sent_info = new base::DictionaryValue(); | |
198 dict->Set("sent_info", sent_info); | |
199 sent_info->SetString("least_unacked", | |
200 base::Uint64ToString(frame->least_unacked)); | |
201 return dict; | |
202 } | |
203 | |
204 base::Value* NetLogQuicVersionNegotiationPacketCallback( | |
205 const QuicVersionNegotiationPacket* packet, | |
206 NetLog::LogLevel /* log_level */) { | |
207 base::DictionaryValue* dict = new base::DictionaryValue(); | |
208 base::ListValue* versions = new base::ListValue(); | |
209 dict->Set("versions", versions); | |
210 for (QuicVersionVector::const_iterator it = packet->versions.begin(); | |
211 it != packet->versions.end(); ++it) { | |
212 versions->AppendString(QuicVersionToString(*it)); | |
213 } | |
214 return dict; | |
215 } | |
216 | |
217 base::Value* NetLogQuicCryptoHandshakeMessageCallback( | |
218 const CryptoHandshakeMessage* message, | |
219 NetLog::LogLevel /* log_level */) { | |
220 base::DictionaryValue* dict = new base::DictionaryValue(); | |
221 dict->SetString("quic_crypto_handshake_message", message->DebugString()); | |
222 return dict; | |
223 } | |
224 | |
225 base::Value* NetLogQuicOnConnectionClosedCallback( | |
226 QuicErrorCode error, | |
227 bool from_peer, | |
228 NetLog::LogLevel /* log_level */) { | |
229 base::DictionaryValue* dict = new base::DictionaryValue(); | |
230 dict->SetInteger("quic_error", error); | |
231 dict->SetBoolean("from_peer", from_peer); | |
232 return dict; | |
233 } | |
234 | |
235 base::Value* NetLogQuicCertificateVerifiedCallback( | |
236 scoped_refptr<X509Certificate> cert, | |
237 NetLog::LogLevel /* log_level */) { | |
238 // Only the subjects are logged so that we can investigate connection pooling. | |
239 // More fields could be logged in the future. | |
240 std::vector<std::string> dns_names; | |
241 cert->GetDNSNames(&dns_names); | |
242 base::DictionaryValue* dict = new base::DictionaryValue(); | |
243 base::ListValue* subjects = new base::ListValue(); | |
244 for (std::vector<std::string>::const_iterator it = dns_names.begin(); | |
245 it != dns_names.end(); it++) { | |
246 subjects->Append(new base::StringValue(*it)); | |
247 } | |
248 dict->Set("subjects", subjects); | |
249 return dict; | |
250 } | |
251 | |
252 void UpdatePacketGapSentHistogram(size_t num_consecutive_missing_packets) { | |
253 UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapSent", | |
254 num_consecutive_missing_packets); | |
255 } | |
256 | |
257 void UpdatePublicResetAddressMismatchHistogram( | |
258 const IPEndPoint& server_hello_address, | |
259 const IPEndPoint& public_reset_address) { | |
260 int sample = GetAddressMismatch(server_hello_address, public_reset_address); | |
261 // We are seemingly talking to an older server that does not support the | |
262 // feature, so we can't report the results in the histogram. | |
263 if (sample < 0) { | |
264 return; | |
265 } | |
266 UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.PublicResetAddressMismatch2", | |
267 sample, QUIC_ADDRESS_MISMATCH_MAX); | |
268 } | |
269 | |
270 const char* GetConnectionDescriptionString() { | |
271 // TODO(rtenneti): Remove ScopedTracker below once crbug.com/422516 is fixed. | |
272 tracked_objects::ScopedTracker tracking_profile( | |
273 FROM_HERE_WITH_EXPLICIT_FUNCTION( | |
274 "422516 QuicConnectionLogger GetConnectionDescriptionString")); | |
275 | |
276 NetworkChangeNotifier::ConnectionType type = | |
277 NetworkChangeNotifier::GetConnectionType(); | |
278 const char* description = NetworkChangeNotifier::ConnectionTypeToString(type); | |
279 // Most platforms don't distingish Wifi vs Etherenet, and call everything | |
280 // CONNECTION_UNKNOWN :-(. We'll tease out some details when we are on WiFi, | |
281 // and hopefully leave only ethernet (with no WiFi available) in the | |
282 // CONNECTION_UNKNOWN category. This *might* err if there is both ethernet, | |
283 // as well as WiFi, where WiFi was not being used that much. | |
284 // This function only seems usefully defined on Windows currently. | |
285 if (type == NetworkChangeNotifier::CONNECTION_UNKNOWN || | |
286 type == NetworkChangeNotifier::CONNECTION_WIFI) { | |
287 WifiPHYLayerProtocol wifi_type = GetWifiPHYLayerProtocol(); | |
288 switch (wifi_type) { | |
289 case WIFI_PHY_LAYER_PROTOCOL_NONE: | |
290 // No wifi support or no associated AP. | |
291 break; | |
292 case WIFI_PHY_LAYER_PROTOCOL_ANCIENT: | |
293 // An obsolete modes introduced by the original 802.11, e.g. IR, FHSS. | |
294 description = "CONNECTION_WIFI_ANCIENT"; | |
295 break; | |
296 case WIFI_PHY_LAYER_PROTOCOL_A: | |
297 // 802.11a, OFDM-based rates. | |
298 description = "CONNECTION_WIFI_802.11a"; | |
299 break; | |
300 case WIFI_PHY_LAYER_PROTOCOL_B: | |
301 // 802.11b, DSSS or HR DSSS. | |
302 description = "CONNECTION_WIFI_802.11b"; | |
303 break; | |
304 case WIFI_PHY_LAYER_PROTOCOL_G: | |
305 // 802.11g, same rates as 802.11a but compatible with 802.11b. | |
306 description = "CONNECTION_WIFI_802.11g"; | |
307 break; | |
308 case WIFI_PHY_LAYER_PROTOCOL_N: | |
309 // 802.11n, HT rates. | |
310 description = "CONNECTION_WIFI_802.11n"; | |
311 break; | |
312 case WIFI_PHY_LAYER_PROTOCOL_UNKNOWN: | |
313 // Unclassified mode or failure to identify. | |
314 break; | |
315 } | |
316 } | |
317 return description; | |
318 } | |
319 | |
320 // If |address| is an IPv4-mapped IPv6 address, returns ADDRESS_FAMILY_IPV4 | |
321 // instead of ADDRESS_FAMILY_IPV6. Othewise, behaves like GetAddressFamily(). | |
322 AddressFamily GetRealAddressFamily(const IPAddressNumber& address) { | |
323 return IsIPv4Mapped(address) ? ADDRESS_FAMILY_IPV4 : | |
324 GetAddressFamily(address); | |
325 } | |
326 | |
327 } // namespace | |
328 | |
329 QuicConnectionLogger::QuicConnectionLogger(QuicSession* session, | |
330 const BoundNetLog& net_log) | |
331 : net_log_(net_log), | |
332 session_(session), | |
333 last_received_packet_sequence_number_(0), | |
334 last_received_packet_size_(0), | |
335 previous_received_packet_size_(0), | |
336 largest_received_packet_sequence_number_(0), | |
337 largest_received_missing_packet_sequence_number_(0), | |
338 num_out_of_order_received_packets_(0), | |
339 num_out_of_order_large_received_packets_(0), | |
340 num_packets_received_(0), | |
341 num_truncated_acks_sent_(0), | |
342 num_truncated_acks_received_(0), | |
343 num_frames_received_(0), | |
344 num_duplicate_frames_received_(0), | |
345 num_incorrect_connection_ids_(0), | |
346 num_undecryptable_packets_(0), | |
347 num_duplicate_packets_(0), | |
348 num_blocked_frames_received_(0), | |
349 num_blocked_frames_sent_(0), | |
350 connection_description_(GetConnectionDescriptionString()) { | |
351 } | |
352 | |
353 QuicConnectionLogger::~QuicConnectionLogger() { | |
354 UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderPacketsReceived", | |
355 num_out_of_order_received_packets_); | |
356 UMA_HISTOGRAM_COUNTS("Net.QuicSession.OutOfOrderLargePacketsReceived", | |
357 num_out_of_order_large_received_packets_); | |
358 UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksSent", | |
359 num_truncated_acks_sent_); | |
360 UMA_HISTOGRAM_COUNTS("Net.QuicSession.TruncatedAcksReceived", | |
361 num_truncated_acks_received_); | |
362 UMA_HISTOGRAM_COUNTS("Net.QuicSession.IncorrectConnectionIDsReceived", | |
363 num_incorrect_connection_ids_); | |
364 UMA_HISTOGRAM_COUNTS("Net.QuicSession.UndecryptablePacketsReceived", | |
365 num_undecryptable_packets_); | |
366 UMA_HISTOGRAM_COUNTS("Net.QuicSession.DuplicatePacketsReceived", | |
367 num_duplicate_packets_); | |
368 UMA_HISTOGRAM_COUNTS("Net.QuicSession.BlockedFrames.Received", | |
369 num_blocked_frames_received_); | |
370 UMA_HISTOGRAM_COUNTS("Net.QuicSession.BlockedFrames.Sent", | |
371 num_blocked_frames_sent_); | |
372 | |
373 if (num_frames_received_ > 0) { | |
374 int duplicate_stream_frame_per_thousand = | |
375 num_duplicate_frames_received_ * 1000 / num_frames_received_; | |
376 if (num_packets_received_ < 100) { | |
377 UMA_HISTOGRAM_CUSTOM_COUNTS( | |
378 "Net.QuicSession.StreamFrameDuplicatedShortConnection", | |
379 duplicate_stream_frame_per_thousand, 1, 1000, 75); | |
380 } else { | |
381 UMA_HISTOGRAM_CUSTOM_COUNTS( | |
382 "Net.QuicSession.StreamFrameDuplicatedLongConnection", | |
383 duplicate_stream_frame_per_thousand, 1, 1000, 75); | |
384 | |
385 } | |
386 } | |
387 | |
388 RecordLossHistograms(); | |
389 } | |
390 | |
391 void QuicConnectionLogger::OnFrameAddedToPacket(const QuicFrame& frame) { | |
392 switch (frame.type) { | |
393 case PADDING_FRAME: | |
394 break; | |
395 case STREAM_FRAME: | |
396 net_log_.AddEvent( | |
397 NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_SENT, | |
398 base::Bind(&NetLogQuicStreamFrameCallback, frame.stream_frame)); | |
399 break; | |
400 case ACK_FRAME: { | |
401 net_log_.AddEvent( | |
402 NetLog::TYPE_QUIC_SESSION_ACK_FRAME_SENT, | |
403 base::Bind(&NetLogQuicAckFrameCallback, frame.ack_frame)); | |
404 const SequenceNumberSet& missing_packets = | |
405 frame.ack_frame->missing_packets; | |
406 const uint8 max_ranges = std::numeric_limits<uint8>::max(); | |
407 // Compute an upper bound on the number of NACK ranges. If the bound | |
408 // is below the max, then it clearly isn't truncated. | |
409 if (missing_packets.size() < max_ranges || | |
410 (*missing_packets.rbegin() - *missing_packets.begin() - | |
411 missing_packets.size() + 1) < max_ranges) { | |
412 break; | |
413 } | |
414 size_t num_ranges = 0; | |
415 QuicPacketSequenceNumber last_missing = 0; | |
416 for (SequenceNumberSet::const_iterator it = missing_packets.begin(); | |
417 it != missing_packets.end(); ++it) { | |
418 if (*it != last_missing + 1 && ++num_ranges >= max_ranges) { | |
419 ++num_truncated_acks_sent_; | |
420 break; | |
421 } | |
422 last_missing = *it; | |
423 } | |
424 break; | |
425 } | |
426 case RST_STREAM_FRAME: | |
427 UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeClient", | |
428 frame.rst_stream_frame->error_code); | |
429 net_log_.AddEvent( | |
430 NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_SENT, | |
431 base::Bind(&NetLogQuicRstStreamFrameCallback, | |
432 frame.rst_stream_frame)); | |
433 break; | |
434 case CONNECTION_CLOSE_FRAME: | |
435 net_log_.AddEvent( | |
436 NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_SENT, | |
437 base::Bind(&NetLogQuicConnectionCloseFrameCallback, | |
438 frame.connection_close_frame)); | |
439 break; | |
440 case GOAWAY_FRAME: | |
441 net_log_.AddEvent( | |
442 NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_SENT, | |
443 base::Bind(&NetLogQuicGoAwayFrameCallback, | |
444 frame.goaway_frame)); | |
445 break; | |
446 case WINDOW_UPDATE_FRAME: | |
447 net_log_.AddEvent( | |
448 NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_SENT, | |
449 base::Bind(&NetLogQuicWindowUpdateFrameCallback, | |
450 frame.window_update_frame)); | |
451 break; | |
452 case BLOCKED_FRAME: | |
453 ++num_blocked_frames_sent_; | |
454 net_log_.AddEvent( | |
455 NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_SENT, | |
456 base::Bind(&NetLogQuicBlockedFrameCallback, | |
457 frame.blocked_frame)); | |
458 break; | |
459 case STOP_WAITING_FRAME: | |
460 net_log_.AddEvent( | |
461 NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_SENT, | |
462 base::Bind(&NetLogQuicStopWaitingFrameCallback, | |
463 frame.stop_waiting_frame)); | |
464 break; | |
465 case PING_FRAME: | |
466 UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.ConnectionFlowControlBlocked", | |
467 session_->IsConnectionFlowControlBlocked()); | |
468 UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.StreamFlowControlBlocked", | |
469 session_->IsStreamFlowControlBlocked()); | |
470 // PingFrame has no contents to log, so just record that it was sent. | |
471 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PING_FRAME_SENT); | |
472 break; | |
473 default: | |
474 DCHECK(false) << "Illegal frame type: " << frame.type; | |
475 } | |
476 } | |
477 | |
478 void QuicConnectionLogger::OnPacketSent( | |
479 const SerializedPacket& serialized_packet, | |
480 QuicPacketSequenceNumber original_sequence_number, | |
481 EncryptionLevel level, | |
482 TransmissionType transmission_type, | |
483 const QuicEncryptedPacket& packet, | |
484 QuicTime sent_time) { | |
485 if (original_sequence_number == 0) { | |
486 net_log_.AddEvent( | |
487 NetLog::TYPE_QUIC_SESSION_PACKET_SENT, | |
488 base::Bind(&NetLogQuicPacketSentCallback, serialized_packet, | |
489 level, transmission_type, packet.length(), sent_time)); | |
490 } else { | |
491 net_log_.AddEvent( | |
492 NetLog::TYPE_QUIC_SESSION_PACKET_RETRANSMITTED, | |
493 base::Bind(&NetLogQuicPacketRetransmittedCallback, | |
494 original_sequence_number, | |
495 serialized_packet.sequence_number)); | |
496 } | |
497 } | |
498 | |
499 void QuicConnectionLogger::OnPacketReceived(const IPEndPoint& self_address, | |
500 const IPEndPoint& peer_address, | |
501 const QuicEncryptedPacket& packet) { | |
502 if (local_address_from_self_.GetFamily() == ADDRESS_FAMILY_UNSPECIFIED) { | |
503 local_address_from_self_ = self_address; | |
504 UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromSelf", | |
505 GetRealAddressFamily(self_address.address()), | |
506 ADDRESS_FAMILY_LAST); | |
507 } | |
508 | |
509 previous_received_packet_size_ = last_received_packet_size_; | |
510 last_received_packet_size_ = packet.length(); | |
511 net_log_.AddEvent( | |
512 NetLog::TYPE_QUIC_SESSION_PACKET_RECEIVED, | |
513 base::Bind(&NetLogQuicPacketCallback, &self_address, &peer_address, | |
514 packet.length())); | |
515 } | |
516 | |
517 void QuicConnectionLogger::OnIncorrectConnectionId( | |
518 QuicConnectionId connection_id) { | |
519 ++num_incorrect_connection_ids_; | |
520 } | |
521 | |
522 void QuicConnectionLogger::OnUndecryptablePacket() { | |
523 ++num_undecryptable_packets_; | |
524 } | |
525 | |
526 void QuicConnectionLogger::OnDuplicatePacket( | |
527 QuicPacketSequenceNumber sequence_number) { | |
528 ++num_duplicate_packets_; | |
529 } | |
530 | |
531 void QuicConnectionLogger::OnProtocolVersionMismatch( | |
532 QuicVersion received_version) { | |
533 // TODO(rtenneti): Add logging. | |
534 } | |
535 | |
536 void QuicConnectionLogger::OnPacketHeader(const QuicPacketHeader& header) { | |
537 net_log_.AddEvent( | |
538 NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_RECEIVED, | |
539 base::Bind(&NetLogQuicPacketHeaderCallback, &header)); | |
540 ++num_packets_received_; | |
541 if (largest_received_packet_sequence_number_ < | |
542 header.packet_sequence_number) { | |
543 QuicPacketSequenceNumber delta = header.packet_sequence_number - | |
544 largest_received_packet_sequence_number_; | |
545 if (delta > 1) { | |
546 // There is a gap between the largest packet previously received and | |
547 // the current packet. This indicates either loss, or out-of-order | |
548 // delivery. | |
549 UMA_HISTOGRAM_COUNTS("Net.QuicSession.PacketGapReceived", | |
550 static_cast<base::HistogramBase::Sample>(delta - 1)); | |
551 } | |
552 largest_received_packet_sequence_number_ = header.packet_sequence_number; | |
553 } | |
554 if (header.packet_sequence_number < received_packets_.size()) { | |
555 received_packets_[static_cast<size_t>(header.packet_sequence_number)] = | |
556 true; | |
557 } | |
558 if (header.packet_sequence_number < last_received_packet_sequence_number_) { | |
559 ++num_out_of_order_received_packets_; | |
560 if (previous_received_packet_size_ < last_received_packet_size_) | |
561 ++num_out_of_order_large_received_packets_; | |
562 UMA_HISTOGRAM_COUNTS( | |
563 "Net.QuicSession.OutOfOrderGapReceived", | |
564 static_cast<base::HistogramBase::Sample>( | |
565 last_received_packet_sequence_number_ - | |
566 header.packet_sequence_number)); | |
567 } | |
568 last_received_packet_sequence_number_ = header.packet_sequence_number; | |
569 } | |
570 | |
571 void QuicConnectionLogger::OnStreamFrame(const QuicStreamFrame& frame) { | |
572 net_log_.AddEvent( | |
573 NetLog::TYPE_QUIC_SESSION_STREAM_FRAME_RECEIVED, | |
574 base::Bind(&NetLogQuicStreamFrameCallback, &frame)); | |
575 } | |
576 | |
577 void QuicConnectionLogger::OnAckFrame(const QuicAckFrame& frame) { | |
578 net_log_.AddEvent( | |
579 NetLog::TYPE_QUIC_SESSION_ACK_FRAME_RECEIVED, | |
580 base::Bind(&NetLogQuicAckFrameCallback, &frame)); | |
581 | |
582 const size_t kApproximateLargestSoloAckBytes = 100; | |
583 if (last_received_packet_sequence_number_ < received_acks_.size() && | |
584 last_received_packet_size_ < kApproximateLargestSoloAckBytes) { | |
585 received_acks_[static_cast<size_t>(last_received_packet_sequence_number_)] = | |
586 true; | |
587 } | |
588 | |
589 if (frame.is_truncated) | |
590 ++num_truncated_acks_received_; | |
591 | |
592 if (frame.missing_packets.empty()) | |
593 return; | |
594 | |
595 SequenceNumberSet missing_packets = frame.missing_packets; | |
596 SequenceNumberSet::const_iterator it = missing_packets.lower_bound( | |
597 largest_received_missing_packet_sequence_number_); | |
598 if (it == missing_packets.end()) | |
599 return; | |
600 | |
601 if (*it == largest_received_missing_packet_sequence_number_) { | |
602 ++it; | |
603 if (it == missing_packets.end()) | |
604 return; | |
605 } | |
606 // Scan through the list and log consecutive ranges of missing packets. | |
607 size_t num_consecutive_missing_packets = 0; | |
608 QuicPacketSequenceNumber previous_missing_packet = *it - 1; | |
609 while (it != missing_packets.end()) { | |
610 if (previous_missing_packet == *it - 1) { | |
611 ++num_consecutive_missing_packets; | |
612 } else { | |
613 DCHECK_NE(0u, num_consecutive_missing_packets); | |
614 UpdatePacketGapSentHistogram(num_consecutive_missing_packets); | |
615 // Make sure this packet it included in the count. | |
616 num_consecutive_missing_packets = 1; | |
617 } | |
618 previous_missing_packet = *it; | |
619 ++it; | |
620 } | |
621 if (num_consecutive_missing_packets != 0) { | |
622 UpdatePacketGapSentHistogram(num_consecutive_missing_packets); | |
623 } | |
624 largest_received_missing_packet_sequence_number_ = | |
625 *missing_packets.rbegin(); | |
626 } | |
627 | |
628 void QuicConnectionLogger::OnStopWaitingFrame( | |
629 const QuicStopWaitingFrame& frame) { | |
630 net_log_.AddEvent( | |
631 NetLog::TYPE_QUIC_SESSION_STOP_WAITING_FRAME_RECEIVED, | |
632 base::Bind(&NetLogQuicStopWaitingFrameCallback, &frame)); | |
633 } | |
634 | |
635 void QuicConnectionLogger::OnRstStreamFrame(const QuicRstStreamFrame& frame) { | |
636 UMA_HISTOGRAM_SPARSE_SLOWLY("Net.QuicSession.RstStreamErrorCodeServer", | |
637 frame.error_code); | |
638 net_log_.AddEvent( | |
639 NetLog::TYPE_QUIC_SESSION_RST_STREAM_FRAME_RECEIVED, | |
640 base::Bind(&NetLogQuicRstStreamFrameCallback, &frame)); | |
641 } | |
642 | |
643 void QuicConnectionLogger::OnConnectionCloseFrame( | |
644 const QuicConnectionCloseFrame& frame) { | |
645 net_log_.AddEvent( | |
646 NetLog::TYPE_QUIC_SESSION_CONNECTION_CLOSE_FRAME_RECEIVED, | |
647 base::Bind(&NetLogQuicConnectionCloseFrameCallback, &frame)); | |
648 } | |
649 | |
650 void QuicConnectionLogger::OnWindowUpdateFrame( | |
651 const QuicWindowUpdateFrame& frame) { | |
652 net_log_.AddEvent( | |
653 NetLog::TYPE_QUIC_SESSION_WINDOW_UPDATE_FRAME_RECEIVED, | |
654 base::Bind(&NetLogQuicWindowUpdateFrameCallback, &frame)); | |
655 } | |
656 | |
657 void QuicConnectionLogger::OnBlockedFrame(const QuicBlockedFrame& frame) { | |
658 ++num_blocked_frames_received_; | |
659 net_log_.AddEvent( | |
660 NetLog::TYPE_QUIC_SESSION_BLOCKED_FRAME_RECEIVED, | |
661 base::Bind(&NetLogQuicBlockedFrameCallback, &frame)); | |
662 } | |
663 | |
664 void QuicConnectionLogger::OnGoAwayFrame(const QuicGoAwayFrame& frame) { | |
665 net_log_.AddEvent( | |
666 NetLog::TYPE_QUIC_SESSION_GOAWAY_FRAME_RECEIVED, | |
667 base::Bind(&NetLogQuicGoAwayFrameCallback, &frame)); | |
668 } | |
669 | |
670 void QuicConnectionLogger::OnPingFrame(const QuicPingFrame& frame) { | |
671 // PingFrame has no contents to log, so just record that it was received. | |
672 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PING_FRAME_RECEIVED); | |
673 } | |
674 | |
675 void QuicConnectionLogger::OnPublicResetPacket( | |
676 const QuicPublicResetPacket& packet) { | |
677 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_PUBLIC_RESET_PACKET_RECEIVED); | |
678 UpdatePublicResetAddressMismatchHistogram(local_address_from_shlo_, | |
679 packet.client_address); | |
680 } | |
681 | |
682 void QuicConnectionLogger::OnVersionNegotiationPacket( | |
683 const QuicVersionNegotiationPacket& packet) { | |
684 net_log_.AddEvent( | |
685 NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATION_PACKET_RECEIVED, | |
686 base::Bind(&NetLogQuicVersionNegotiationPacketCallback, &packet)); | |
687 } | |
688 | |
689 void QuicConnectionLogger::OnRevivedPacket( | |
690 const QuicPacketHeader& revived_header, | |
691 base::StringPiece payload) { | |
692 net_log_.AddEvent( | |
693 NetLog::TYPE_QUIC_SESSION_PACKET_HEADER_REVIVED, | |
694 base::Bind(&NetLogQuicPacketHeaderCallback, &revived_header)); | |
695 } | |
696 | |
697 void QuicConnectionLogger::OnCryptoHandshakeMessageReceived( | |
698 const CryptoHandshakeMessage& message) { | |
699 net_log_.AddEvent( | |
700 NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_RECEIVED, | |
701 base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message)); | |
702 | |
703 if (message.tag() == kSHLO) { | |
704 StringPiece address; | |
705 QuicSocketAddressCoder decoder; | |
706 if (message.GetStringPiece(kCADR, &address) && | |
707 decoder.Decode(address.data(), address.size())) { | |
708 local_address_from_shlo_ = IPEndPoint(decoder.ip(), decoder.port()); | |
709 UMA_HISTOGRAM_ENUMERATION("Net.QuicSession.ConnectionTypeFromPeer", | |
710 GetRealAddressFamily( | |
711 local_address_from_shlo_.address()), | |
712 ADDRESS_FAMILY_LAST); | |
713 } | |
714 } | |
715 } | |
716 | |
717 void QuicConnectionLogger::OnCryptoHandshakeMessageSent( | |
718 const CryptoHandshakeMessage& message) { | |
719 net_log_.AddEvent( | |
720 NetLog::TYPE_QUIC_SESSION_CRYPTO_HANDSHAKE_MESSAGE_SENT, | |
721 base::Bind(&NetLogQuicCryptoHandshakeMessageCallback, &message)); | |
722 } | |
723 | |
724 void QuicConnectionLogger::OnConnectionClosed(QuicErrorCode error, | |
725 bool from_peer) { | |
726 net_log_.AddEvent( | |
727 NetLog::TYPE_QUIC_SESSION_CLOSED, | |
728 base::Bind(&NetLogQuicOnConnectionClosedCallback, error, from_peer)); | |
729 } | |
730 | |
731 void QuicConnectionLogger::OnSuccessfulVersionNegotiation( | |
732 const QuicVersion& version) { | |
733 string quic_version = QuicVersionToString(version); | |
734 net_log_.AddEvent(NetLog::TYPE_QUIC_SESSION_VERSION_NEGOTIATED, | |
735 NetLog::StringCallback("version", &quic_version)); | |
736 } | |
737 | |
738 void QuicConnectionLogger::UpdateReceivedFrameCounts( | |
739 QuicStreamId stream_id, | |
740 int num_frames_received, | |
741 int num_duplicate_frames_received) { | |
742 if (stream_id != kCryptoStreamId) { | |
743 num_frames_received_ += num_frames_received; | |
744 num_duplicate_frames_received_ += num_duplicate_frames_received; | |
745 } | |
746 } | |
747 | |
748 void QuicConnectionLogger::OnCertificateVerified( | |
749 const CertVerifyResult& result) { | |
750 net_log_.AddEvent( | |
751 NetLog::TYPE_QUIC_SESSION_CERTIFICATE_VERIFIED, | |
752 base::Bind(&NetLogQuicCertificateVerifiedCallback, result.verified_cert)); | |
753 } | |
754 | |
755 base::HistogramBase* QuicConnectionLogger::GetPacketSequenceNumberHistogram( | |
756 const char* statistic_name) const { | |
757 string prefix("Net.QuicSession.PacketReceived_"); | |
758 return base::LinearHistogram::FactoryGet( | |
759 prefix + statistic_name + connection_description_, | |
760 1, received_packets_.size(), received_packets_.size() + 1, | |
761 base::HistogramBase::kUmaTargetedHistogramFlag); | |
762 } | |
763 | |
764 base::HistogramBase* QuicConnectionLogger::Get6PacketHistogram( | |
765 const char* which_6) const { | |
766 // This histogram takes a binary encoding of the 6 consecutive packets | |
767 // received. As a result, there are 64 possible sample-patterns. | |
768 string prefix("Net.QuicSession.6PacketsPatternsReceived_"); | |
769 return base::LinearHistogram::FactoryGet( | |
770 prefix + which_6 + connection_description_, 1, 64, 65, | |
771 base::HistogramBase::kUmaTargetedHistogramFlag); | |
772 } | |
773 | |
774 base::HistogramBase* QuicConnectionLogger::Get21CumulativeHistogram( | |
775 const char* which_21) const { | |
776 // This histogram contains, for each sequence of 21 packets, the results from | |
777 // 21 distinct questions about that sequence. Conceptually the histogtram is | |
778 // broken into 21 distinct ranges, and one sample is added into each of those | |
779 // ranges whenever we process a set of 21 packets. | |
780 // There is a little rendundancy, as each "range" must have the same number | |
781 // of samples, all told, but the histogram is a tad easier to read this way. | |
782 // The questions are: | |
783 // Was the first packet present (bucket 0==>no; bucket 1==>yes) | |
784 // Of the first two packets, how many were present? (bucket 2==> none; | |
785 // bucket 3==> 1 of 2; bucket 4==> 2 of 2) | |
786 // Of the first three packets, how many were present? (bucket 5==>none; | |
787 // bucket 6==> 1 of 3; bucket 7==> 2 of 3; bucket 8==> 3 of 3). | |
788 // etc. | |
789 string prefix("Net.QuicSession.21CumulativePacketsReceived_"); | |
790 return base::LinearHistogram::FactoryGet( | |
791 prefix + which_21 + connection_description_, | |
792 1, kBoundingSampleInCumulativeHistogram, | |
793 kBoundingSampleInCumulativeHistogram + 1, | |
794 base::HistogramBase::kUmaTargetedHistogramFlag); | |
795 } | |
796 | |
797 // static | |
798 void QuicConnectionLogger::AddTo21CumulativeHistogram( | |
799 base::HistogramBase* histogram, | |
800 int bit_mask_of_packets, | |
801 int valid_bits_in_mask) { | |
802 DCHECK_LE(valid_bits_in_mask, 21); | |
803 DCHECK_LT(bit_mask_of_packets, 1 << 21); | |
804 const int blank_bits_in_mask = 21 - valid_bits_in_mask; | |
805 DCHECK_EQ(bit_mask_of_packets & ((1 << blank_bits_in_mask) - 1), 0); | |
806 bit_mask_of_packets >>= blank_bits_in_mask; | |
807 int bits_so_far = 0; | |
808 int range_start = 0; | |
809 for (int i = 1; i <= valid_bits_in_mask; ++i) { | |
810 bits_so_far += bit_mask_of_packets & 1; | |
811 bit_mask_of_packets >>= 1; | |
812 DCHECK_LT(range_start + bits_so_far, kBoundingSampleInCumulativeHistogram); | |
813 histogram->Add(range_start + bits_so_far); | |
814 range_start += i + 1; | |
815 } | |
816 } | |
817 | |
818 void QuicConnectionLogger::RecordAggregatePacketLossRate() const { | |
819 // For short connections under 22 packets in length, we'll rely on the | |
820 // Net.QuicSession.21CumulativePacketsReceived_* histogram to indicate packet | |
821 // loss rates. This way we avoid tremendously anomalous contributions to our | |
822 // histogram. (e.g., if we only got 5 packets, but lost 1, we'd otherwise | |
823 // record a 20% loss in this histogram!). We may still get some strange data | |
824 // (1 loss in 22 is still high :-/). | |
825 if (largest_received_packet_sequence_number_ <= 21) | |
826 return; | |
827 | |
828 QuicPacketSequenceNumber divisor = largest_received_packet_sequence_number_; | |
829 QuicPacketSequenceNumber numerator = divisor - num_packets_received_; | |
830 if (divisor < 100000) | |
831 numerator *= 1000; | |
832 else | |
833 divisor /= 1000; | |
834 string prefix("Net.QuicSession.PacketLossRate_"); | |
835 base::HistogramBase* histogram = base::Histogram::FactoryGet( | |
836 prefix + connection_description_, 1, 1000, 75, | |
837 base::HistogramBase::kUmaTargetedHistogramFlag); | |
838 histogram->Add(static_cast<base::HistogramBase::Sample>(numerator / divisor)); | |
839 } | |
840 | |
841 void QuicConnectionLogger::RecordLossHistograms() const { | |
842 if (largest_received_packet_sequence_number_ == 0) | |
843 return; // Connection was never used. | |
844 RecordAggregatePacketLossRate(); | |
845 | |
846 base::HistogramBase* is_not_ack_histogram = | |
847 GetPacketSequenceNumberHistogram("IsNotAck_"); | |
848 base::HistogramBase* is_an_ack_histogram = | |
849 GetPacketSequenceNumberHistogram("IsAnAck_"); | |
850 base::HistogramBase* packet_arrived_histogram = | |
851 GetPacketSequenceNumberHistogram("Ack_"); | |
852 base::HistogramBase* packet_missing_histogram = | |
853 GetPacketSequenceNumberHistogram("Nack_"); | |
854 base::HistogramBase* ongoing_cumulative_packet_histogram = | |
855 Get21CumulativeHistogram("Some21s_"); | |
856 base::HistogramBase* first_cumulative_packet_histogram = | |
857 Get21CumulativeHistogram("First21_"); | |
858 base::HistogramBase* six_packet_histogram = Get6PacketHistogram("Some6s_"); | |
859 | |
860 DCHECK_EQ(received_packets_.size(), received_acks_.size()); | |
861 const QuicPacketSequenceNumber last_index = | |
862 std::min<QuicPacketSequenceNumber>(received_packets_.size() - 1, | |
863 largest_received_packet_sequence_number_); | |
864 const QuicPacketSequenceNumber index_of_first_21_contribution = | |
865 std::min<QuicPacketSequenceNumber>(21, last_index); | |
866 // Bit pattern of consecutively received packets that is maintained as we scan | |
867 // through the received_packets_ vector. Less significant bits correspond to | |
868 // less recent packets, and only the low order 21 bits are ever defined. | |
869 // Bit is 1 iff corresponding packet was received. | |
870 int packet_pattern_21 = 0; | |
871 // Zero is an invalid packet sequence number. | |
872 DCHECK(!received_packets_[0]); | |
873 for (size_t i = 1; i <= last_index; ++i) { | |
874 if (received_acks_[i]) | |
875 is_an_ack_histogram->Add(i); | |
876 else | |
877 is_not_ack_histogram->Add(i); | |
878 | |
879 packet_pattern_21 >>= 1; | |
880 if (received_packets_[i]) { | |
881 packet_arrived_histogram->Add(i); | |
882 packet_pattern_21 |= (1 << 20); // Turn on the 21st bit. | |
883 } else { | |
884 packet_missing_histogram->Add(i); | |
885 } | |
886 | |
887 if (i == index_of_first_21_contribution) { | |
888 AddTo21CumulativeHistogram(first_cumulative_packet_histogram, | |
889 packet_pattern_21, i); | |
890 } | |
891 // We'll just record for non-overlapping ranges, to reduce histogramming | |
892 // cost for now. Each call does 21 separate histogram additions. | |
893 if (i > 21 || i % 21 == 0) { | |
894 AddTo21CumulativeHistogram(ongoing_cumulative_packet_histogram, | |
895 packet_pattern_21, 21); | |
896 } | |
897 | |
898 if (i < 6) | |
899 continue; // Not enough packets to do any pattern recording. | |
900 int recent_6_mask = packet_pattern_21 >> 15; | |
901 DCHECK_LT(recent_6_mask, 64); | |
902 if (i == 6) { | |
903 Get6PacketHistogram("First6_")->Add(recent_6_mask); | |
904 continue; | |
905 } | |
906 // Record some overlapping patterns, to get a better picture, since this is | |
907 // not very expensive. | |
908 if (i % 3 == 0) | |
909 six_packet_histogram->Add(recent_6_mask); | |
910 } | |
911 } | |
912 | |
913 } // namespace net | |
OLD | NEW |