quic: add debug stats output

PR-URL: #31

src/node_quic_session.cc

@@ -758,6 +758,29 @@ QuicSession::~QuicSession() {
   CHECK(destroyed_);
   ssl_.reset();
   ngtcp2_conn_del(connection_);
+
+  uint64_t now = uv_hrtime();
+  Debug(this,
+        "Quic%sSession destroyed.\n"
+        "  Duration: %llu\n"
+        "  Handshake Started: %llu\n"
+        "  Handshake Completed: %llu\n"
+        "  Bytes Received: %llu\n"
+        "  Bytes Sent: %llu\n"
+        "  Bidi Stream Count: %llu\n"
+        "  Uni Stream Count: %llu\n"
+        "  Streams In Count: %llu\n"
+        "  Streams Out Count: %llu\n",
+        IsServer() ? "Server" : "Client",
+        now - session_stats_.created_at,
+        session_stats_.handshake_start_at,
+        session_stats_.handshake_completed_at,
+        session_stats_.bytes_received,
+        session_stats_.bytes_sent,
+        session_stats_.bidi_stream_count,
+        session_stats_.uni_stream_count,
+        session_stats_.streams_in_count,
+        session_stats_.streams_out_count);
 }
 
 void QuicSession::SetLastError(QuicError error) {

src/node_quic_stream.cc

@@ -68,12 +68,23 @@ QuicStream::QuicStream(
   session->AddStream(this);
   StreamBase::AttachToObject(GetObject());
   PushStreamListener(&stream_listener_);
+  stream_stats_.created_at = uv_hrtime();
 }
 
 QuicStream::~QuicStream() {
   // Check that Destroy() has been called
   CHECK_NULL(session_);
   CHECK_EQ(0, streambuf_.Length());
+  uint64_t now = uv_hrtime();
+  Debug(this,
+        "QuicStream %llu destroyed.\n"
+        "  Duration: %llu\n"
+        "  Bytes Received: %llu\n"
+        "  Bytes Sent: %llu\n",
+        GetID(),
+        now - stream_stats_.created_at,
+        stream_stats_.bytes_received,
+        stream_stats_.bytes_sent);
 }
 
 inline void QuicStream::SetInitialFlags() {
@@ -155,6 +166,7 @@ int QuicStream::DoShutdown(ShutdownWrap* req_wrap) {
   // we should not attempt to send anything on the QuicSession
   if (!IsWritable())
     return 1;
+  stream_stats_.closing_at = uv_hrtime();
   SetWriteClose();
   session_->SendStreamData(this);
   return 1;
@@ -215,8 +227,10 @@ int QuicStream::DoWrite(
   // to be careful not to allow the internal buffer to grow
   // too large, or we'll run into several other problems.
 
-  streambuf_.Copy(bufs, nbufs);
+  uint64_t len = streambuf_.Copy(bufs, nbufs);
+  IncrementStat(len, &stream_stats_, &stream_stats::bytes_sent);
   req_wrap->Done(0);
+  stream_stats_.stream_sent_at = uv_hrtime();
   session_->SendStreamData(this);
 
   // IncrementAvailableOutboundLength(len);
@@ -227,6 +241,7 @@ void QuicStream::AckedDataOffset(uint64_t offset,  size_t datalen) {
   if (IsDestroyed())
     return;
   streambuf_.Consume(datalen);
+  stream_stats_.stream_acked_at = uv_hrtime();
 }
 
 size_t QuicStream::DrainInto(
@@ -277,6 +292,10 @@ void QuicStream::ReceiveData(int fin, const uint8_t* data, size_t datalen) {
   if (!IsReadable())
     return;
 
+  IncrementStat(datalen, &stream_stats_, &stream_stats::bytes_received);
+
+  stream_stats_.stream_received_at = uv_hrtime();
+
   while (datalen > 0) {
     uv_buf_t buf = EmitAlloc(datalen);
     size_t avail = std::min(static_cast<size_t>(buf.len), datalen);

src/node_quic_stream.h

@@ -235,6 +235,25 @@ class QuicStream : public AsyncWrap,
   QuicBuffer streambuf_;
   size_t available_outbound_length_;
   size_t inbound_consumed_data_while_paused_;
+
+  struct stream_stats {
+    // The timestamp at which the stream was created
+    uint64_t created_at;
+    // The timestamp at which the stream most recently sent data
+    uint64_t stream_sent_at;
+    // The timestamp at which the stream most recently received data
+    uint64_t stream_received_at;
+    // The timestamp at which the stream most recently received an
+    // acknowledgement for data
+    uint64_t stream_acked_at;
+    // The timestamp at which a graceful close started
+    uint64_t closing_at;
+    // The total number of bytes received
+    uint64_t bytes_received;
+    // The total number of bytes sent
+    uint64_t bytes_sent;
+  };
+  stream_stats stream_stats_{0, 0, 0, 0, 0, 0, 0};
 };
 
 }  // namespace quic