More trace events

The goal of this change is to unify tracing events styles and add trace events for all RTP traffic. BUG=1555 Review URL: https://webrtc-codereview.appspot.com/1290007 git-svn-id: http://webrtc.googlecode.com/svn/trunk@3806 4adac7df-926f-26a2-2b94-8c16560cd09d
2013-04-09 19:54:10 +00:00
parent 4d2f5de67a
commit 806dc3b0e6
20 changed files with 199 additions and 97 deletions
--- a/webrtc/modules/video_coding/codecs/vp8/vp8_impl.cc
+++ b/webrtc/modules/video_coding/codecs/vp8/vp8_impl.cc
@@ -331,6 +331,8 @@ uint32_t VP8EncoderImpl::MaxIntraTarget(uint32_t optimalBuffersize) {
 int VP8EncoderImpl::Encode(const I420VideoFrame& input_image,
                           const CodecSpecificInfo* codec_specific_info,
                           const std::vector<VideoFrameType>* frame_types) {
+  TRACE_EVENT1("webrtc", "VP8::Encode", "timestamp", input_image.timestamp());
+
  if (!inited_) {
    return WEBRTC_VIDEO_CODEC_UNINITIALIZED;
  }
@@ -390,9 +392,6 @@ int VP8EncoderImpl::Encode(const I420VideoFrame& input_image,
                              input_image.timestamp());
  }

-  TRACE_EVENT1("video_coding", "VP8EncoderImpl::Encode",
-               "input_image_timestamp", input_image.timestamp());
-
  // TODO(holmer): Ideally the duration should be the timestamp diff of this
  // frame and the next frame to be encoded, which we don't have. Instead we
  // would like to use the duration of the previous frame. Unfortunately the
--- a/webrtc/modules/video_coding/main/source/generic_decoder.cc
+++ b/webrtc/modules/video_coding/main/source/generic_decoder.cc
@@ -64,9 +64,6 @@ int32_t VCMDecodedFrameCallback::Decoded(I420VideoFrame& decodedImage)
        _frame.SwapFrame(&decodedImage);
        _frame.set_render_time_ms(frameInfo->renderTimeMs);
        int32_t callbackReturn = _receiveCallback->FrameToRender(_frame);
-        TRACE_EVENT_INSTANT2("webrtc_vie", "VCMDecodedFrameCallback::Decoded",
-                             "timestamp", decodedImage.timestamp(),
-                             "render_time_ms", decodedImage.render_time_ms());
        if (callbackReturn < 0)
        {
            WEBRTC_TRACE(webrtc::kTraceDebug,
@@ -169,10 +166,6 @@ int32_t VCMGenericDecoder::Decode(const VCMEncodedFrame& frame,
                 "Decoding timestamp %u", frame.TimeStamp());

    _nextFrameInfoIdx = (_nextFrameInfoIdx + 1) % kDecoderFrameMemoryLength;
-
-    TRACE_EVENT2("webrtc_vie", "VCMGenericDecoder::Decode",
-                 "timestamp", frame.TimeStamp(),
-                 "render_time_ms", frame.RenderTimeMs());
    int32_t ret = _decoder.Decode(frame.EncodedImage(),
                                        frame.MissingFrame(),
                                        frame.FragmentationHeader(),
--- a/webrtc/modules/video_coding/main/source/generic_encoder.cc
+++ b/webrtc/modules/video_coding/main/source/generic_encoder.cc
@@ -12,6 +12,7 @@
 #include "generic_encoder.h"
 #include "media_optimization.h"
 #include "../../../../engine_configurations.h"
+#include "trace_event.h"

 namespace webrtc {

@@ -177,6 +178,8 @@ VCMEncodedFrameCallback::Encoded(
    const CodecSpecificInfo* codecSpecificInfo,
    const RTPFragmentationHeader* fragmentationHeader)
 {
+    TRACE_EVENT2("webrtc", "VCM::Encoded", "timestamp", encodedImage._timeStamp,
+                 "length", encodedImage._length);
    FrameType frameType = VCMEncodedFrame::ConvertFrameType(encodedImage._frameType);

    uint32_t encodedBytes = 0;
--- a/webrtc/modules/video_coding/main/source/jitter_buffer.cc
+++ b/webrtc/modules/video_coding/main/source/jitter_buffer.cc
@@ -215,7 +215,7 @@ void VCMJitterBuffer::Stop() {
  running_ = false;
  last_decoded_state_.Reset();
  frame_list_.clear();
-  TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", "type", "Stop");
+  TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied", "type", "Stop");
  for (int i = 0; i < kMaxNumberOfFrames; i++) {
    if (frame_buffers_[i] != NULL) {
      static_cast<VCMFrameBuffer*>(frame_buffers_[i])->SetState(kStateFree);
@@ -240,7 +240,8 @@ void VCMJitterBuffer::Flush() {
  CriticalSectionScoped cs(crit_sect_);
  // Erase all frames from the sorted list and set their state to free.
  frame_list_.clear();
-  TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied", "type", "Flush");
+  TRACE_EVENT_INSTANT2("webrtc", "JB::FrameListEmptied", "type", "Flush",
+                       "frames", max_number_of_frames_);
  for (int i = 0; i < max_number_of_frames_; i++) {
    ReleaseFrameIfNotDecoding(frame_buffers_[i]);
  }
@@ -261,7 +262,6 @@ void VCMJitterBuffer::Flush() {
  WEBRTC_TRACE(webrtc::kTraceDebug, webrtc::kTraceVideoCoding,
               VCMId(vcm_id_, receiver_id_), "JB(0x%x): Jitter buffer: flush",
               this);
-  TRACE_EVENT_INSTANT0("webrtc_vie", "VCMJitterBuffer::Flush");
 }

 // Get received key and delta frames
@@ -340,8 +340,8 @@ void VCMJitterBuffer::IncomingRateStatistics(unsigned int* framerate,
    bitrate = 0;
    incoming_bit_rate_ = 0;
  }
-  TRACE_COUNTER1("webrtc_vie", "IncomingFrameRate", incoming_frame_rate_);
-  TRACE_COUNTER1("webrtc_vie", "IncomingBitRate", incoming_bit_rate_);
+  TRACE_COUNTER1("webrtc", "JBIncomingFramerate", incoming_frame_rate_);
+  TRACE_COUNTER1("webrtc", "JBIncomingBitrate", incoming_bit_rate_);
 }

 // Wait for the first packet in the next frame to arrive.
@@ -433,6 +433,7 @@ bool VCMJitterBuffer::CompleteSequenceWithNextFrame() {
 // complete frame, |max_wait_time_ms| decided by caller.
 VCMEncodedFrame* VCMJitterBuffer::GetCompleteFrameForDecoding(
    uint32_t max_wait_time_ms) {
+  TRACE_EVENT0("webrtc", "JB::GetCompleteFrame");
  if (!running_) {
    return NULL;
  }
@@ -495,7 +496,7 @@ VCMEncodedFrame* VCMJitterBuffer::GetCompleteFrameForDecoding(
  VCMFrameBuffer* oldest_frame = *it;
  it = frame_list_.erase(it);
  if (frame_list_.empty()) {
-    TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied",
+    TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied",
                         "type", "GetCompleteFrameForDecoding");
  }

@@ -521,15 +522,11 @@ VCMEncodedFrame* VCMJitterBuffer::GetCompleteFrameForDecoding(
  DropPacketsFromNackList(last_decoded_state_.sequence_num());

  crit_sect_->Leave();
-
-  TRACE_EVENT_INSTANT2("webrtc_vie",
-                       "VCMJitterBuffer::GetCompleteFrameForDecoding",
-                       "timestamp", oldest_frame->TimeStamp(),
-                       "render_time_ms", oldest_frame->RenderTimeMs());
  return oldest_frame;
 }

 VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecoding() {
+  TRACE_EVENT0("webrtc", "JB::GetFrameForDecoding");
  CriticalSectionScoped cs(crit_sect_);
  if (!running_) {
    return NULL;
@@ -572,7 +569,7 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecoding() {
  }
  frame_list_.erase(frame_list_.begin());
  if (frame_list_.empty()) {
-    TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied",
+    TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied",
                         "type", "GetFrameForDecoding");
  }

@@ -596,11 +593,6 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecoding() {
  // We have a frame - update decoded state with frame info.
  last_decoded_state_.SetState(oldest_frame);
  DropPacketsFromNackList(last_decoded_state_.sequence_num());
-
-  TRACE_EVENT_INSTANT2("webrtc_vie",
-                       "VCMJitterBuffer::GetFrameForDecoding",
-                       "timestamp", oldest_frame->TimeStamp(),
-                       "render_time_ms", oldest_frame->RenderTimeMs());
  return oldest_frame;
 }

@@ -627,10 +619,10 @@ int VCMJitterBuffer::GetFrame(const VCMPacket& packet,
    if (packet.sizeBytes > 0) {
      num_discarded_packets_++;
      num_consecutive_old_packets_++;
-      TRACE_EVENT_INSTANT2("webrtc_vie", "OldPacketDropped",
+      TRACE_EVENT_INSTANT2("webrtc", "JB::OldPacketDropped",
                           "seqnum", packet.seqNum,
                           "timestamp", packet.timestamp);
-      TRACE_COUNTER1("webrtc_vie", "DroppedOldPackets", num_discarded_packets_);
+      TRACE_COUNTER1("webrtc", "JBDroppedOldPackets", num_discarded_packets_);
    }
    // Update last decoded sequence number if the packet arrived late and
    // belongs to a frame with a timestamp equal to the last decoded
@@ -896,6 +888,8 @@ uint16_t* VCMJitterBuffer::GetNackList(uint16_t* nack_list_size,
    return NULL;
  }
  if (TooLargeNackList()) {
+    TRACE_EVENT_INSTANT1("webrtc", "JB::NackListTooLarge",
+                         "size", missing_sequence_numbers_.size());
    *request_key_frame = !HandleTooLargeNackList();
  }
  unsigned int i = 0;
@@ -925,6 +919,7 @@ bool VCMJitterBuffer::UpdateNackList(uint16_t sequence_number) {
    for (uint16_t i = latest_received_sequence_number_ + 1;
        i < sequence_number; ++i) {
      missing_sequence_numbers_.insert(missing_sequence_numbers_.end(), i);
+      TRACE_EVENT_INSTANT1("webrtc", "AddNack", "seqnum", i);
    }
    if (TooLargeNackList() && !HandleTooLargeNackList()) {
      return false;
@@ -935,6 +930,7 @@ bool VCMJitterBuffer::UpdateNackList(uint16_t sequence_number) {
    }
  } else {
    missing_sequence_numbers_.erase(sequence_number);
+    TRACE_EVENT_INSTANT1("webrtc", "RemoveNack", "seqnum", sequence_number);
  }
  return true;
 }
@@ -994,6 +990,7 @@ int64_t VCMJitterBuffer::LastDecodedTimestamp() const {
 }

 VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecodingNACK() {
+  TRACE_EVENT0("webrtc", "JB::GetFrameForDecodingNACK");
  CleanUpOldOrEmptyFrames();
  // First look for a complete continuous frame.
  // When waiting for nack, wait for a key frame, if a continuous frame cannot
@@ -1023,7 +1020,7 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecodingNACK() {
  }
  it = frame_list_.erase(it);
  if (frame_list_.empty()) {
-    TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied",
+    TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied",
                         "type", "GetFrameForDecodingNACK");
  }

@@ -1045,11 +1042,6 @@ VCMEncodedFrame* VCMJitterBuffer::GetFrameForDecodingNACK() {
  // We have a frame - update decoded state with frame info.
  last_decoded_state_.SetState(oldest_frame);
  DropPacketsFromNackList(last_decoded_state_.sequence_num());
-
-  TRACE_EVENT_INSTANT2("webrtc_vie",
-                       "VCMJitterBuffer::GetFrameForDecodingNACK",
-                       "timestamp", oldest_frame->TimeStamp(),
-                       "render_time_ms", oldest_frame->RenderTimeMs());
  return oldest_frame;
 }

@@ -1066,8 +1058,6 @@ VCMFrameBuffer* VCMJitterBuffer::GetEmptyFrame() {
    return NULL;
  }

-  TRACE_EVENT_INSTANT0("webrtc_vie", "VCMJitterBuffer::GetEmptyFrame");
-
  crit_sect_->Enter();

  for (int i = 0; i < max_number_of_frames_; ++i) {
@@ -1091,8 +1081,7 @@ VCMFrameBuffer* VCMJitterBuffer::GetEmptyFrame() {
                 VCMId(vcm_id_, receiver_id_),
                 "JB(0x%x) FB(0x%x): Jitter buffer  increased to:%d frames",
                 this, ptr_new_buffer, max_number_of_frames_);
-    TRACE_EVENT_INSTANT1("webrtc_vie", "JitterBufferIncreased",
-                         "NewSize", max_number_of_frames_);
+    TRACE_COUNTER1("webrtc", "JBMaxFrames", max_number_of_frames_);
    return ptr_new_buffer;
  }
  crit_sect_->Leave();
@@ -1113,8 +1102,7 @@ bool VCMJitterBuffer::RecycleFramesUntilKeyFrame() {
                 VCMId(vcm_id_, receiver_id_),
                 "Jitter buffer drop count:%d, low_seq %d", drop_count_,
                 (*it)->GetLowSeqNum());
-    TRACE_EVENT_INSTANT0("webrtc_vie",
-                         "VCMJitterBuffer::RecycleFramesUntilKeyFrame");
+    TRACE_EVENT_INSTANT0("webrtc", "JB::RecycleFramesUntilKeyFrame");
    ReleaseFrameIfNotDecoding(*it);
    it = frame_list_.erase(it);
    if (it != frame_list_.end() && (*it)->FrameType() == kVideoFrameKey) {
@@ -1125,7 +1113,7 @@ bool VCMJitterBuffer::RecycleFramesUntilKeyFrame() {
    }
  }
  if (frame_list_.empty()) {
-    TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied",
+    TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied",
                         "type", "RecycleFramesUntilKeyFrame");
  }
  waiting_for_key_frame_ = true;
@@ -1154,32 +1142,19 @@ VCMFrameBufferEnum VCMJitterBuffer::UpdateFrameState(VCMFrameBuffer* frame) {
                 this, frame, length, frame->FrameType());
  }

+  bool frame_counted = false;
  if (length != 0 && !frame->GetCountedFrame()) {
    // Ignore ACK frames.
    incoming_frame_count_++;
-    TRACE_EVENT_INSTANT1("webrtc_vie", "AddFrameToJitterBuffer",
-                         "timestamp", frame->TimeStamp());
-    if (frame->FrameType() == kVideoFrameKey) {
-      TRACE_EVENT_INSTANT1("webrtc_vie", "AddKeyFrameToJitterBuffer",
-                           "timestamp", frame->TimeStamp());
-    }
    frame->SetCountedFrame(true);
-  } else {
-    TRACE_EVENT_INSTANT1("webrtc_vie",
-                         "AddRetransmittedFrameToJitterBuffer",
-                         "timestamp", frame->TimeStamp());
-    if (frame->FrameType() == kVideoFrameKey) {
-      TRACE_EVENT_INSTANT1("webrtc_vie",
-                           "AddRetransmittedKeyFrameToJitterBuffer",
-                           "timestamp", frame->TimeStamp());
-    }
+    frame_counted = true;
  }

  // Check if we should drop the frame. A complete frame can arrive too late.
  if (last_decoded_state_.IsOldFrame(frame)) {
    // Frame is older than the latest decoded frame, drop it. Will be
    // released by CleanUpOldFrames later.
-    TRACE_EVENT_INSTANT1("webrtc_vie", "DropLateFrame",
+    TRACE_EVENT_INSTANT1("webrtc", "JB::DropLateFrame",
                         "timestamp", frame->TimeStamp());
    frame->Reset();
    frame->SetState(kStateEmpty);
@@ -1202,6 +1177,15 @@ VCMFrameBufferEnum VCMJitterBuffer::UpdateFrameState(VCMFrameBuffer* frame) {
  }
  num_consecutive_old_frames_ = 0;
  frame->SetState(kStateComplete);
+  if (frame->FrameType() == kVideoFrameKey) {
+    TRACE_EVENT_INSTANT2("webrtc", "JB::AddKeyFrame",
+                         "timestamp", frame->TimeStamp(),
+                         "retransmit", !frame_counted);
+  } else {
+    TRACE_EVENT_INSTANT2("webrtc", "JB::AddFrame",
+                         "timestamp", frame->TimeStamp(),
+                         "retransmit", !frame_counted);
+  }

  // Update receive statistics. We count all layers, thus when you use layers
  // adding all key and delta frames might differ from frame count.
@@ -1294,16 +1278,16 @@ void VCMJitterBuffer::CleanUpOldOrEmptyFrames() {
    }
    if (last_decoded_state_.IsOldFrame(oldest_frame)) {
      ReleaseFrameIfNotDecoding(frame_list_.front());
-      TRACE_EVENT_INSTANT1("webrtc_vie", "OldFrameDropped",
+      TRACE_EVENT_INSTANT1("webrtc", "JB::OldFrameDropped",
                           "timestamp", oldest_frame->TimeStamp());
-      TRACE_COUNTER1("webrtc_vie", "DroppedLateFrames", drop_count_);
+      TRACE_COUNTER1("webrtc", "JBDroppedLateFrames", drop_count_);
      frame_list_.erase(frame_list_.begin());
    } else {
      break;
    }
  }
  if (frame_list_.empty()) {
-    TRACE_EVENT_INSTANT1("webrtc_vie", "FrameListEmptied",
+    TRACE_EVENT_INSTANT1("webrtc", "JB::FrameListEmptied",
                         "type", "CleanUpOldOrEmptyFrames");
  }
  if (!last_decoded_state_.in_initial_state()) {
--- a/webrtc/modules/video_coding/main/source/receiver.cc
+++ b/webrtc/modules/video_coding/main/source/receiver.cc
@@ -18,6 +18,7 @@
 #include "webrtc/modules/video_coding/main/source/media_opt_util.h"
 #include "webrtc/system_wrappers/interface/clock.h"
 #include "webrtc/system_wrappers/interface/trace.h"
+#include "webrtc/system_wrappers/interface/trace_event.h"

 namespace webrtc {

@@ -173,6 +174,7 @@ VCMEncodedFrame* VCMReceiver::FrameForDecoding(
    int64_t& next_render_time_ms,
    bool render_timing,
    VCMReceiver* dual_receiver) {
+  TRACE_EVENT0("webrtc", "Recv::FrameForDecoding");
  // No need to enter the critical section here since the jitter buffer
  // is thread-safe.
  FrameType incoming_frame_type = kVideoFrameDelta;
@@ -227,6 +229,8 @@ VCMEncodedFrame* VCMReceiver::FrameForDecoding(
    uint16_t max_wait_time_ms,
    int64_t next_render_time_ms,
    VCMReceiver* dual_receiver) {
+  TRACE_EVENT1("webrtc", "FrameForDecoding",
+               "max_wait", max_wait_time_ms);
  // How long can we wait until we must decode the next frame.
  uint32_t wait_time_ms = timing_->MaxWaitingTime(
      next_render_time_ms, clock_->TimeInMilliseconds());
@@ -286,6 +290,7 @@ VCMEncodedFrame* VCMReceiver::FrameForDecoding(
 VCMEncodedFrame* VCMReceiver::FrameForRendering(uint16_t max_wait_time_ms,
                                                int64_t next_render_time_ms,
                                                VCMReceiver* dual_receiver) {
+  TRACE_EVENT0("webrtc", "FrameForRendering");
  // How long MUST we wait until we must decode the next frame. This is
  // different for the case where we have a renderer which can render at a
  // specified time. Here we must wait as long as possible before giving the
--- a/webrtc/modules/video_coding/main/source/video_coding_impl.cc
+++ b/webrtc/modules/video_coding/main/source/video_coding_impl.cc
@@ -17,6 +17,7 @@
 #include "trace.h"
 #include "video_codec_interface.h"
 #include "webrtc/system_wrappers/interface/clock.h"
+#include "webrtc/system_wrappers/interface/trace_event.h"

 namespace webrtc
 {
@@ -863,6 +864,7 @@ VideoCodingModuleImpl::RegisterPacketRequestCallback(
 int32_t
 VideoCodingModuleImpl::Decode(uint16_t maxWaitTimeMs)
 {
+    TRACE_EVENT1("webrtc", "VCM::Decode", "max_wait", maxWaitTimeMs);
    int64_t nextRenderTimeMs;
    {
        CriticalSectionScoped cs(_receiveCritSect);
@@ -954,6 +956,7 @@ int32_t
 VideoCodingModuleImpl::RequestSliceLossIndication(
    const uint64_t pictureID) const
 {
+    TRACE_EVENT1("webrtc", "RequestSLI", "picture_id", pictureID);
    if (_frameTypeCallback != NULL)
    {
        const int32_t ret =
@@ -980,6 +983,7 @@ VideoCodingModuleImpl::RequestSliceLossIndication(
 int32_t
 VideoCodingModuleImpl::RequestKeyFrame()
 {
+    TRACE_EVENT0("webrtc", "RequestKeyFrame");
    if (_frameTypeCallback != NULL)
    {
        const int32_t ret = _frameTypeCallback->RequestKeyFrame();
@@ -1062,6 +1066,9 @@ VideoCodingModuleImpl::DecodeDualFrame(uint16_t maxWaitTimeMs)
 int32_t
 VideoCodingModuleImpl::Decode(const VCMEncodedFrame& frame)
 {
+    TRACE_EVENT2("webrtc", "Decode",
+                 "timestamp", frame.TimeStamp(),
+                 "type", frame.FrameType());
    // Change decoder if payload type has changed
    const bool renderTimingBefore = _codecDataBase.SupportsRenderScheduling();
    _decoder = _codecDataBase.GetDecoder(frame.PayloadType(),
@@ -1208,6 +1215,9 @@ VideoCodingModuleImpl::IncomingPacket(const uint8_t* incomingPayload,
                                    uint32_t payloadLength,
                                    const WebRtcRTPHeader& rtpInfo)
 {
+    TRACE_EVENT2("webrtc", "VCM::Packet",
+                 "seqnum", rtpInfo.header.sequenceNumber,
+                 "type", rtpInfo.frameType);
    if (incomingPayload == NULL) {
      // The jitter buffer doesn't handle non-zero payload lengths for packets
      // without payload.