mpxyd: add new M_READ_FROM_DONE state for send WR's and add more profiling options

new state added to work request flag along with a m_qp->wr_tl_rf field
to limit wr pending thread processing to just RF pending entries
and avoiding needless processing of M_SEND_POSTED entries.

Add more perf profiling capabilities to defer IB RDMA until after all the post_send
scif_readfrom's, first to last segment, are complete.

disable MCM_PROFILE_DBG compile option by default

Signed-off-by: Arlin Davis <arlin.r.davis@intel.com>

diff --git a/dapl/svc/mpxyd.h b/dapl/svc/mpxyd.h
index 832ab9d8d38faf4f1d78aa61652148c73cddd630..ca66e995447e32e3d510239bbea8ac82bd8362c8 100644 (file)
--- a/dapl/svc/mpxyd.h
+++ b/dapl/svc/mpxyd.h
@@ -70,7 +70,7 @@
 #define MIX_MAX_MSG_SIZE       (8*1024*1024)
 
 #define MCM_PROFILE 1
-#define MCM_PROFILE_DBG 1
+#define MCM_PROFILE_DBG 0
 
 /* locking */
 
@@ -192,6 +192,8 @@ enum mcm_wr_flags {
        M_READ_WRITE_TO_DONE    = 1 << 13, /* m_wr_rx read data forwarded to MIC scif_writeto */
        M_READ_CN_SIG           = 1 << 14, /* m_wr_rx consumer signaled, IB completion needed */
        M_READ_MP_SIG           = 1 << 15, /* m_wr_rx mpxyd signaled, segmentation, manage proxy buf/wr resources */
+
+       M_READ_FROM_DONE        = 1 << 16, /* m_wr mpxyd read_from_done, ready for posting */
 };
 
 /*
@@ -275,37 +277,23 @@ enum mcm_prof_type
        MCM_QP_ALL
 };
 
+typedef struct mcm_qp_prof_val {
+       uint32_t        min;
+       uint32_t        max;
+       uint32_t        avg;
+       uint32_t        all;
+       uint32_t        cnt;
+       uint32_t        start;
+       uint32_t        stop;
+} mcm_qp_prof_val_t;
+
 typedef struct mcm_qp_prof {
-       uint32_t                wt_min;         /* scif_writeto  */
-       uint32_t                wt_max;
-       uint32_t                wt_avg;
-       uint32_t                wt_all;
-       uint32_t                wt_cnt;
-       uint32_t                rf_min;         /* scif_readfrom  */
-       uint32_t                rf_max;
-       uint32_t                rf_avg;
-       uint32_t                rf_all;
-       uint32_t                rf_cnt;
-       uint32_t                rw_min;         /* IB write */
-       uint32_t                rw_max;
-       uint32_t                rw_avg;
-       uint32_t                rw_all;
-       uint32_t                rw_cnt;
-       uint32_t                rr_min;         /* IB read */
-       uint32_t                rr_max;
-       uint32_t                rr_avg;
-       uint32_t                rr_all;
-       uint32_t                rr_cnt;
-       uint32_t                pi_min;         /* IO proxy-in: FirstSeg to LastSeg */
-       uint32_t                pi_max;
-       uint32_t                pi_avg;
-       uint32_t                pi_all;
-       uint32_t                pi_cnt;
-       uint32_t                po_min;         /* IO proxy-out: FirstSeg to LastSeg */
-       uint32_t                po_max;
-       uint32_t                po_avg;
-       uint32_t                po_all;
-       uint32_t                po_cnt;
+       mcm_qp_prof_val_t       wt; /* scif_writeto  */
+       mcm_qp_prof_val_t       rf; /* scif_readfrom  */
+       mcm_qp_prof_val_t       rw; /* IB write */
+       mcm_qp_prof_val_t       rr; /* IB read */
+       mcm_qp_prof_val_t       pi; /* IO proxy-in: FirstSeg to LastSeg */
+       mcm_qp_prof_val_t       po; /* IO proxy-out: FirstSeg to LastSeg */
 } mcm_qp_prof_t;
 
 /*  DAPL MCM QP object, id in entry */
@@ -327,6 +315,7 @@ typedef struct mcm_qp {
        off_t                   wr_off;         /* SCIF registered, for scif_fence_signal @ wr->wr_id */
        int                     wr_hd;          /* work request pool head  */
        int                     wr_tl;          /* work request pool tail  */
+       int                     wr_tl_rf;       /* work requets pool RF tail */
        int                     wr_end;         /* work request pool end  */
        int                     wr_len;         /* work request pool size */
        int                     wr_pp;          /* work request pending */
@@ -380,6 +369,8 @@ typedef struct mcm_qp {
        int                     post_sr;
 #ifdef MCM_PROFILE
        mcm_qp_prof_t           ts;
+       uint32_t                last_wr_sig;
+       uint32_t                last_wr_pst;
 #endif
 #if MCM_PROFILE_DBG
        int                     wt_err;
@@ -693,7 +684,7 @@ void mpxy_write(int level, const char *format, ...);
 void mpxy_pr_addrs(int lvl, struct dat_mcm_msg *msg, int state, int in);
 #ifdef MCM_PROFILE
 void mcm_qp_prof_pr(struct mcm_qp *m_qp, int type);
-void mcm_qp_prof_ts(struct mcm_qp *m_qp, int type, uint32_t start, int qcnt, int ccnt);
+void mcm_qp_prof_ts(struct mcm_qp *m_qp, int type, uint32_t start, uint32_t qcnt, uint32_t ccnt);
 #endif
 
 struct mcm_fd_set *mcm_alloc_fd_set(void);
@@ -824,7 +815,7 @@ static inline uint32_t mcm_ts_us(void)
         struct timeval curtime;
         timerclear(&curtime);
         gettimeofday(&curtime, NULL);
-        return (uint32_t) curtime.tv_usec;
+        return (uint32_t) (((curtime.tv_sec & 0xff) * 1000000) + curtime.tv_usec);
 }
 
 static inline uint64_t mcm_time_us(void)

diff --git a/dapl/svc/util.c b/dapl/svc/util.c
index b67e0da5b984398e598de6f99ad3badc033e1581..ac6b163e39150d80f61e5c89845820de12fc270d 100644 (file)
--- a/dapl/svc/util.c
+++ b/dapl/svc/util.c
@@ -194,15 +194,15 @@ static char *mcm_cntr_names[] = {
 void mpxy_write(int level, const char *format, ...)
 {
        va_list args;
-       struct timeval tv;
+       uint32_t ts;
 
        if (level && !(level & log_level))
                return;
 
-       gettimeofday(&tv, NULL);
+       ts = mcm_ts_us();
        va_start(args, format);
        mpxy_lock(&flock);
-       fprintf(logfile, " %x:%03u.%03u: ", (unsigned)pthread_self(),(unsigned) tv.tv_sec, (unsigned) (tv.tv_usec));
+       fprintf(logfile, " %x:%u: ", (unsigned)pthread_self(), ts);
        vfprintf(logfile, format, args);
        fflush(logfile);
        mpxy_unlock(&flock);
@@ -513,117 +513,148 @@ int rd_dev_file(char *path, char *file, char *v_str, int len)
 #ifdef MCM_PROFILE
 void mcm_qp_prof_pr(struct mcm_qp *m_qp, int type)
 {
-       if ((m_qp->ts.wt_min) &&
+       if ((m_qp->ts.wt.min) &&
            (type == MCM_QP_WT || type == MCM_QP_ALL))
-               mlog(0, " QP (%p) PERF scif_writeto() times (usecs):"
-                       " max %u min %u avg %u ttime %u io_cnt %u\n",
-                       m_qp, m_qp->ts.wt_max, m_qp->ts.wt_min,
-                       m_qp->ts.wt_avg, m_qp->ts.wt_all, m_qp->ts.wt_cnt);
-
-       if ((m_qp->ts.rf_min) &&
+               mlog(0, " QP (%p) PERF scif_WT() times (usecs):"
+                       " max %u min %u avg %u ttime %u cnt %u - et %u avg %u\n",
+                       m_qp, m_qp->ts.wt.max, m_qp->ts.wt.min,
+                       m_qp->ts.wt.avg, m_qp->ts.wt.all, m_qp->ts.wt.cnt,
+                       m_qp->ts.wt.stop - m_qp->ts.wt.start,
+                       (m_qp->ts.wt.stop - m_qp->ts.wt.start)/m_qp->ts.wt.cnt);
+
+       if ((m_qp->ts.rf.min) &&
            (type == MCM_QP_RF || type == MCM_QP_ALL))
-               mlog(0, " QP (%p) PERF scif_readfrom() times (usecs):"
-                       " max %u min %u avg %u ttime %u io_cnt %u\n",
-                       m_qp, m_qp->ts.rf_max, m_qp->ts.rf_min,
-                       m_qp->ts.rf_avg, m_qp->ts.rf_all, m_qp->ts.rf_cnt);
-
-       if ((m_qp->ts.rw_min) &&
+               mlog(0, " QP (%p) PERF scif_RF() times (usecs):"
+                       " max %u min %u avg %u ttime %u cnt %u - et %u avg %u\n",
+                       m_qp, m_qp->ts.rf.max, m_qp->ts.rf.min,
+                       m_qp->ts.rf.avg, m_qp->ts.rf.all, m_qp->ts.rf.cnt,
+                       m_qp->ts.rf.stop - m_qp->ts.rf.start,
+                       (m_qp->ts.rf.stop - m_qp->ts.rf.start)/m_qp->ts.rf.cnt);
+
+       if ((m_qp->ts.rw.min) &&
            (type == MCM_QP_IB_RW || type == MCM_QP_ALL))
-               mlog(0, " QP (%p) PERF ib_write() times (usecs):"
-                       " max %u min %u avg %u ttime %u io_cnt %u\n",
-                       m_qp, m_qp->ts.rw_max, m_qp->ts.rw_min,
-                       m_qp->ts.rw_avg, m_qp->ts.rw_all, m_qp->ts.rw_cnt);
-
-       if ((m_qp->ts.rr_min) &&
+               mlog(0, " QP (%p) PERF %s times (usecs):"
+                       " max %u min %u avg %u ttime %u cnt %u - et %u avg %u\n",
+                       m_qp, "ib_RW or RW_imm+RR",
+                       m_qp->ts.rw.max, m_qp->ts.rw.min,
+                       m_qp->ts.rw.avg, m_qp->ts.rw.all, m_qp->ts.rw.cnt,
+                       m_qp->ts.rw.stop - m_qp->ts.rw.start,
+                       (m_qp->ts.rw.stop - m_qp->ts.rw.start)/m_qp->ts.rw.cnt);
+
+       if ((m_qp->ts.rr.min) &&
            (type == MCM_QP_IB_RR || type == MCM_QP_ALL))
-               mlog(0, " QP (%p) PERF ib_read() times (usecs):"
-                       " max %u min %u avg %u ttime %u io_cnt %u\n",
-                       m_qp, m_qp->ts.rr_max, m_qp->ts.rr_min,
-                       m_qp->ts.rr_avg, m_qp->ts.rr_all, m_qp->ts.rr_cnt);
-
-       if ((m_qp->ts.pi_min) &&
+               mlog(0, " QP (%p) PERF ib_RR() times (usecs):"
+                       " max %u min %u avg %u ttime %u cnt %u - et %u avg %u\n",
+                       m_qp, m_qp->ts.rr.max, m_qp->ts.rr.min,
+                       m_qp->ts.rr.avg, m_qp->ts.rr.all, m_qp->ts.rr.cnt,
+                       m_qp->ts.rr.stop - m_qp->ts.rr.start,
+                       (m_qp->ts.rr.stop - m_qp->ts.rr.start)/m_qp->ts.rr.cnt);
+
+       if ((m_qp->ts.pi.min) &&
            (type == MCM_QP_PI_IO || type == MCM_QP_ALL))
                mlog(0, " QP (%p) PERF IO: Proxy-in: FS to LS times"
-                       " (usecs): max %u min %u avg %u ttime %u io_cnt %u\n",
-                       m_qp, m_qp->ts.pi_max, m_qp->ts.pi_min,
-                       m_qp->ts.pi_avg, m_qp->ts.pi_all, m_qp->ts.pi_cnt);
+                       " (usecs): max %u min %u avg %u ttime %u cnt %u - et %u avg %u\n",
+                       m_qp, m_qp->ts.pi.max, m_qp->ts.pi.min,
+                       m_qp->ts.pi.avg, m_qp->ts.pi.all, m_qp->ts.pi.cnt,
+                       m_qp->ts.pi.stop - m_qp->ts.pi.start,
+                       (m_qp->ts.pi.stop - m_qp->ts.pi.start)/m_qp->ts.pi.cnt);
 
-       if ((m_qp->ts.po_min) &&
+       if ((m_qp->ts.po.min) &&
            (type == MCM_QP_PO_IO || type == MCM_QP_ALL))
                mlog(0, " QP (%p) PERF IO: Proxy-out: FS to LS times"
-                       " (usecs): max %u min %u avg %u ttime %u io_cnt %u\n",
-                       m_qp, m_qp->ts.po_max, m_qp->ts.po_min,
-                       m_qp->ts.po_avg, m_qp->ts.po_all, m_qp->ts.po_cnt);
+                       " (usecs): max %u min %u avg %u ttime %u cnt %u et %u\n",
+                       m_qp, m_qp->ts.po.max, m_qp->ts.po.min,
+                       m_qp->ts.po.avg, m_qp->ts.po.all, m_qp->ts.po.cnt,
+                       m_qp->ts.po.stop - m_qp->ts.po.start,
+                       (m_qp->ts.po.stop - m_qp->ts.po.start)/m_qp->ts.po.cnt);
 }
 
-void mcm_qp_prof_ts(struct mcm_qp *m_qp, int type, uint32_t start, int qcnt, int ccnt)
+void mcm_qp_prof_ts(struct mcm_qp *m_qp, int type, uint32_t start, uint32_t que, uint32_t cmp)
 {
        uint32_t diff, stop = mcm_ts_us();
-       uint32_t *min, *max, *avg, *all, *cnt;
+       uint32_t *min, *max, *avg, *all, *cnt, *begin, *end, qcnt, ccnt;
        char *type_str;
 
        diff = stop - start;
+       ccnt = cmp ? cmp:1;
+       qcnt = que ? que:1;
 
        switch (type) {
        case MCM_QP_WT:
                type_str = "MCM_QP_WT";
-               min = &m_qp->ts.wt_min;
-               max = &m_qp->ts.wt_max;
-               avg = &m_qp->ts.wt_avg;
-               all = &m_qp->ts.wt_all;
-               cnt = &m_qp->ts.wt_cnt;
-               diff = diff/(qcnt+1);
+               min = &m_qp->ts.wt.min;
+               max = &m_qp->ts.wt.max;
+               avg = &m_qp->ts.wt.avg;
+               all = &m_qp->ts.wt.all;
+               cnt = &m_qp->ts.wt.cnt;
+               begin = &m_qp->ts.wt.start;
+               end = &m_qp->ts.wt.stop;
+               diff = diff/qcnt;
                break;
        case MCM_QP_RF:
                type_str = "MCM_QP_RF";
-               min = &m_qp->ts.rf_min;
-               max = &m_qp->ts.rf_max;
-               avg = &m_qp->ts.rf_avg;
-               all = &m_qp->ts.rf_all;
-               cnt = &m_qp->ts.rf_cnt;
-               diff = diff/(qcnt+1);
+               min = &m_qp->ts.rf.min;
+               max = &m_qp->ts.rf.max;
+               avg = &m_qp->ts.rf.avg;
+               all = &m_qp->ts.rf.all;
+               cnt = &m_qp->ts.rf.cnt;
+               begin = &m_qp->ts.rf.start;
+               end = &m_qp->ts.rf.stop;
+               diff = diff/qcnt;
                break;
        case MCM_QP_IB_RW:
                type_str = "MCM_QP_IB_RW";
-               min = &m_qp->ts.rw_min;
-               max = &m_qp->ts.rw_max;
-               avg = &m_qp->ts.rw_avg;
-               all = &m_qp->ts.rw_all;
-               cnt = &m_qp->ts.rw_cnt;
-               diff = diff/(qcnt+1);
+               min = &m_qp->ts.rw.min;
+               max = &m_qp->ts.rw.max;
+               avg = &m_qp->ts.rw.avg;
+               all = &m_qp->ts.rw.all;
+               cnt = &m_qp->ts.rw.cnt;
+               begin = &m_qp->ts.rw.start;
+               end = &m_qp->ts.rw.stop;
+               diff = diff/qcnt;
                break;
        case MCM_QP_IB_RR:
                type_str = "MCM_QP_IB_RR";
-               min = &m_qp->ts.rr_min;
-               max = &m_qp->ts.rr_max;
-               avg = &m_qp->ts.rr_avg;
-               all = &m_qp->ts.rr_all;
-               cnt = &m_qp->ts.rr_cnt;
-               diff = diff/(qcnt+1);
+               min = &m_qp->ts.rr.min;
+               max = &m_qp->ts.rr.max;
+               avg = &m_qp->ts.rr.avg;
+               all = &m_qp->ts.rr.all;
+               cnt = &m_qp->ts.rr.cnt;
+               begin = &m_qp->ts.rr.start;
+               end = &m_qp->ts.rr.stop;
+               diff = diff/qcnt;
                break;
        case MCM_QP_PI_IO:
                type_str = "MCM_QP_PI_IO";
-               min = &m_qp->ts.pi_min;
-               max = &m_qp->ts.pi_max;
-               avg = &m_qp->ts.pi_avg;
-               all = &m_qp->ts.pi_all;
-               cnt = &m_qp->ts.po_cnt;
+               min = &m_qp->ts.pi.min;
+               max = &m_qp->ts.pi.max;
+               avg = &m_qp->ts.pi.avg;
+               all = &m_qp->ts.pi.all;
+               cnt = &m_qp->ts.pi.cnt;
+               begin = &m_qp->ts.pi.start;
+               end = &m_qp->ts.pi.stop;
                break;
        case MCM_QP_PO_IO:
                type_str = "MCM_QP_PO_IO";
-               min = &m_qp->ts.po_min;
-               max = &m_qp->ts.po_max;
-               avg = &m_qp->ts.po_avg;
-               all = &m_qp->ts.po_all;
-               cnt = &m_qp->ts.po_cnt;
+               min = &m_qp->ts.po.min;
+               max = &m_qp->ts.po.max;
+               avg = &m_qp->ts.po.avg;
+               all = &m_qp->ts.po.all;
+               cnt = &m_qp->ts.po.cnt;
+               begin = &m_qp->ts.po.start;
+               end = &m_qp->ts.po.stop;
                break;
        default:
                return;
        }
 
+       if (*cnt == 0)
+               *begin = start;
+
        diff = diff/ccnt;
        *cnt += ccnt;
-       *all += diff;
+       *all += stop - start;
+       *end = stop;
        if (*min == 0 || diff < *min)
                *min = diff;
        if (*max == 0 || diff > *max)
@@ -633,11 +664,11 @@ void mcm_qp_prof_ts(struct mcm_qp *m_qp, int type, uint32_t start, int qcnt, int
        else
                *avg = (diff + *avg)/2;
 
-       mlog(0x10, "us(%u-%u=%u,%d,%d) %s: io %d: mx %u mn %u av %u tt %u "
+       mlog(0x10, "us(%u-%u=%u,%d,%d) %s: io %d: mx %u mn %u av %u tt %u et %u "
                   "TX tl %d hd %d RX tl %d w_tl %d hd %d rr %d wt %d\n",
-               start, stop, diff, qcnt+1, ccnt, type_str, *cnt, *max, *min, *avg, *all,
-               m_qp->wr_tl, m_qp->wr_hd, m_qp->wr_tl_r, m_qp->wr_tl_r_wt, m_qp->wr_hd_r,
-               m_qp->pi_rr_cnt, m_qp->post_cnt_wt);
+               start, stop, diff, qcnt, ccnt, type_str, *cnt, *max, *min, *avg, *all,
+               *end - *begin, m_qp->wr_tl, m_qp->wr_hd, m_qp->wr_tl_r,
+               m_qp->wr_tl_r_wt, m_qp->wr_hd_r, m_qp->pi_rr_cnt, m_qp->post_cnt_wt);
 }
 #endif