[BUG] DCCP performance stops on CCID3 at times

[BUG] DCCP performance stops on CCID3 at times

[Ian McDonald]

Folks,

Was chatting to Arnaldo about how I was working on this and he suggested to post to list. I'm still working on it but anybody else can feel free to help!

I was getting the following in my logs sometimes when testing and the connection would basically stop:
Nov  1 15:16:47 localhost kernel: [15923.523670] dccp_li_hist_calc_i_mean: w_tot = 0

So I've added some debugs in as per below:
---
diff --git a/net/dccp/ccids/ccid3.c b/net/dccp/ccids/ccid3.c
index 788ee0f..e8c9584 100644
--- a/net/dccp/ccids/ccid3.c
+++ b/net/dccp/ccids/ccid3.c
@@ -834,21 +834,21 @@ static u32 ccid3_hc_rx_calc_first_li(str
 	}
 
 	if (unlikely(step = 0)) {
-		LIMIT_NETDEBUG(KERN_WARNING "%s: %s, sk=%p, packet history "
+		printk(KERN_CRIT "%s: %s, sk=%p, packet history "
 			       "contains no data packets!\n",
 			       __FUNCTION__, dccp_role(sk), sk);
 		return ~0;
 	}
 
 	if (unlikely(interval = 0)) {
-		LIMIT_NETDEBUG(KERN_WARNING "%s: %s, sk=%p, Could not find a "
+		printk(KERN_CRIT "%s: %s, sk=%p, Could not find a "
 			       "win_count interval > 0. Defaulting to 1\n",
 			       __FUNCTION__, dccp_role(sk), sk);
 		interval = 1;
 	}
 found:
 	if (!tail) {
-		LIMIT_NETDEBUG(KERN_WARNING "%s: tail is null\n",
+		printk(KERN_CRIT "%s: tail is null\n",
 		   __FUNCTION__);
 		return ~0;
 	}
@@ -870,7 +870,7 @@ found:
 	tmp2 = (u32)tmp1;
 
 	if (!tmp2) {
-		LIMIT_NETDEBUG(KERN_WARNING "tmp2 = 0 "
+		printk(KERN_CRIT "tmp2 = 0 "
 		   "%s: x_recv = %u, rtt =%u\n",
 		   __FUNCTION__, x_recv, rtt);
 		return ~0;
@@ -882,9 +882,10 @@ found:
 	ccid3_pr_debug("%s, sk=%p, receive rate=%u bytes/s, implied "
 		       "loss rate=%u\n", dccp_role(sk), sk, x_recv, p);
 
-	if (p = 0)
+	if (p = 0) {
+		printk(KERN_CRIT "%s: p = 0, fval = %d\n",__FUNCTION__,fval);
 		return ~0;
-	else
+	} else
 		return 1000000 / p; 
 }
 
@@ -896,9 +897,10 @@ static void ccid3_hc_rx_update_li(struct
 
 	if (list_empty(&hcrx->ccid3hcrx_li_hist)) {
 		if (!dccp_li_hist_interval_new(ccid3_li_hist,
-		   &hcrx->ccid3hcrx_li_hist, seq_loss, win_loss))
+		   &hcrx->ccid3hcrx_li_hist, seq_loss, win_loss)) {
+		   	printk(KERN_CRIT "%s:interval_new failed\n",__FUNCTION__);
 			return;
-
+		}
 		head = list_entry(hcrx->ccid3hcrx_li_hist.next,
 		   struct dccp_li_hist_entry, dccplih_node);
 		head->dccplih_interval = ccid3_hc_rx_calc_first_li(sk);
@@ -929,6 +931,9 @@ static void ccid3_hc_rx_update_li(struct
 		list_del(tail);
 		kmem_cache_free(ccid3_li_hist->dccplih_slab, tail);
 
+		if (seq_temp = ~0)
+			printk(KERN_CRIT "%s: seq_temp = ~0\n",__FUNCTION__);
+
 		/* Create the newest interval */
 		entry->dccplih_seqno = seq_loss;
 		entry->dccplih_interval = seq_temp;
---

And now I get these subcases:
Nov  2 21:22:21 localhost kernel: [26564.665163] ccid3_hc_rx_calc_first_li: p = 0, fval = 7046
This is due to the computed x_recv being very, very low I believe. So it sets it to ~0

Nov  2 21:22:21 localhost kernel: [26564.665381] dccp_li_hist_calc_i_mean: w_tot = 0
Nov  3 02:27:46 localhost kernel: [44880.646467] ccid3_hc_rx_calc_first_li: server, skÜ04b16c, Could not find a win_count interval > 0. Defaulting to 1
Nov  3 02:27:46 localhost kernel: [44880.646538] tmp2 = 0 ccid3_hc_rx_calc_first_li: x_recv = 0, rtt =1

These other cases I have to investigate. First is most common though. I think I should fix them all.

Other random notes:
This is from dccp_li_hist_calc_i_mean in ccids/lib/loss_interval.c

Because dccp_li_hist_w[i] is static this means that all values of li_entry->dccplih_interval must be ~0.

calc_i_mean is only called by ccid3_hc_rx_packet_recv in ccids/ccid3.c after a loss has been found. This means that li_entry->dccplih_interval on one of the nodes mustn't be getting set.

dccplih_interval only gets altered in ccid3_hc_rx_update_li in ccid3.c. If the list is empty it gets created and dccplih_interval gets set to ccid3_hc_rx_calc_first_li or alternatively to dccp_delta_seqno result.

dccp_delta_seqno could return ~0 if numbers are reversed. (but this has proved not to be the case yet)

The spec does say transmission can drop to as low as 1 packet every 64 seconds but some of it is tied up to this I think:
http://www.mail-archive.com/dccp@vger.kernel.org/msg00467.html

Re: [BUG] DCCP performance stops on CCID3 at times

[Gerrit Renker]

Quoting Ian McDonald:
|  I'm still working on it but anybody else can feel free to help!
It is great to see that this is picked up. It is one of the items which I had put onto the ToDo list as well,
the thread starting this began on 
		http://www.mail-archive.com/dccp%40vger.kernel.org/msg00446.html


|  And now I get these subcases:
|  Nov  2 21:22:21 localhost kernel: [26564.665163] ccid3_hc_rx_calc_first_li: p = 0, fval = 7046
|  This is due to the computed x_recv being very, very low I believe. So it sets it to ~0
|  
|  Nov  2 21:22:21 localhost kernel: [26564.665381] dccp_li_hist_calc_i_mean: w_tot = 0
|  Nov  3 02:27:46 localhost kernel: [44880.646467] ccid3_hc_rx_calc_first_li: server, skÜ04b16c, Could not find a win_count interval > 0. Defaulting to 1
|  Nov  3 02:27:46 localhost kernel: [44880.646538] tmp2 = 0 ccid3_hc_rx_calc_first_li: x_recv = 0, rtt =1
I wonder whether this is due to the RTT, due to the following statement in ccid3_hc_rx_calc_first_li:
	if (rtt = 0)
		rtt = 1;
Maybe it would be good to print out when the RTT estimate is zero (with regard to the other email, I am still
puzzled about the Receiver-RTT measurement). The same statement re-appears in tfrc_calc_x (to avoid division-by-zero), 
without warning. 
I think that a warning message could bring in some light: maybe it is the case here that the RTT measurement is just
at rock bottom, always returns 0,  and thus always stays at 1. 


It would be great if you could come up with something, you know this code best. I have put it into my `TBD' folder
and may just pester with emails later ;-) 

There is another thread which I think may be of relevance, incidentally again at the rx_packet_recv function:

	http://www.mail-archive.com/dccp%40vger.kernel.org/msg00118.html

I put this also into the ToDo list, but I am still stuck with other work. Maybe we could kill all those ToDos in 
one swoop?

-- Gerrit
 

Re: [BUG] DCCP performance stops on CCID3 at times

[Ian McDonald]

Gerrit,

Comments inline.

On 11/17/06, Gerrit Renker <gerrit@erg.abdn.ac.uk> wrote:
>It is great to see that this is picked up. It is one of the items
which I had put onto the ToDo >list as well,
>the thread starting this began on
>               http://www.mail-archive.com/dccp%40vger.kernel.org/msg00446.html

That is the same bug as
http://www.mail-archive.com/dccp@vger.kernel.org/msg00467.html which I
mentioned in my original email.

> |  Nov  3 02:27:46 localhost kernel: [44880.646538] tmp2 = 0 ccid3_hc_rx_calc_first_li: x_recv = 0, rtt =1
> I wonder whether this is due to the RTT, due to the following statement in ccid3_hc_rx_calc_first_li:
>         if (rtt = 0)
>                 rtt = 1;

Of course it is! I feel stupid I didn't find that one....

> Maybe it would be good to print out when the RTT estimate is zero (with regard to the other email, I am still
> puzzled about the Receiver-RTT measurement). The same statement re-appears in tfrc_calc_x (to avoid division-by-zero),
> without warning.
> I think that a warning message could bring in some light: maybe it is the case here that the RTT measurement is just
> at rock bottom, always returns 0,  and thus always stays at 1.

It was just put in there to stop divide by zeros. It wasn't meant to
be a proper fix.
>
>
> It would be great if you could come up with something, you know this code best. I have put it into my `TBD' folder
> and may just pester with emails later ;-)

Yes I will try and look at it all again when I get the chance.
>
> There is another thread which I think may be of relevance, incidentally again at the rx_packet_recv function:
>
>         http://www.mail-archive.com/dccp%40vger.kernel.org/msg00118.html
>
This one has already been fixed. If you look at the code it's changed
a fair bit since then. This was a bug which crippled my testing and I
was glad to get sorted. I also removed some of the cc_val/window stuff
at this point as I figured 80% working was better than 0% working as
regards to congestion control...

Ian
-- 
Ian McDonald
Web: http://wand.net.nz/~iam4
Blog: http://imcdnzl.blogspot.com
WAND Network Research Group
Department of Computer Science
University of Waikato
New Zealand

Re: [BUG] DCCP performance stops on CCID3 at times

[Gerrit Renker]

Quoting Ian McDonald:
|  > I think that a warning message could bring in some light: maybe it is the case here that the RTT measurement is just
|  > at rock bottom, always returns 0,  and thus always stays at 1.
|  
|  It was just put in there to stop divide by zeros. It wasn't meant to
|  be a proper fix.
I have added warning messages in latest patch. 

|  >
|  > There is another thread which I think may be of relevance, incidentally again at the rx_packet_recv function:
|  >
|  >         http://www.mail-archive.com/dccp%40vger.kernel.org/msg00118.html
|  >
|  This one has already been fixed. If you look at the code it's changed
|  a fair bit since then. This was a bug which crippled my testing and I
|  was glad to get sorted. I also removed some of the cc_val/window stuff
|  at this point as I figured 80% working was better than 0% working as
|  regards to congestion control...
I take your word for it - when looking yesterday, I noted that new functions and variable names
were used, but the structure seemed somewhat similar - but I am not so familiar with the CCID 3 code.
Will do some more code reading.

-- Gerrit