]> www.infradead.org Git - users/jedix/linux-maple.git/commitdiff
sdp: /proc/net/sdpprf - performance utilities
authorAmir Vadai <amirv@mellanox.co.il>
Sun, 26 Apr 2009 07:55:26 +0000 (10:55 +0300)
committerMukesh Kacker <mukesh.kacker@oracle.com>
Tue, 6 Oct 2015 12:04:27 +0000 (05:04 -0700)
Signed-off-by: Amir Vadai <amirv@mellanox.co.il>
drivers/infiniband/ulp/sdp/perf.pl [new file with mode: 0755]
drivers/infiniband/ulp/sdp/sdp.h
drivers/infiniband/ulp/sdp/sdp_bcopy.c
drivers/infiniband/ulp/sdp/sdp_cma.c
drivers/infiniband/ulp/sdp/sdp_main.c
drivers/infiniband/ulp/sdp/sdp_proc.c

diff --git a/drivers/infiniband/ulp/sdp/perf.pl b/drivers/infiniband/ulp/sdp/perf.pl
new file mode 100755 (executable)
index 0000000..58204d3
--- /dev/null
@@ -0,0 +1,84 @@
+#!/usr/bin/perl
+
+use strict;
+
+sub average {
+       @_ == 1 or die ('Sub usage: $average = average(\@array);');
+       my ($array_ref) = @_;
+       my $sum;
+       my $count = scalar @$array_ref;
+       foreach (@$array_ref) { $sum += $_; }
+       return 0 if !$count;
+       return $sum / $count;
+}
+
+sub median {
+       @_ == 1 or die ('Sub usage: $median = median(\@array);');
+       my ($array_ref) = @_;
+       my $count = scalar @$array_ref;
+
+       # Sort a COPY of the array, leaving the original untouched
+       my @array = sort { $a <=> $b } @$array_ref;
+       if ($count % 2) {
+               return $array[int($count/2)];
+       } else {
+               return ($array[$count/2] + $array[$count/2 - 1]) / 2;
+       }
+}
+
+open FD, "</proc/net/sdpprf" || die "Couldn't find proc file";
+
+my %create_time;
+my @skb_send_till_posted;
+my @skb_send_interval;
+my @skb_post_interval;
+my $last_send_time = -1;
+my $last_post_time = -1;
+
+while (my $line = <FD>) {
+       if ($line =~ /^([0-9]*).*\[([0-9 .]*)\] Created.*skb: ([0-9a-f]*)/) {
+               my $idx = $1;
+               my $time = $2;
+               my $skb = $3;
+               $create_time{$skb} = $time;
+               if ($last_send_time > -1) {
+                       my $delta = $time - $last_send_time;
+                       $delta = int($delta * 1000000);
+                       push @skb_send_interval, $delta;
+                       print "skb_send_interval: $idx $skb - $delta\n";
+               }
+               $last_send_time = $time;
+#              print "Start: $time - $skb\n";
+       } elsif ($line =~ /^([0-9]*).*\[([0-9 .]*)\] post_send mid = SDP_MID_DATA.*skb: ([0-9a-f]*)/) {
+               my $idx = $1;
+               my $time = $2;
+               my $skb = $3;
+               if ($last_post_time > -1) {
+                       my $delta = $time - $last_post_time;
+                       $delta = int($delta * 1000000);
+                       push @skb_post_interval, $delta;
+                       print "skb_post_interval: $idx $skb - $delta\n";
+               }
+               $last_post_time = $time;
+               if ($create_time{$skb}) {
+                       my $delta = $time - $create_time{$skb};
+                       $delta = int($delta * 1000000);
+#                      print "create..send $skb $time..$create_time{$skb}: $delta usec\n";
+                       push @skb_send_till_posted, $delta;
+               }
+       }
+}
+
+print "skb send .. posted:\n";
+print "  median : " . median(\@skb_send_till_posted) . "\n";
+print "  average: " . average(\@skb_send_till_posted) . "\n";
+
+print "skb send interval:\n";
+print "  median : " . median(\@skb_send_interval) . "\n";
+print "  average: " . average(\@skb_send_interval) . "\n";
+
+print "skb post interval:\n";
+print "  median : " . median(\@skb_post_interval) . "\n";
+print "  average: " . average(\@skb_post_interval) . "\n";
+
+close FD;
index 81280655d3acd99a81272e35bb4fd50c0fddaf42..8da329fc96046591d4bc86b1716e33550cbc9183 100644 (file)
@@ -8,16 +8,74 @@
 #include <rdma/ib_verbs.h>
 
 #define SDPSTATS_ON
+#undef CONFIG_INFINIBAND_SDP_DEBUG_DATA
 
-#define sdp_printk(level, sk, format, arg...)                \
+#define _sdp_printk(func, line, level, sk, format, arg...)                \
        printk(level "%s:%d sdp_sock(%d %d:%d): " format,             \
-              __func__, __LINE__, \
+              func, line, \
               current->pid, \
               (sk) ? inet_sk(sk)->num : -1,                 \
               (sk) ? ntohs(inet_sk(sk)->dport) : -1, ## arg)
+#define sdp_printk(level, sk, format, arg...)                \
+       _sdp_printk(__func__, __LINE__, level, sk, format, ## arg)
 #define sdp_warn(sk, format, arg...)                         \
        sdp_printk(KERN_WARNING, sk, format , ## arg)
 
+
+struct sk_buff;
+struct sdpprf_log {
+       int             idx;
+       int             pid;
+       int             sk_num;
+       int             sk_dport;
+       struct sk_buff  *skb;
+       char            msg[256];
+
+       unsigned long long time;
+
+       const char      *func;
+       int             line;
+};
+
+#define SDPPRF_LOG_SIZE 0x10000 /* must be a power of 2 */
+
+extern struct sdpprf_log sdpprf_log[SDPPRF_LOG_SIZE];
+extern int sdpprf_log_count;
+
+static inline unsigned long long current_nsec(void)
+{
+       struct timespec tv;
+       getnstimeofday(&tv);
+       return tv.tv_sec * NSEC_PER_SEC + tv.tv_nsec;
+}
+#if 1
+#define sdp_prf(sk, s, format, arg...) ({ \
+       struct sdpprf_log *l = &sdpprf_log[sdpprf_log_count++ & (SDPPRF_LOG_SIZE - 1)]; \
+       l->idx = sdpprf_log_count - 1; \
+       l->pid = current->pid; \
+       l->sk_num = (sk) ? inet_sk(sk)->num : -1;                 \
+       l->sk_dport = (sk) ? ntohs(inet_sk(sk)->dport) : -1; \
+       l->skb = s; \
+       snprintf(l->msg, sizeof(l->msg) - 1, format, ## arg); \
+       l->time = current_nsec(); \
+       l->func = __func__; \
+       l->line = __LINE__; \
+       1; \
+})
+#else
+#define sdp_prf(sk, s, format, arg...)
+#endif
+
+#if 0
+#if 1
+#define sdp_prf_rx(sk, s, format, arg...) sdp_prf(sk, s, format, ## arg)
+#define sdp_prf_tx(sk, s, format, arg...)
+#else
+#define sdp_prf_rx(sk, s, format, arg...)
+#define sdp_prf_tx(sk, s, format, arg...) sdp_prf(sk, s, format, ## arg)
+#endif
+#endif
+
 #ifdef CONFIG_INFINIBAND_SDP_DEBUG
 extern int sdp_debug_level;
 
@@ -364,21 +422,6 @@ extern struct workqueue_struct *rx_comp_wq;
 extern atomic_t sdp_current_mem_usage;
 extern spinlock_t sdp_large_sockets_lock;
 
-/* just like TCP fs */
-struct sdp_seq_afinfo {
-       struct module           *owner;
-       char                    *name;
-       sa_family_t             family;
-       int                     (*seq_show) (struct seq_file *m, void *v);
-       struct file_operations  *seq_fops;
-};
-
-struct sdp_iter_state {
-       sa_family_t             family;
-       int                     num;
-       struct seq_operations   seq_ops;
-};
-
 static inline struct sdp_sock *sdp_sk(const struct sock *sk)
 {
                return (struct sdp_sock *)sk;
@@ -439,6 +482,7 @@ static inline void sdp_set_error(struct sock *sk, int err)
        int ib_teardown_states = TCPF_FIN_WAIT1 | TCPF_CLOSE_WAIT
                | TCPF_LAST_ACK;
        sk->sk_err = -err;
+       dump_stack();
        if (sk->sk_socket)
                sk->sk_socket->state = SS_DISCONNECTING;
 
@@ -458,7 +502,9 @@ static inline void sdp_arm_rx_cq(struct sock *sk)
 }
 
 #ifdef CONFIG_INFINIBAND_SDP_DEBUG_DATA
-void dump_packet(struct sock *sk, char *str, struct sk_buff *skb, const struct sdp_bsdh *h);
+void _dump_packet(const char *func, int line, struct sock *sk, char *str,
+               struct sk_buff *skb, const struct sdp_bsdh *h);
+#define dump_packet(sk, str, skb, h) _dump_packet(__func__, __LINE__, sk, str, skb, h)
 #endif
 int sdp_cma_handler(struct rdma_cm_id *, struct rdma_cm_event *);
 void sdp_reset(struct sock *sk);
@@ -466,13 +512,15 @@ void sdp_reset_sk(struct sock *sk, int rc);
 void sdp_rx_irq(struct ib_cq *cq, void *cq_context);
 void sdp_tx_irq(struct ib_cq *cq, void *cq_context);
 void sdp_poll_tx_cq(unsigned long data);
+void _sdp_poll_tx_cq(unsigned long data);
 void sdp_rx_comp_work(struct work_struct *work);
 void sdp_process_tx_wc_work(struct work_struct *work);
 int sdp_post_credits(struct sdp_sock *ssk);
 void sdp_post_send(struct sdp_sock *ssk, struct sk_buff *skb, u8 mid);
 void sdp_post_recvs(struct sdp_sock *ssk);
 int sdp_poll_rx_cq(struct sdp_sock *ssk);
-void sdp_post_sends(struct sdp_sock *ssk, int nonagle);
+void _sdp_post_sends(const char *func, int line, struct sdp_sock *ssk, int nonagle);
+#define sdp_post_sends(ssk, nonagle) _sdp_post_sends(__func__, __LINE__, ssk, nonagle)
 void sdp_destroy_work(struct work_struct *work);
 void sdp_cancel_dreq_wait_timeout(struct sdp_sock *ssk);
 void sdp_dreq_wait_timeout_work(struct work_struct *work);
index 29c9761ec96b198ffda2d9e0ef7c38a692ce6352..6d432378aeb4dd13cb1bb7215196f4cfd6a4ff48 100644 (file)
@@ -187,7 +187,8 @@ void sdp_post_keepalive(struct sdp_sock *ssk)
 }
 
 #ifdef CONFIG_INFINIBAND_SDP_DEBUG_DATA
-void dump_packet(struct sock *sk, char *str, struct sk_buff *skb, const struct sdp_bsdh *h)
+void _dump_packet(const char *func, int line, struct sock *sk, char *str,
+               struct sk_buff *skb, const struct sdp_bsdh *h)
 {
        int len = 0;
        char buf[256];
@@ -240,7 +241,7 @@ void dump_packet(struct sock *sk, char *str, struct sk_buff *skb, const struct s
                        break;
        }
        buf[len] = 0;
-       sdp_warn(sk, "%s: %s\n", str, buf);
+       _sdp_printk(func, line, KERN_WARNING, sk, "%s: %s\n", str, buf);
 }
 #endif
 
@@ -249,6 +250,7 @@ static int sdp_process_tx_cq(struct sdp_sock *ssk);
 int sdp_xmit_poll(struct sdp_sock *ssk, int force)
 {
        int wc_processed = 0;
+//     sdp_prf(&ssk->isk.sk, NULL, "xmit_poll force = %d", force);
 
        /* If we don't have a pending timer, set one up to catch our recent
           post in case the interface becomes idle */
@@ -273,6 +275,18 @@ void sdp_post_send(struct sdp_sock *ssk, struct sk_buff *skb, u8 mid)
        struct ib_sge *sge;
        struct ib_send_wr *bad_wr;
 
+#define ENUM2STR(e) [e] = #e
+       static char *mid2str[] = {
+               ENUM2STR(SDP_MID_HELLO),
+               ENUM2STR(SDP_MID_HELLO_ACK),
+               ENUM2STR(SDP_MID_DISCONN),
+               ENUM2STR(SDP_MID_CHRCVBUF),
+               ENUM2STR(SDP_MID_CHRCVBUF_ACK),
+               ENUM2STR(SDP_MID_DATA),
+       };
+       sdp_prf(&ssk->isk.sk, skb, "post_send mid = %s, bufs = %d",
+                       mid2str[mid], ssk->rx_head - ssk->rx_tail);
+
        SDPSTATS_COUNTER_MID_INC(post_send, mid);
        SDPSTATS_HIST(send_size, skb->len);
 
@@ -343,6 +357,10 @@ void sdp_post_send(struct sdp_sock *ssk, struct sk_buff *skb, u8 mid)
                sdp_set_error(&ssk->isk.sk, -ECONNRESET);
                wake_up(&ssk->wq);
        }
+
+       if (ssk->tx_ring.credits <= SDP_MIN_TX_CREDITS) {
+               sdp_poll_rx_cq(ssk);
+       }
 }
 
 struct sk_buff *sdp_send_completion(struct sdp_sock *ssk, int mseq)
@@ -466,6 +484,7 @@ static void sdp_post_recv(struct sdp_sock *ssk)
        ssk->rx_wr.sg_list = ssk->ibsge;
        ssk->rx_wr.num_sge = frags + 1;
        rc = ib_post_recv(ssk->qp, &ssk->rx_wr, &bad_wr);
+       sdp_prf(&ssk->isk.sk, skb, "rx skb was posted");
        SDPSTATS_COUNTER_INC(post_recv);
        ++ssk->rx_head;
        if (unlikely(rc)) {
@@ -582,6 +601,26 @@ static inline int sdp_nagle_off(struct sdp_sock *ssk, struct sk_buff *skb)
 
 int sdp_post_credits(struct sdp_sock *ssk)
 {
+       int post_count = 0;
+       struct sk_buff *skb;
+
+       sdp_dbg_data(&ssk->isk.sk, "credits: %d remote credits: %d "
+                       "tx ring slots left: %d send_head: %p\n",
+               ssk->tx_ring.credits, ssk->remote_credits,
+               sdp_tx_ring_slots_left(&ssk->tx_ring),
+               ssk->isk.sk.sk_send_head);
+
+       if (ssk->tx_ring.credits > SDP_MIN_TX_CREDITS &&
+              sdp_tx_ring_slots_left(&ssk->tx_ring) &&
+              (skb = ssk->isk.sk.sk_send_head) &&
+               sdp_nagle_off(ssk, skb)) {
+               update_send_head(&ssk->isk.sk, skb);
+               __skb_dequeue(&ssk->isk.sk.sk_write_queue);
+               sdp_post_send(ssk, skb, SDP_MID_DATA);
+               post_count++;
+               goto out;
+       }
+
        if (likely(ssk->tx_ring.credits > 1) &&
            likely(sdp_tx_ring_slots_left(&ssk->tx_ring))) {
                struct sk_buff *skb;
@@ -591,12 +630,16 @@ int sdp_post_credits(struct sdp_sock *ssk)
                if (!skb)
                        return -ENOMEM;
                sdp_post_send(ssk, skb, SDP_MID_DATA);
-               sdp_xmit_poll(ssk, 0);
+               post_count++;
        }
-       return 0;
+
+out:
+       if (post_count)
+               sdp_xmit_poll(ssk, 0);
+       return post_count;
 }
 
-void sdp_post_sends(struct sdp_sock *ssk, int nonagle)
+void _sdp_post_sends(const char *func, int line, struct sdp_sock *ssk, int nonagle)
 {
        /* TODO: nonagle? */
        struct sk_buff *skb;
@@ -604,6 +647,8 @@ void sdp_post_sends(struct sdp_sock *ssk, int nonagle)
        gfp_t gfp_page;
        int post_count = 0;
 
+       sdp_dbg_data(&ssk->isk.sk, "called from %s:%d\n", func, line);
+
        if (unlikely(!ssk->id)) {
                if (ssk->isk.sk.sk_send_head) {
                        sdp_dbg(&ssk->isk.sk,
@@ -619,6 +664,15 @@ void sdp_post_sends(struct sdp_sock *ssk, int nonagle)
        else
                gfp_page = GFP_KERNEL;
 
+       sdp_dbg_data(&ssk->isk.sk, "credits: %d tx ring slots left: %d send_head: %p\n",
+               ssk->tx_ring.credits, sdp_tx_ring_slots_left(&ssk->tx_ring),
+               ssk->isk.sk.sk_send_head);
+
+       if (sdp_tx_ring_slots_left(&ssk->tx_ring) < SDP_TX_SIZE / 2) {
+               int wc_processed = sdp_xmit_poll(ssk,  1);
+               sdp_dbg_data(&ssk->isk.sk, "freed %d\n", wc_processed);
+       }
+
        if (ssk->recv_request &&
            ssk->rx_tail >= ssk->recv_request_head &&
            ssk->tx_ring.credits >= SDP_MIN_TX_CREDITS &&
@@ -642,12 +696,9 @@ void sdp_post_sends(struct sdp_sock *ssk, int nonagle)
               (skb = ssk->isk.sk.sk_send_head) &&
                sdp_nagle_off(ssk, skb)) {
                SDPSTATS_COUNTER_INC(send_miss_no_credits);
+               sdp_prf(&ssk->isk.sk, skb, "no credits. called from %s:%d", func, line);
        }
 
-       sdp_dbg_data(&ssk->isk.sk, "credits: %d tx ring slots left: %d send_head: %p\n",
-               ssk->tx_ring.credits, sdp_tx_ring_slots_left(&ssk->tx_ring),
-               ssk->isk.sk.sk_send_head);
-
        while (ssk->tx_ring.credits > SDP_MIN_TX_CREDITS &&
               sdp_tx_ring_slots_left(&ssk->tx_ring) &&
               (skb = ssk->isk.sk.sk_send_head) &&
@@ -658,7 +709,7 @@ void sdp_post_sends(struct sdp_sock *ssk, int nonagle)
                post_count++;
        }
 
-       if (ssk->tx_ring.credits == SDP_MIN_TX_CREDITS &&
+       if (0 && ssk->tx_ring.credits == SDP_MIN_TX_CREDITS &&
            !ssk->sent_request &&
            ssk->tx_ring.head > ssk->sent_request_head + SDP_RESIZE_WAIT &&
            sdp_tx_ring_slots_left(&ssk->tx_ring)) {
@@ -713,8 +764,11 @@ void sdp_post_sends(struct sdp_sock *ssk, int nonagle)
                sdp_post_send(ssk, skb, SDP_MID_DISCONN);
                post_count++;
        }
-       if (post_count)
+       if (post_count) {
                sdp_xmit_poll(ssk, 0);
+
+               sdp_prf(&ssk->isk.sk, NULL, "finshed polling from post_sends");
+       }
 }
 
 int sdp_init_buffers(struct sdp_sock *ssk, u32 new_size)
@@ -787,6 +841,8 @@ static int sdp_handle_recv_comp(struct sdp_sock *ssk, struct ib_wc *wc)
        if (unlikely(!skb))
                return -1;
 
+       sdp_prf(sk, skb, "recv completion");    
+
        atomic_sub(SDP_MAX_SEND_SKB_FRAGS, &sdp_current_mem_usage);
 
        if (unlikely(wc->status)) {
@@ -911,6 +967,7 @@ static int sdp_handle_send_comp(struct sdp_sock *ssk, struct ib_wc *wc)
                }
        }
 
+       sdp_prf(&ssk->isk.sk, skb, "tx completion");
        sk_stream_free_skb(&ssk->isk.sk, skb);
 
        return 0;
@@ -928,6 +985,9 @@ void sdp_rx_irq(struct ib_cq *cq, void *cq_context)
 
        SDPSTATS_COUNTER_INC(rx_int_count);
 
+       sdp_prf(sk, NULL, "rx completion");
+
+       /* issue sdp_rx_comp_work() */
        queue_work(rx_comp_wq, &ssk->rx_comp_work);
 }
 
@@ -995,6 +1055,7 @@ void sdp_poll_tx_cq(unsigned long data)
        struct sock *sk = &ssk->isk.sk;
        u32 inflight, wc_processed;
 
+
        sdp_dbg_data(&ssk->isk.sk, "Polling tx cq. inflight=%d\n",
                (u32) ssk->tx_ring.head - ssk->tx_ring.tail);
 
@@ -1029,6 +1090,16 @@ out:
        bh_unlock_sock(sk);
 }
 
+void _sdp_poll_tx_cq(unsigned long data)
+{
+       struct sdp_sock *ssk = (struct sdp_sock *)data;
+       struct sock *sk = &ssk->isk.sk;
+
+       sdp_prf(sk, NULL, "sdp poll tx timeout expired");
+
+       sdp_poll_tx_cq(data);
+}
+
 
 void sdp_tx_irq(struct ib_cq *cq, void *cq_context)
 {
@@ -1040,6 +1111,25 @@ void sdp_tx_irq(struct ib_cq *cq, void *cq_context)
        mod_timer(&ssk->tx_ring.timer, jiffies + 1);
 }
 
+static inline int credit_update_needed(struct sdp_sock *ssk, int wc_processed)
+{
+       int c;
+
+       c = ssk->remote_credits;
+       if (likely(c > SDP_MIN_TX_CREDITS))
+               c += c/2;
+
+/*     sdp_warn(&ssk->isk.sk, "credits: %d remote credits: %d "
+                       "tx ring slots left: %d send_head: %p\n",
+               ssk->tx_ring.credits, ssk->remote_credits,
+               sdp_tx_ring_slots_left(&ssk->tx_ring),
+               ssk->isk.sk.sk_send_head);
+*/
+       return (unlikely(c < ssk->rx_head - ssk->rx_tail + wc_processed) &&
+           likely(ssk->tx_ring.credits > 1) &&
+           likely(sdp_tx_ring_slots_left(&ssk->tx_ring)));
+}
+
 
 int sdp_poll_rx_cq(struct sdp_sock *ssk)
 {
@@ -1048,6 +1138,7 @@ int sdp_poll_rx_cq(struct sdp_sock *ssk)
        int n, i;
        int ret = -EAGAIN;
        int updated_credits = 0;
+       int wc_processed = 0;
 
        do {
                n = ib_poll_cq(cq, SDP_NUM_WC, ibwc);
@@ -1056,11 +1147,22 @@ int sdp_poll_rx_cq(struct sdp_sock *ssk)
 
                        BUG_ON(!(wc->wr_id & SDP_OP_RECV));
                        sdp_handle_recv_comp(ssk, wc);
+                       wc_processed++;
 
-                       if (!updated_credits) {
+/*                     if (!updated_credits) {
                                sdp_post_recvs(ssk);
                                sdp_post_sends(ssk, 0);
                                updated_credits = 1;
+                       }*/
+//sdp_warn(&ssk->isk.sk, "i = %d, wc_processed = %d wr_id = 0x%llx\n", i, wc_processed, wc->wr_id);
+                       if (credit_update_needed(ssk, wc_processed)) {
+                               sdp_prf(&ssk->isk.sk, NULL, "credit update. remote_credits: %d, avail now: %d processed: %d",
+                                               ssk->remote_credits,
+                                               ssk->rx_head - ssk->rx_tail,
+                                               wc_processed);
+                               sdp_post_recvs(ssk);
+                               if (sdp_post_credits(ssk))
+                                       wc_processed = 0;
                        }
 
                        ret = 0;
index 7c34637fd9a266898bdb12c530809a8234c84fc1..e0d0b20e8c31fcffd703fa1092b1eaa9ba2c059b 100644 (file)
@@ -149,7 +149,7 @@ static int sdp_init_qp(struct sock *sk, struct rdma_cm_id *id)
        }
 
        init_timer(&sdp_sk(sk)->tx_ring.timer);
-       sdp_sk(sk)->tx_ring.timer.function = sdp_poll_tx_cq;
+       sdp_sk(sk)->tx_ring.timer.function = _sdp_poll_tx_cq;
        sdp_sk(sk)->tx_ring.timer.data = (unsigned long) sdp_sk(sk);
        sdp_sk(sk)->tx_ring.poll_cnt = 0;
 
@@ -477,7 +477,7 @@ int sdp_cma_handler(struct rdma_cm_id *id, struct rdma_cm_event *event)
                        rc = rdma_accept(id, NULL);
 
                if (!rc)
-                       rc = sdp_post_credits(sdp_sk(sk));
+                       rc = sdp_post_credits(sdp_sk(sk)) < 0 ?: 0;
                break;
        case RDMA_CM_EVENT_CONNECT_ERROR:
                sdp_dbg(sk, "RDMA_CM_EVENT_CONNECT_ERROR\n");
index 454abeb2872ab49bd9ed0ed40b20ac8992c80cc0..8cd739a05f37cd8ee5a04911c81b8e0a9dcf3c8b 100644 (file)
@@ -1748,6 +1748,8 @@ new_segment:
                                if (!skb)
                                        goto wait_for_memory;
 
+                               sdp_prf(sk, skb, "Created");
+
                                BZCOPY_STATE(skb) = bz;
 
                                /*
@@ -1762,6 +1764,7 @@ new_segment:
                                skb_entail(sk, ssk, skb);
                                copy = size_goal;
                        } else {
+                               sdp_prf(sk, skb, "adding %d bytes", copy);
                                sdp_dbg_data(sk, "adding to existing skb: %p"
                                        " len = %d, sk_send_head: %p copy: %d\n",
                                        skb, skb->len, sk->sk_send_head, copy);
@@ -1780,8 +1783,10 @@ new_segment:
                                goto new_segment;
                        }
 
+//                     sdp_prf(sk, skb, "before memcpy %d bytes", copy);
                        copy = (bz) ? sdp_bzcopy_get(sk, skb, from, copy, bz) :
                                      sdp_bcopy_get(sk, skb, from, copy);
+//                     sdp_prf(sk, skb, "after memcpy. result: %d", copy);
                        if (unlikely(copy < 0)) {
                                if (!++copy)
                                        goto wait_for_memory;
@@ -1818,6 +1823,7 @@ new_segment:
 wait_for_sndbuf:
                        set_bit(SOCK_NOSPACE, &sk->sk_socket->flags);
 wait_for_memory:
+                       sdp_prf(sk, skb, "wait for mem");
                        SDPSTATS_COUNTER_INC(send_wait_for_mem);
                        if (copied)
                                sdp_push(sk, ssk, flags & ~MSG_MORE, PAGE_SIZE, TCP_NAGLE_PUSH);
@@ -1826,6 +1832,7 @@ wait_for_memory:
 
                        err = (bz) ? sdp_bzcopy_wait_memory(ssk, &timeo, bz) :
                                     sk_stream_wait_memory(sk, &timeo);
+                       sdp_prf(sk, skb, "finished wait for mem. err: %d", err);
                        if (err)
                                goto do_error;
 
@@ -1849,6 +1856,8 @@ out:
        return copied;
 
 do_fault:
+       sdp_prf(sk, skb, "prepare fault");
+
        if (!skb->len) {
                if (sk->sk_send_head == skb)
                        sk->sk_send_head = NULL;
@@ -1888,6 +1897,8 @@ static int sdp_recvmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
        lock_sock(sk);
        sdp_dbg_data(sk, "%s\n", __func__);
 
+       sdp_prf(sk, skb, "Read from user");
+
        err = -ENOTCONN;
        if (sk->sk_state == TCP_LISTEN)
                goto out;
@@ -2026,6 +2037,7 @@ static int sdp_recvmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
                        err = skb_copy_datagram_iovec(skb, offset,
                                                      /* TODO: skip header? */
                                                      msg->msg_iov, used);
+                       sdp_prf(sk, skb, "Copied to user %ld bytes. err = %d", used, err);
                        if (err) {
                                sdp_dbg(sk, "%s: skb_copy_datagram_iovec failed"
                                        "offset %d size %ld status %d\n",
index 0971a49ebc9abf98502fc51fe32ff7efded177c8..3778c9a971af9c2e5a5093778a3cb43f0e7f9c29 100644 (file)
 #ifdef CONFIG_PROC_FS
 
 #define PROC_SDP_STATS "sdpstats"
+#define PROC_SDP_PERF "sdpprf"
+
+struct sdpprf_log sdpprf_log[SDPPRF_LOG_SIZE];
+int sdpprf_log_count = 0;
+
+/* just like TCP fs */
+struct sdp_seq_afinfo {
+       struct module           *owner;
+       char                    *name;
+       sa_family_t             family;
+       int                     (*seq_show) (struct seq_file *m, void *v);
+       struct file_operations  *seq_fops;
+};
+
+struct sdp_iter_state {
+       sa_family_t             family;
+       int                     num;
+       struct seq_operations   seq_ops;
+};
+
+//struct sdpprf sdpprf = { { 0 } };
+
 
 static void *sdp_get_idx(struct seq_file *seq, loff_t pos)
 {
@@ -277,10 +299,6 @@ static ssize_t sdpstats_write(struct file *file, const char __user *buf,
        return count;
 }
 
-static const struct seq_operations sdpstats_seq_ops = {
-       .show   = sdpstats_seq_show,
-};
-
 static int sdpstats_seq_open(struct inode *inode, struct file *file)
 {
        return single_open(file, sdpstats_seq_show, NULL);
@@ -297,10 +315,113 @@ static struct file_operations sdpstats_fops = {
 
 #endif
 
+unsigned long long start_t = 0;
+
+static int sdpprf_show(struct seq_file *m, void *v)
+{
+       struct sdpprf_log *l = v;
+       char ts[TIMESTAMP_SIZE];
+
+       if (!sdpprf_log_count) {
+               seq_printf(m, "No performance logs\n");
+               goto out;
+       }
+
+       nsec_to_timestamp(ts, l->time - start_t);
+
+       seq_printf(m, "%-6d: %s %-50s - [%d %d:%d] skb: %p %s:%d\n",
+                       l->idx, ts,
+                       l->msg, l->pid, l->sk_num, l->sk_dport,
+                       l->skb, l->func, l->line);
+out:
+        return 0;
+}
+
+static void *sdpprf_start(struct seq_file *p, loff_t *pos)
+{
+       int idx = *pos;
+
+       if (!*pos) {
+               if (!sdpprf_log_count)
+                       return SEQ_START_TOKEN;
+       }
+       
+       if (*pos >= MIN(sdpprf_log_count, SDPPRF_LOG_SIZE - 1))
+               return NULL;
+
+       if (sdpprf_log_count >= SDPPRF_LOG_SIZE - 1) {
+               int off = sdpprf_log_count & ( SDPPRF_LOG_SIZE - 1);
+               idx = (idx + off) & (SDPPRF_LOG_SIZE - 1);
+
+       }
+
+       if (!start_t)
+               start_t = sdpprf_log[idx].time;
+       return &sdpprf_log[idx];
+}
+
+static void *sdpprf_next(struct seq_file *p, void *v, loff_t *pos)
+{
+       struct sdpprf_log *l = v;
+
+       if (++*pos >= MIN(sdpprf_log_count, SDPPRF_LOG_SIZE - 1))
+               return NULL;
+
+       ++l;
+       if (l - &sdpprf_log[0] >= SDPPRF_LOG_SIZE - 1)
+               return &sdpprf_log[0];
+
+        return l;
+}
+
+static void sdpprf_stop(struct seq_file *p, void *v)
+{
+}
+
+
+struct seq_operations sdpprf_ops = {
+       .start = sdpprf_start,
+       .stop = sdpprf_stop,
+       .next = sdpprf_next,
+       .show = sdpprf_show,
+};
+
+static int sdpprf_open(struct inode *inode, struct file *file)
+{
+       int res;
+
+       res = seq_open(file, &sdpprf_ops);
+
+       if (sdpprf_log_count >= SDPPRF_LOG_SIZE - 1) {
+               printk("ATTENTION: performance log was wrapped around! count = %d\n",
+                               sdpprf_log_count);
+       }
+
+       return res;
+}
+
+static ssize_t sdpprf_write(struct file *file, const char __user *buf,
+                           size_t count, loff_t *offs)
+{
+       sdpprf_log_count = 0;
+       printk("Cleared sdpprf statistics\n");
+
+       return count;
+}
+
+static struct file_operations sdpprf_fops = {
+        .open           = sdpprf_open,
+        .read           = seq_read,
+        .llseek         = seq_lseek,
+        .release        = seq_release,
+       .write          = sdpprf_write,
+};
+
 int __init sdp_proc_init(void)
 {
        struct proc_dir_entry *p = NULL;
        struct proc_dir_entry *sdpstats = NULL;
+       struct proc_dir_entry *sdpprf = NULL;
 
        sdp_seq_afinfo.seq_fops->owner         = sdp_seq_afinfo.owner;
        sdp_seq_afinfo.seq_fops->open          = sdp_seq_open;
@@ -322,10 +443,18 @@ int __init sdp_proc_init(void)
        if (!sdpstats)
                goto no_mem;;
 
-       return 0;
 #endif
 
+       sdpprf = proc_net_fops_create(PROC_SDP_PERF,
+                       S_IRUGO | S_IWUGO, &sdpprf_fops); 
+       if (!sdpprf)
+               goto no_mem;
+
+       return 0;
 no_mem:
+       if (sdpprf)
+               proc_net_remove(PROC_SDP_PERF);
+
        if (sdpstats)
                proc_net_remove(PROC_SDP_STATS);
 
@@ -343,6 +472,7 @@ void sdp_proc_unregister(void)
 #ifdef SDPSTATS_ON
        proc_net_remove(PROC_SDP_STATS);
 #endif
+       proc_net_remove(PROC_SDP_PERF);
 }
 
 #else /* CONFIG_PROC_FS */