Skip to content

L
linux
Commit a9672411 authored by Gerrit Renker's avatar Gerrit Renker Committed by David S. Miller
Browse files
Options

[DCCP] ccid3: Make debug output consistent 

This patch does not alter any algorithm, just the debug message format:

 * s#%s, sk=%p#%s(%p)#g

 * when a statename is present, it now uses %s(%p, state=%s)

 * when only function entry is debugged, it adds an `- entry'
Signed-off-by: default avatarGerrit Renker <gerrit@erg.abdn.ac.uk>
Acked-by: default avatarIan McDonald <ian.mcdonald@jandi.co.nz>
Signed-off-by: default avatarArnaldo Carvalho de Melo <acme@mandriva.com>
parent c5a1ae9a
Hide whitespace changes
Inline Side-by-side
Showing with 32 additions and 35 deletions
net/dccp/ccids/ccid3.c
View file @ a9672411
...@@ -201,18 +201,17 @@ static void ccid3_hc_tx_no_feedback_timer(unsigned long data) ...@@ -201,18 +201,17 @@ static void ccid3_hc_tx_no_feedback_timer(unsigned long data)
goto restart_timer; goto restart_timer;
} }
ccid3_pr_debug("%s, sk=%p, state=%s\n", dccp_role(sk), sk, ccid3_pr_debug("%s(%p, state=%s) - entry \n", dccp_role(sk), sk,
ccid3_tx_state_name(hctx->ccid3hctx_state)); ccid3_tx_state_name(hctx->ccid3hctx_state));
switch (hctx->ccid3hctx_state) { switch (hctx->ccid3hctx_state) {
case TFRC_SSTATE_NO_FBACK: case TFRC_SSTATE_NO_FBACK:
/* RFC 3448, 4.4: Halve send rate directly */ /* RFC 3448, 4.4: Halve send rate directly */
hctx->ccid3hctx_x = max_t(u32, hctx->ccid3hctx_x / 2, hctx->ccid3hctx_x = max_t(u32, hctx->ccid3hctx_x / 2,
(hctx->ccid3hctx_s << 6)/TFRC_T_MBI); (hctx->ccid3hctx_s << 6)/TFRC_T_MBI);
ccid3_pr_debug("%s, sk=%p, state=%s, updated tx rate to %u " ccid3_pr_debug("%s(%p, state=%s), updated tx rate to %u "
"bytes/s\n", "bytes/s\n", dccp_role(sk), sk,
dccp_role(sk), sk,
ccid3_tx_state_name(hctx->ccid3hctx_state), ccid3_tx_state_name(hctx->ccid3hctx_state),
(unsigned)(hctx->ccid3hctx_x >> 6)); (unsigned)(hctx->ccid3hctx_x >> 6));
/* The value of R is still undefined and so we can not recompute /* The value of R is still undefined and so we can not recompute
...@@ -230,7 +229,7 @@ static void ccid3_hc_tx_no_feedback_timer(unsigned long data) ...@@ -230,7 +229,7 @@ static void ccid3_hc_tx_no_feedback_timer(unsigned long data)
scaled_div(hctx->ccid3hctx_s << 6, hctx->ccid3hctx_rtt))) { scaled_div(hctx->ccid3hctx_s << 6, hctx->ccid3hctx_rtt))) {
struct timeval now; struct timeval now;
ccid3_pr_debug("%s, sk=%p, state=%s, not idle\n", ccid3_pr_debug("%s(%p, state=%s), not idle\n",
dccp_role(sk), sk, dccp_role(sk), sk,
ccid3_tx_state_name(hctx->ccid3hctx_state)); ccid3_tx_state_name(hctx->ccid3hctx_state));
...@@ -270,7 +269,7 @@ static void ccid3_hc_tx_no_feedback_timer(unsigned long data) ...@@ -270,7 +269,7 @@ static void ccid3_hc_tx_no_feedback_timer(unsigned long data)
t_nfb = max(hctx->ccid3hctx_t_rto, 2 * hctx->ccid3hctx_t_ipi); t_nfb = max(hctx->ccid3hctx_t_rto, 2 * hctx->ccid3hctx_t_ipi);
break; break;
case TFRC_SSTATE_NO_SENT: case TFRC_SSTATE_NO_SENT:
DCCP_BUG("Illegal %s state NO_SENT, sk=%p", dccp_role(sk), sk); DCCP_BUG("%s(%p) - Illegal state NO_SENT", dccp_role(sk), sk);
/* fall through */ /* fall through */
case TFRC_SSTATE_TERM: case TFRC_SSTATE_TERM:
goto out; goto out;
...@@ -348,7 +347,7 @@ static int ccid3_hc_tx_send_packet(struct sock *sk, struct sk_buff *skb) ...@@ -348,7 +347,7 @@ static int ccid3_hc_tx_send_packet(struct sock *sk, struct sk_buff *skb)
ccid3_hc_tx_update_win_count(hctx, &now); ccid3_hc_tx_update_win_count(hctx, &now);
break; break;
case TFRC_SSTATE_TERM: case TFRC_SSTATE_TERM:
DCCP_BUG("Illegal %s state TERM, sk=%p", dccp_role(sk), sk); DCCP_BUG("%s(%p) - Illegal state TERM", dccp_role(sk), sk);
return -EINVAL; return -EINVAL;
} }
...@@ -521,13 +520,12 @@ static void ccid3_hc_tx_packet_recv(struct sock *sk, struct sk_buff *skb) ...@@ -521,13 +520,12 @@ static void ccid3_hc_tx_packet_recv(struct sock *sk, struct sk_buff *skb)
* max(t_RTO, 2 * s/X) = max(t_RTO, 2 * t_ipi) * max(t_RTO, 2 * s/X) = max(t_RTO, 2 * t_ipi)
*/ */
t_nfb = max(hctx->ccid3hctx_t_rto, 2 * hctx->ccid3hctx_t_ipi); t_nfb = max(hctx->ccid3hctx_t_rto, 2 * hctx->ccid3hctx_t_ipi);
ccid3_pr_debug("%s, sk=%p, Scheduled no feedback timer to "
"expire in %lu jiffies (%luus)\n",
dccp_role(sk), sk,
usecs_to_jiffies(t_nfb), t_nfb);
sk_reset_timer(sk, &hctx->ccid3hctx_no_feedback_timer, ccid3_pr_debug("%s(%p), Scheduled no feedback timer to "
"expire in %lu jiffies (%luus)\n", dccp_role(sk),
sk, usecs_to_jiffies(t_nfb), t_nfb);
sk_reset_timer(sk, &hctx->ccid3hctx_no_feedback_timer,
jiffies + usecs_to_jiffies(t_nfb)); jiffies + usecs_to_jiffies(t_nfb));
/* set idle flag */ /* set idle flag */
...@@ -566,13 +564,13 @@ static int ccid3_hc_tx_parse_options(struct sock *sk, unsigned char option, ...@@ -566,13 +564,13 @@ static int ccid3_hc_tx_parse_options(struct sock *sk, unsigned char option,
switch (option) { switch (option) {
case TFRC_OPT_LOSS_EVENT_RATE: case TFRC_OPT_LOSS_EVENT_RATE:
if (unlikely(len != 4)) { if (unlikely(len != 4)) {
DCCP_WARN("%s, sk=%p, invalid len %d " DCCP_WARN("%s(%p), invalid len %d "
"for TFRC_OPT_LOSS_EVENT_RATE\n", "for TFRC_OPT_LOSS_EVENT_RATE\n",
dccp_role(sk), sk, len); dccp_role(sk), sk, len);
rc = -EINVAL; rc = -EINVAL;
} else { } else {
opt_recv->ccid3or_loss_event_rate = ntohl(*(__be32 *)value); opt_recv->ccid3or_loss_event_rate = ntohl(*(__be32 *)value);
ccid3_pr_debug("%s, sk=%p, LOSS_EVENT_RATE=%u\n", ccid3_pr_debug("%s(%p), LOSS_EVENT_RATE=%u\n",
dccp_role(sk), sk, dccp_role(sk), sk,
opt_recv->ccid3or_loss_event_rate); opt_recv->ccid3or_loss_event_rate);
} }
...@@ -580,20 +578,20 @@ static int ccid3_hc_tx_parse_options(struct sock *sk, unsigned char option, ...@@ -580,20 +578,20 @@ static int ccid3_hc_tx_parse_options(struct sock *sk, unsigned char option,
case TFRC_OPT_LOSS_INTERVALS: case TFRC_OPT_LOSS_INTERVALS:
opt_recv->ccid3or_loss_intervals_idx = idx; opt_recv->ccid3or_loss_intervals_idx = idx;
opt_recv->ccid3or_loss_intervals_len = len; opt_recv->ccid3or_loss_intervals_len = len;
ccid3_pr_debug("%s, sk=%p, LOSS_INTERVALS=(%u, %u)\n", ccid3_pr_debug("%s(%p), LOSS_INTERVALS=(%u, %u)\n",
dccp_role(sk), sk, dccp_role(sk), sk,
opt_recv->ccid3or_loss_intervals_idx, opt_recv->ccid3or_loss_intervals_idx,
opt_recv->ccid3or_loss_intervals_len); opt_recv->ccid3or_loss_intervals_len);
break; break;
case TFRC_OPT_RECEIVE_RATE: case TFRC_OPT_RECEIVE_RATE:
if (unlikely(len != 4)) { if (unlikely(len != 4)) {
DCCP_WARN("%s, sk=%p, invalid len %d " DCCP_WARN("%s(%p), invalid len %d "
"for TFRC_OPT_RECEIVE_RATE\n", "for TFRC_OPT_RECEIVE_RATE\n",
dccp_role(sk), sk, len); dccp_role(sk), sk, len);
rc = -EINVAL; rc = -EINVAL;
} else { } else {
opt_recv->ccid3or_receive_rate = ntohl(*(__be32 *)value); opt_recv->ccid3or_receive_rate = ntohl(*(__be32 *)value);
ccid3_pr_debug("%s, sk=%p, RECEIVE_RATE=%u\n", ccid3_pr_debug("%s(%p), RECEIVE_RATE=%u\n",
dccp_role(sk), sk, dccp_role(sk), sk,
opt_recv->ccid3or_receive_rate); opt_recv->ccid3or_receive_rate);
} }
...@@ -679,7 +677,7 @@ static void ccid3_hc_rx_send_feedback(struct sock *sk) ...@@ -679,7 +677,7 @@ static void ccid3_hc_rx_send_feedback(struct sock *sk)
struct timeval now; struct timeval now;
suseconds_t delta; suseconds_t delta;
ccid3_pr_debug("%s, sk=%p\n", dccp_role(sk), sk); ccid3_pr_debug("%s(%p) - entry \n", dccp_role(sk), sk);
dccp_timestamp(sk, &now); dccp_timestamp(sk, &now);
...@@ -695,13 +693,13 @@ static void ccid3_hc_rx_send_feedback(struct sock *sk) ...@@ -695,13 +693,13 @@ static void ccid3_hc_rx_send_feedback(struct sock *sk)
scaled_div32(hcrx->ccid3hcrx_bytes_recv, delta); scaled_div32(hcrx->ccid3hcrx_bytes_recv, delta);
break; break;
case TFRC_RSTATE_TERM: case TFRC_RSTATE_TERM:
DCCP_BUG("Illegal %s state TERM, sk=%p", dccp_role(sk), sk); DCCP_BUG("%s(%p) - Illegal state TERM", dccp_role(sk), sk);
return; return;
} }
packet = dccp_rx_hist_find_data_packet(&hcrx->ccid3hcrx_hist); packet = dccp_rx_hist_find_data_packet(&hcrx->ccid3hcrx_hist);
if (unlikely(packet == NULL)) { if (unlikely(packet == NULL)) {
DCCP_WARN("%s, sk=%p, no data packet in history!\n", DCCP_WARN("%s(%p), no data packet in history!\n",
dccp_role(sk), sk); dccp_role(sk), sk);
return; return;
} }
...@@ -797,13 +795,13 @@ static u32 ccid3_hc_rx_calc_first_li(struct sock *sk) ...@@ -797,13 +795,13 @@ static u32 ccid3_hc_rx_calc_first_li(struct sock *sk)
} }
if (unlikely(step == 0)) { if (unlikely(step == 0)) {
DCCP_WARN("%s, sk=%p, packet history has no data packets!\n", DCCP_WARN("%s(%p), packet history has no data packets!\n",
dccp_role(sk), sk); dccp_role(sk), sk);
return ~0; return ~0;
} }
if (unlikely(interval == 0)) { if (unlikely(interval == 0)) {
DCCP_WARN("%s, sk=%p, Could not find a win_count interval > 0." DCCP_WARN("%s(%p), Could not find a win_count interval > 0."
"Defaulting to 1\n", dccp_role(sk), sk); "Defaulting to 1\n", dccp_role(sk), sk);
interval = 1; interval = 1;
} }
...@@ -817,7 +815,7 @@ static u32 ccid3_hc_rx_calc_first_li(struct sock *sk) ...@@ -817,7 +815,7 @@ static u32 ccid3_hc_rx_calc_first_li(struct sock *sk)
DCCP_BUG_ON(delta < 0); DCCP_BUG_ON(delta < 0);
rtt = delta * 4 / interval; rtt = delta * 4 / interval;
ccid3_pr_debug("%s, sk=%p, approximated RTT to %ldus\n", ccid3_pr_debug("%s(%p), approximated RTT to %ldus\n",
dccp_role(sk), sk, rtt); dccp_role(sk), sk, rtt);
/* /*
...@@ -850,7 +848,7 @@ static u32 ccid3_hc_rx_calc_first_li(struct sock *sk) ...@@ -850,7 +848,7 @@ static u32 ccid3_hc_rx_calc_first_li(struct sock *sk)
fval = scaled_div32(fval, x_recv); fval = scaled_div32(fval, x_recv);
p = tfrc_calc_x_reverse_lookup(fval); p = tfrc_calc_x_reverse_lookup(fval);
ccid3_pr_debug("%s, sk=%p, receive rate=%u bytes/s, implied " ccid3_pr_debug("%s(%p), receive rate=%u bytes/s, implied "
"loss rate=%u\n", dccp_role(sk), sk, x_recv, p); "loss rate=%u\n", dccp_role(sk), sk, x_recv, p);
if (p == 0) if (p == 0)
...@@ -1000,8 +998,8 @@ static void ccid3_hc_rx_packet_recv(struct sock *sk, struct sk_buff *skb) ...@@ -1000,8 +998,8 @@ static void ccid3_hc_rx_packet_recv(struct sock *sk, struct sk_buff *skb)
r_sample / 10; r_sample / 10;
if (rtt_prev != hcrx->ccid3hcrx_rtt) if (rtt_prev != hcrx->ccid3hcrx_rtt)
ccid3_pr_debug("%s, New RTT=%uus, elapsed time=%u\n", ccid3_pr_debug("%s(%p), New RTT=%uus, elapsed time=%u\n",
dccp_role(sk), hcrx->ccid3hcrx_rtt, dccp_role(sk), sk, hcrx->ccid3hcrx_rtt,
opt_recv->dccpor_elapsed_time); opt_recv->dccpor_elapsed_time);
break; break;
case DCCP_PKT_DATA: case DCCP_PKT_DATA:
...@@ -1013,7 +1011,7 @@ static void ccid3_hc_rx_packet_recv(struct sock *sk, struct sk_buff *skb) ...@@ -1013,7 +1011,7 @@ static void ccid3_hc_rx_packet_recv(struct sock *sk, struct sk_buff *skb)
packet = dccp_rx_hist_entry_new(ccid3_rx_hist, sk, opt_recv->dccpor_ndp, packet = dccp_rx_hist_entry_new(ccid3_rx_hist, sk, opt_recv->dccpor_ndp,
skb, GFP_ATOMIC); skb, GFP_ATOMIC);
if (unlikely(packet == NULL)) { if (unlikely(packet == NULL)) {
DCCP_WARN("%s, sk=%p, Not enough mem to add rx packet " DCCP_WARN("%s(%p), Not enough mem to add rx packet "
"to history, consider it lost!\n", dccp_role(sk), sk); "to history, consider it lost!\n", dccp_role(sk), sk);
return; return;
} }
...@@ -1028,9 +1026,8 @@ static void ccid3_hc_rx_packet_recv(struct sock *sk, struct sk_buff *skb) ...@@ -1028,9 +1026,8 @@ static void ccid3_hc_rx_packet_recv(struct sock *sk, struct sk_buff *skb)
switch (hcrx->ccid3hcrx_state) { switch (hcrx->ccid3hcrx_state) {
case TFRC_RSTATE_NO_DATA: case TFRC_RSTATE_NO_DATA:
ccid3_pr_debug("%s, sk=%p(%s), skb=%p, sending initial " ccid3_pr_debug("%s(%p, state=%s), skb=%p, sending initial "
"feedback\n", "feedback\n", dccp_role(sk), sk,
dccp_role(sk), sk,
dccp_state_name(sk->sk_state), skb); dccp_state_name(sk->sk_state), skb);
ccid3_hc_rx_send_feedback(sk); ccid3_hc_rx_send_feedback(sk);
ccid3_hc_rx_set_state(sk, TFRC_RSTATE_DATA); ccid3_hc_rx_set_state(sk, TFRC_RSTATE_DATA);
...@@ -1048,12 +1045,12 @@ static void ccid3_hc_rx_packet_recv(struct sock *sk, struct sk_buff *skb) ...@@ -1048,12 +1045,12 @@ static void ccid3_hc_rx_packet_recv(struct sock *sk, struct sk_buff *skb)
} }
return; return;
case TFRC_RSTATE_TERM: case TFRC_RSTATE_TERM:
DCCP_BUG("Illegal %s state TERM, sk=%p", dccp_role(sk), sk); DCCP_BUG("%s(%p) - Illegal state TERM", dccp_role(sk), sk);
return; return;
} }
/* Dealing with packet loss */ /* Dealing with packet loss */
ccid3_pr_debug("%s, sk=%p(%s), data loss! Reacting...\n", ccid3_pr_debug("%s(%p, state=%s), data loss! Reacting...\n",
dccp_role(sk), sk, dccp_state_name(sk->sk_state)); dccp_role(sk), sk, dccp_state_name(sk->sk_state));
p_prev = hcrx->ccid3hcrx_p; p_prev = hcrx->ccid3hcrx_p;
...@@ -1078,7 +1075,7 @@ static int ccid3_hc_rx_init(struct ccid *ccid, struct sock *sk) ...@@ -1078,7 +1075,7 @@ static int ccid3_hc_rx_init(struct ccid *ccid, struct sock *sk)
{ {
struct ccid3_hc_rx_sock *hcrx = ccid_priv(ccid); struct ccid3_hc_rx_sock *hcrx = ccid_priv(ccid);
ccid3_pr_debug("%s, sk=%p\n", dccp_role(sk), sk); ccid3_pr_debug("entry\n");
hcrx->ccid3hcrx_state = TFRC_RSTATE_NO_DATA; hcrx->ccid3hcrx_state = TFRC_RSTATE_NO_DATA;
INIT_LIST_HEAD(&hcrx->ccid3hcrx_hist); INIT_LIST_HEAD(&hcrx->ccid3hcrx_hist);
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment
GitLab Nexedi Edition | About GitLab | About Nexedi | 沪ICP备2021021310号-2 | 沪ICP备2021021310号-7