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

Side by Side Diff: net/quic/quic_connection_logger.cc

Issue 992733002: Remove //net (except for Android test stuff) and sdch (Closed) Base URL: git@github.com:domokit/mojo.git@master
Patch Set: Created 5 years, 9 months 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 | « net/quic/quic_connection_logger.h ('k') | net/quic/quic_connection_logger_unittest.cc » ('j') | no next file with comments »
Toggle Intra-line Diffs ('i') | Expand Comments ('e') | Collapse Comments ('c') | Show Comments Hide Comments ('s')
OLDNEW
(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
OLDNEW
« no previous file with comments | « net/quic/quic_connection_logger.h ('k') | net/quic/quic_connection_logger_unittest.cc » ('j') | no next file with comments »

Powered by Google App Engine
This is Rietveld 408576698