From: Amir Vadai Date: Sun, 26 Apr 2009 07:55:26 +0000 (+0300) Subject: sdp: /proc/net/sdpprf - performance utilities X-Git-Tag: v4.1.12-92~264^2~5^2~284 X-Git-Url: https://www.infradead.org/git/?a=commitdiff_plain;h=d7f508b2ff5f42e9c95038a38c3451c02a21921b;p=users%2Fjedix%2Flinux-maple.git sdp: /proc/net/sdpprf - performance utilities Signed-off-by: Amir Vadai --- diff --git a/drivers/infiniband/ulp/sdp/perf.pl b/drivers/infiniband/ulp/sdp/perf.pl new file mode 100755 index 0000000000000..58204d3ac6a24 --- /dev/null +++ b/drivers/infiniband/ulp/sdp/perf.pl @@ -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, ") { + 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; diff --git a/drivers/infiniband/ulp/sdp/sdp.h b/drivers/infiniband/ulp/sdp/sdp.h index 81280655d3acd..8da329fc96046 100644 --- a/drivers/infiniband/ulp/sdp/sdp.h +++ b/drivers/infiniband/ulp/sdp/sdp.h @@ -8,16 +8,74 @@ #include #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); diff --git a/drivers/infiniband/ulp/sdp/sdp_bcopy.c b/drivers/infiniband/ulp/sdp/sdp_bcopy.c index 29c9761ec96b1..6d432378aeb4d 100644 --- a/drivers/infiniband/ulp/sdp/sdp_bcopy.c +++ b/drivers/infiniband/ulp/sdp/sdp_bcopy.c @@ -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; diff --git a/drivers/infiniband/ulp/sdp/sdp_cma.c b/drivers/infiniband/ulp/sdp/sdp_cma.c index 7c34637fd9a26..e0d0b20e8c31f 100644 --- a/drivers/infiniband/ulp/sdp/sdp_cma.c +++ b/drivers/infiniband/ulp/sdp/sdp_cma.c @@ -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"); diff --git a/drivers/infiniband/ulp/sdp/sdp_main.c b/drivers/infiniband/ulp/sdp/sdp_main.c index 454abeb2872ab..8cd739a05f37c 100644 --- a/drivers/infiniband/ulp/sdp/sdp_main.c +++ b/drivers/infiniband/ulp/sdp/sdp_main.c @@ -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", diff --git a/drivers/infiniband/ulp/sdp/sdp_proc.c b/drivers/infiniband/ulp/sdp/sdp_proc.c index 0971a49ebc9ab..3778c9a971af9 100644 --- a/drivers/infiniband/ulp/sdp/sdp_proc.c +++ b/drivers/infiniband/ulp/sdp/sdp_proc.c @@ -37,6 +37,28 @@ #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 */