summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorArun Raghavan <arun@centricular.com>2015-09-30 12:06:25 (GMT)
committerArun Raghavan <arun@centricular.com>2015-10-28 05:55:51 (GMT)
commit72223b60e1c2818ada5765c5322cd6fd562ef45e (patch)
tree6309109031f12bffcb34cf1d8563212c22d90283
parent5577e596c43493ccf4d1c0932f55f1ffb8dc447b (diff)
downloadopenwebrtc-gst-plugins-72223b60e1c2818ada5765c5322cd6fd562ef45e.tar.gz
openwebrtc-gst-plugins-72223b60e1c2818ada5765c5322cd6fd562ef45e.tar.xz
scream: Improve debug logging
Makes it easier to follow the code path in debug logs when things don't work as expected.
-rw-r--r--gst/scream/gstscreamcontroller.c22
-rw-r--r--gst/scream/gstscreamqueue.c12
2 files changed, 24 insertions, 10 deletions
diff --git a/gst/scream/gstscreamcontroller.c b/gst/scream/gstscreamcontroller.c
index c3e3f2f..c9096f7 100644
--- a/gst/scream/gstscreamcontroller.c
+++ b/gst/scream/gstscreamcontroller.c
@@ -101,10 +101,6 @@
* "catching up" when the throughput drops from a very high to a very low value */
#define MAX_RTP_QUEUE_TIME 2.0f
-/*
-GST_DEBUG_CATEGORY_STATIC(gst_scream_controller_debug_category);
-#define GST_CAT_DEFAULT gst_scream_controller_debug_category
-*/
GST_DEBUG_CATEGORY_EXTERN(gst_scream_queue_debug_category);
#define GST_CAT_DEFAULT gst_scream_queue_debug_category
@@ -377,7 +373,7 @@ gboolean gst_scream_controller_register_new_stream(GstScreamController *controll
g_mutex_lock(&controller->lock);
if (g_hash_table_contains(controller->streams, GUINT_TO_POINTER(stream_id))) {
- g_warning("Failed to register new scream stream. The session id needs to be unique.");
+ GST_WARNING("Failed to register new scream stream. The session id needs to be unique.");
goto end;
}
@@ -449,7 +445,7 @@ guint64 gst_scream_controller_packet_transmitted(GstScreamController *self, guin
* Pick any used entry
*/
ix = 0;
- g_warning("Max number of transmitted_packets allocated, consider increasing MAX_TX_PACKETS %u\n", MAX_TX_PACKETS);
+ GST_WARNING("Max number of transmitted_packets allocated, consider increasing MAX_TX_PACKETS %u\n", MAX_TX_PACKETS);
}
packet = &self->transmitted_packets[ix];
@@ -551,12 +547,14 @@ guint64 gst_scream_controller_approve_transmits(GstScreamController *self, guint
stream = get_prioritized_stream(self);
if (!stream) {
goto end;
- }
+ } else
+ GST_DEBUG("Current prioritized stream is %u", stream->id);
/*
* Enforce packet pacing
*/
if (self->next_transmit_t_us - time_us > 1000 && self->next_transmit_t_us > time_us) {
+ GST_DEBUG("Enforcing packet pacing: time: %lu, next_transmit_t: %lu", time_us, self->next_transmit_t_us);
next_approve_time = self->next_transmit_t_us - time_us;
goto end;
}
@@ -567,6 +565,7 @@ guint64 gst_scream_controller_approve_transmits(GstScreamController *self, guint
update_bytes_in_flight_history(self, time_us);
size_of_next_rtp = get_next_packet_size(stream);
if (!size_of_next_rtp) {
+ GST_DEBUG("Too many bytes in flight (avail: %u)", size_of_next_rtp);
goto end;
}
@@ -577,12 +576,16 @@ guint64 gst_scream_controller_approve_transmits(GstScreamController *self, guint
*/
if (self->owd > self->owd_target) {
exit = (bytes_in_flight(self) + size_of_next_rtp) > self->cwnd;
+ GST_DEBUG("Current OWD > target, exit = %u + %u > %u = %u",
+ bytes_in_flight(self), size_of_next_rtp, self->cwnd, exit);
} else {
float x_cwnd, max_cwnd;
x_cwnd = 1.0f + BYTES_IN_FLIGHT_SLACK * MAX(0.0f,
MIN(1.0f, 1.0f - self->owd_trend / 0.5f));
max_cwnd = MAX(self->cwnd * x_cwnd, (float)self->cwnd + self->mss);
exit = bytes_in_flight(self) + size_of_next_rtp > max_cwnd;
+ GST_DEBUG("Current OWD <= target, exit = %u + %u > %g = %u",
+ bytes_in_flight(self), size_of_next_rtp, max_cwnd, exit);
}
/*
@@ -592,6 +595,7 @@ guint64 gst_scream_controller_approve_transmits(GstScreamController *self, guint
*/
if (time_us - self->last_transmit_t_us > 200000) {
exit = FALSE;
+ GST_DEBUG("Too long since we transmitted, so overriding");
}
if (!exit) {
@@ -618,7 +622,7 @@ void gst_scream_controller_new_rtp_packet(GstScreamController *self, guint strea
stream = g_hash_table_lookup(self->streams, GUINT_TO_POINTER(stream_id));
if (!stream) {
- g_warning("Scream controller received an RTP packet that did not belong to a registered\n"
+ GST_WARNING("Scream controller received an RTP packet that did not belong to a registered\n"
"stream. stream_id is %u\n", stream_id);
goto end;
}
@@ -1058,7 +1062,7 @@ void gst_scream_controller_incoming_feedback(GstScreamController *self, guint st
stream = g_hash_table_lookup(self->streams, GUINT_TO_POINTER(stream_id));
if (!stream) {
- g_warning("Received feedback for an unknown stream.");
+ GST_WARNING("Received feedback for an unknown stream.");
goto end;
}
diff --git a/gst/scream/gstscreamqueue.c b/gst/scream/gstscreamqueue.c
index 3afa277..70b969d 100644
--- a/gst/scream/gstscreamqueue.c
+++ b/gst/scream/gstscreamqueue.c
@@ -412,10 +412,12 @@ static GstFlowReturn gst_scream_queue_sink_chain(GstPad *pad, GstObject *parent,
if (self->pass_through) {
rtp_item->adapted = FALSE;
+ GST_LOG_OBJECT(self, "passing through: pt = %u, seq: %u, pass: %u", rtp_item->rtp_pt, rtp_item->rtp_seq, self->pass_through);
gst_data_queue_push(self->approved_packets, (GstDataQueueItem *)rtp_item);
goto end;
}
+ GST_LOG_OBJECT(self, "queuing: pt = %u, seq: %u, pass: %u", rtp_item->rtp_pt, rtp_item->rtp_seq, self->pass_through);
g_async_queue_push(self->incoming_packets, (gpointer)rtp_item);
end:
@@ -473,7 +475,8 @@ static void gst_scream_queue_srcpad_loop(GstScreamQueue *self)
if (time_now_us >= self->next_approve_time) {
time_until_next_approve = gst_scream_controller_approve_transmits(self->scream_controller,
time_now_us);
- }
+ } else
+ GST_LOG_OBJECT(self, "Time is %lu, waiting %lu", time_now_us, self->next_approve_time);
/* Send all approved packets */
while (!gst_data_queue_is_empty(self->approved_packets)) {
@@ -486,6 +489,8 @@ static void gst_scream_queue_srcpad_loop(GstScreamQueue *self)
buffer = GST_BUFFER(((GstDataQueueItem *)rtp_item)->object);
gst_pad_push(self->src_pad, buffer);
+ GST_LOG_OBJECT(self, "pushing: pt = %u, seq: %u, pass: %u", rtp_item->rtp_pt, rtp_item->rtp_seq, self->pass_through);
+
if (rtp_item->adapted) {
guint tmp_time;
stream_id = ((GstScreamDataQueueItem *)rtp_item)->rtp_ssrc;
@@ -497,6 +502,7 @@ static void gst_scream_queue_srcpad_loop(GstScreamQueue *self)
}
self->next_approve_time = time_now_us + time_until_next_approve;
+ GST_LOG_OBJECT(self, "Popping or waiting %lu", time_until_next_approve);
item = (GstScreamDataQueueItem *)g_async_queue_timeout_pop(self->incoming_packets, time_until_next_approve);
if (!item) {
goto end;
@@ -508,6 +514,8 @@ static void gst_scream_queue_srcpad_loop(GstScreamQueue *self)
stream = get_stream(self, item->rtp_ssrc, rtp_item->rtp_pt);
if (!stream) {
rtp_item->adapted = FALSE;
+ GST_LOG_OBJECT(self, "!adapted, approving: pt = %u, seq: %u, pass: %u",
+ rtp_item->rtp_pt, rtp_item->rtp_seq, self->pass_through);
gst_data_queue_push(self->approved_packets, (GstDataQueueItem *)item);
} else {
if (G_LIKELY(gst_data_queue_push(stream->packet_queue, (GstDataQueueItem *)rtp_item))) {
@@ -665,6 +673,8 @@ static void approve_transmit_cb(guint stream_id, GstScreamQueue *self) {
if (gst_data_queue_pop(stream->packet_queue, (GstDataQueueItem **)&item)) {
stream->enqueued_payload_size -= item->rtp_payload_size;
stream->enqueued_packets--;
+ GST_LOG_OBJECT(self, "approving: pt = %u, seq: %u, pass: %u",
+ item->rtp_pt, item->rtp_seq, self->pass_through);
gst_data_queue_push(self->approved_packets, (GstDataQueueItem *)item);
}
}