dccp: Reduce noise in output and convert to ktime_t

This fixes the problem that dccp_probe output can grow quite large without
apparent benefit (many identical data points), creating huge files (up to
over one Gigabyte for a few minutes' test run) which are very hard to
post-process (in one instance it got so bad that gnuplot ate up all memory
plus swap).

The cause for the problem is that the kprobe is inserted into dccp_sendmsg(),
which can be called in a polling-mode (whenever the TX queue is full due to
congestion-control issues, EAGAIN is returned). This creates many very
similar data points, i.e. the increase of processing time does not increase
the quality/information of the probe output.

The fix is to attach the probe to a different function -- write_xmit was
chosen since it gets called continually (both via userspace and timer);
an input-path function would stop sampling as soon as the other end stops
sending feedback.

For comparison the output file sizes for the same 20 second test
run over a lossy link:
           * before / without patch:  118   Megabytes
           * after  / with patch:       1.2 Megabytes
and there was much less noise in the output.

To allow backward compatibility with scripts that people use, the now-unused
`size' field in the output has been replaced with the CCID identifier. This
also serves for future compatibility - support for CCID2 is work in progress
(depends on the still unfinished SRTT/RTTVAR updates).

While at it, the update to ktime_t was also performed.

Signed-off-by: Gerrit Renker <gerrit@erg.abdn.ac.uk>
Acked-by: Ian McDonald <ian.mcdonald@jandi.co.nz>

diff --git a/net/dccp/probe.c b/net/dccp/probe.c
index a87fd4fc1b3d61302cd6398aa38c35b175c31e33..eaa59d82ab0f813bbaecfafa14ce6f22a34c3452 100644 (file)
--- a/net/dccp/probe.c
+++ b/net/dccp/probe.c
@@ -46,70 +46,54 @@ static struct {
        struct kfifo      *fifo;
        spinlock_t        lock;
        wait_queue_head_t wait;
-       struct timespec   tstart;
+       ktime_t           start;
 } dccpw;
 
-static void printl(const char *fmt, ...)
-{
-       va_list args;
-       int len;
-       struct timespec now;
-       char tbuf[256];
-
-       va_start(args, fmt);
-       getnstimeofday(&now);
-
-       now = timespec_sub(now, dccpw.tstart);
-
-       len = sprintf(tbuf, "%lu.%06lu ",
-                     (unsigned long) now.tv_sec,
-                     (unsigned long) now.tv_nsec / NSEC_PER_USEC);
-       len += vscnprintf(tbuf+len, sizeof(tbuf)-len, fmt, args);
-       va_end(args);
-
-       kfifo_put(dccpw.fifo, tbuf, len);
-       wake_up(&dccpw.wait);
-}
-
-static int jdccp_sendmsg(struct kiocb *iocb, struct sock *sk,
-                        struct msghdr *msg, size_t size)
+static void jdccp_write_xmit(struct sock *sk)
 {
        const struct inet_sock *inet = inet_sk(sk);
        struct ccid3_hc_tx_sock *hctx = NULL;
+       struct timespec tv;
+       char buf[256];
+       int len, ccid = ccid_get_current_tx_ccid(dccp_sk(sk));
 
-       if (ccid_get_current_tx_ccid(dccp_sk(sk)) == DCCPC_CCID3)
+       if (ccid == DCCPC_CCID3)
                hctx = ccid3_hc_tx_sk(sk);
 
-       if (port == 0 || ntohs(inet->dport) == port ||
-           ntohs(inet->sport) == port) {
-               if (hctx)
-                       printl("%d.%d.%d.%d:%u %d.%d.%d.%d:%u %d %d %d %d %u "
-                              "%llu %llu %d\n",
+       if (!port || ntohs(inet->dport) == port || ntohs(inet->sport) == port) {
+
+               tv  = ktime_to_timespec(ktime_sub(ktime_get(), dccpw.start));
+               len = sprintf(buf, "%lu.%09lu %d.%d.%d.%d:%u %d.%d.%d.%d:%u %d",
+                              (unsigned long)tv.tv_sec,
+                              (unsigned long)tv.tv_nsec,
                               NIPQUAD(inet->saddr), ntohs(inet->sport),
-                              NIPQUAD(inet->daddr), ntohs(inet->dport), size,
+                              NIPQUAD(inet->daddr), ntohs(inet->dport), ccid);
+
+               if (hctx)
+                       len += sprintf(buf + len, " %d %d %d %u %u %u %d",
                               hctx->s, hctx->rtt, hctx->p, hctx->x_calc,
-                              hctx->x_recv >> 6, hctx->x >> 6, hctx->t_ipi);
-               else
-                       printl("%d.%d.%d.%d:%u %d.%d.%d.%d:%u %d\n",
-                              NIPQUAD(inet->saddr), ntohs(inet->sport),
-                              NIPQUAD(inet->daddr), ntohs(inet->dport), size);
+                              (unsigned)(hctx->x_recv >> 6),
+                              (unsigned)(hctx->x >> 6), hctx->t_ipi);
+
+               len += sprintf(buf + len, "\n");
+               kfifo_put(dccpw.fifo, buf, len);
+               wake_up(&dccpw.wait);
        }
 
        jprobe_return();
-       return 0;
 }
 
 static struct jprobe dccp_send_probe = {
        .kp     = {
-               .symbol_name = "dccp_sendmsg",
+               .symbol_name = "dccp_write_xmit",
        },
-       .entry  = jdccp_sendmsg,
+       .entry  = jdccp_write_xmit,
 };
 
 static int dccpprobe_open(struct inode *inode, struct file *file)
 {
        kfifo_reset(dccpw.fifo);
-       getnstimeofday(&dccpw.tstart);
+       dccpw.start = ktime_get();
        return 0;
 }