[WSD] Add support for logging last 20MB for each of sent and received

data, based on work by Tzachi Dar.  Also fixed bug with flushed receive
work requests during socket duplictaion.

git-svn-id: svn://openib.tc.cornell.edu/gen1@141 ad392aa1-c5ef-ae45-8dd8-e69d62a5ef86

diff --git a/trunk/ulp/wsd/user/ib_cm.c b/trunk/ulp/wsd/user/ib_cm.c
index 7c28c0b066142d3db6dfdd7874455f782ca09bee..b77376a83478bde728986700c44a3e2ce5390cc5 100644 (file)
--- a/trunk/ulp/wsd/user/ib_cm.c
+++ b/trunk/ulp/wsd/user/ib_cm.c
@@ -156,12 +156,14 @@ cm_req_callback(
                {\r
                        int ret;\r
 \r
-                       wait_cq_drain( socket_info );\r
-\r
                        /* Non-blocking cancel since we're in CM callback context */\r
                        ib_cm_cancel( socket_info->listen.handle, NULL );\r
                        socket_info->listen.handle = NULL;\r
+                       cl_spinlock_release( &socket_info->mutex );\r
+\r
+                       wait_cq_drain( socket_info );\r
 \r
+                       cl_spinlock_acquire( &socket_info->mutex );\r
                        ret = ib_accept( socket_info, p_cm_req_rec );\r
                        if( ret )\r
                        {\r

diff --git a/trunk/ulp/wsd/user/ibsp_duplicate.c b/trunk/ulp/wsd/user/ibsp_duplicate.c
index 6a1d0adce1ffeba571c5c2814d8e712a6726eadf..4d093bf9f46b0f8f2f070ebcc7a584ddde53926d 100644 (file)
--- a/trunk/ulp/wsd/user/ibsp_duplicate.c
+++ b/trunk/ulp/wsd/user/ibsp_duplicate.c
@@ -310,10 +310,10 @@ prepare_duplicate_socket(
 \r
        cl_spinlock_release( &socket_info->mutex );\r
        ib_disconnect( socket_info, &reason );\r
-       cl_spinlock_acquire( &socket_info->mutex );\r
 \r
        wait_cq_drain( socket_info );\r
 \r
+       cl_spinlock_acquire( &socket_info->mutex );\r
        ib_destroy_socket( socket_info );\r
 \r
        /* Put enough info in dup_info so that the remote socket can recreate the connection. */\r

diff --git a/trunk/ulp/wsd/user/ibsp_iblow.c b/trunk/ulp/wsd/user/ibsp_iblow.c
index ca6825099cced51659535eb68a5d0b2eac896ccb..67ec7acf4c04ec89739b23e990eae63b4fd94520 100644 (file)
--- a/trunk/ulp/wsd/user/ibsp_iblow.c
+++ b/trunk/ulp/wsd/user/ibsp_iblow.c
@@ -90,8 +90,18 @@ complete_wq(
                 * GetOverlappedResult() even if we call lpWPUCompleteOverlappedRequest()\r
                 */\r
                if( wc->wc_type == IB_WC_RECV )\r
+               {\r
                        lpOverlapped->InternalHigh = wc->length;\r
 \r
+#ifdef IBSP_LOGGING\r
+                       cl_spinlock_acquire( &socket_info->recv_lock );\r
+                       DataLogger_WriteData(&socket_info->RecvDataLogger,\r
+                               p_recv_wr->idx, (void * __ptr64)p_recv_wr->ds_array[0].vaddr,\r
+                               wc->length);\r
+                       cl_spinlock_release( &socket_info->recv_lock );\r
+#endif\r
+               }\r
+\r
                lpOverlapped->OffsetHigh = 0;\r
                break;\r
 \r
@@ -127,6 +137,7 @@ complete_wq(
                        cl_spinlock_release( &socket_info->recv_lock );\r
 \r
                        cl_spinlock_release( &socket_info->mutex );\r
+                       p_io_info->p_ov = NULL;\r
                        IBSP_EXIT( IBSP_DBG_IO );\r
                        return;\r
                }\r
@@ -269,12 +280,6 @@ complete_wq(
                                 g_ibsp.overlap_h1_comp_count, g_ibsp.send_count, g_ibsp.recv_count));\r
 #endif\r
 \r
-               IBSP_TRACE1( IBSP_DBG_IO,\r
-                       ("Calling lpWPUCompleteOverlappedRequest: "\r
-                       "socket=%p, ov=%p OffsetHigh=%d InternalHigh=%d hEvent=%p\n",\r
-                       socket_info, lpOverlapped, lpOverlapped->OffsetHigh,\r
-                       lpOverlapped->InternalHigh, lpOverlapped->hEvent) );\r
-\r
                p_io_info->p_ov = lpOverlapped;\r
                cl_atomic_inc( &socket_info->ref_cnt );\r
        }\r
@@ -372,8 +377,11 @@ ib_cq_comp(
                        if( info[i].p_ov )\r
                        {\r
                                IBSP_TRACE1( IBSP_DBG_IO,\r
-                                       ("Calling WPUCompleteOverlappedRequest for ov=%p\n",\r
-                                       info[i].p_ov) );\r
+                                       ("Calling lpWPUCompleteOverlappedRequest: "\r
+                                       "socket=%p, ov=%p OffsetHigh=%d "\r
+                                       "InternalHigh=%d hEvent=%p\n",\r
+                                       info[i].p_socket, info[i].p_ov, info[i].p_ov->OffsetHigh,\r
+                                       info[i].p_ov->InternalHigh, info[i].p_ov->hEvent) );\r
 \r
                                ret = g_ibsp.up_call_table.lpWPUCompleteOverlappedRequest(\r
                                        info[i].p_socket->switch_socket, info[i].p_ov,\r
@@ -438,7 +446,7 @@ ib_cq_thread(
                }\r
 \r
                /* \r
-                * TODO: By rearanging thread creation and cq creation, this check\r
+                * TODO: By rearranging thread creation and cq creation, this check\r
                 * may be eliminated.\r
                 */\r
                if( cq_tinfo->cq != NULL )\r
@@ -515,7 +523,6 @@ ib_alloc_cq_tinfo(
        cq_tinfo->hca = hca;\r
        cq_tinfo->ib_cq_thread_exit_wanted = FALSE;\r
 \r
-       /* Create a cleanup thread */\r
        cq_tinfo->ib_cq_thread = CreateThread( NULL, 0, ib_cq_thread, cq_tinfo, 0, (LPDWORD)&cq_tinfo->ib_cq_thread_id );\r
 \r
        if( cq_tinfo->ib_cq_thread == NULL )\r
@@ -533,9 +540,8 @@ ib_alloc_cq_tinfo(
        cq_create.pfn_comp_cb = NULL;\r
        cq_create.h_wait_obj = cq_tinfo->cq_waitobj;\r
 \r
-       status = ib_create_cq( hca->hca_handle, &cq_create, cq_tinfo,   /* context */\r
-               NULL,   /* async handler */\r
-               &cq_tinfo->cq );\r
+       status = ib_create_cq( hca->hca_handle, &cq_create, cq_tinfo,\r
+               NULL, &cq_tinfo->cq );\r
        if( status )\r
        {\r
                ib_destroy_cq_tinfo( cq_tinfo );\r
@@ -1147,6 +1153,11 @@ shutdown_and_destroy_socket_info(
 \r
        ib_destroy_socket( socket_info );\r
 \r
+#ifdef IBSP_LOGGING\r
+       DataLogger_Shutdown(&socket_info->SendDataLogger);\r
+       DataLogger_Shutdown(&socket_info->RecvDataLogger);\r
+#endif\r
+\r
        /* Release the initial reference and clean up. */\r
        deref_socket_info( socket_info );\r
 \r

diff --git a/trunk/ulp/wsd/user/ibspdebug.c b/trunk/ulp/wsd/user/ibspdebug.c
index a2e98c00f3704332e1734a74ae4c2e416a5e240b..a8da7d98a0bd3d928a7b26b34d26e86814e14659 100644 (file)
--- a/trunk/ulp/wsd/user/ibspdebug.c
+++ b/trunk/ulp/wsd/user/ibspdebug.c
@@ -161,3 +161,137 @@ debug_dump_overlapped(
 }\r
 \r
 #endif /* _DEBUG_ */\r
+\r
+\r
+#ifdef IBSP_LOGGING\r
+\r
+VOID DataLogger_Init(\r
+                                       DataLogger                                      *pLogger,\r
+                                       char                                            *prefix,\r
+                                       struct sockaddr_in                      *addr1,\r
+                                       struct sockaddr_in                      *addr2 )\r
+{\r
+       HANDLE hFile;\r
+       HANDLE hMapFile;\r
+\r
+       char Name[100];\r
+       DWORD DataSize = 20 * 1024 * 1024; \r
+\r
+       sprintf(Name,"c:\\%s_%d.%d.%d.%d_%d_%d.%d.%d.%d_%d", \r
+               prefix,\r
+               addr1->sin_addr.S_un.S_un_b.s_b1,\r
+               addr1->sin_addr.S_un.S_un_b.s_b2,\r
+               addr1->sin_addr.S_un.S_un_b.s_b3,\r
+               addr1->sin_addr.S_un.S_un_b.s_b4,\r
+               CL_NTOH16(addr1->sin_port),\r
+               addr2->sin_addr.S_un.S_un_b.s_b1,\r
+               addr2->sin_addr.S_un.S_un_b.s_b2,\r
+               addr2->sin_addr.S_un.S_un_b.s_b3,\r
+               addr2->sin_addr.S_un.S_un_b.s_b4,\r
+               CL_NTOH16(addr2->sin_port)\r
+               );\r
+\r
+       pLogger->NextPrint = NULL;\r
+       pLogger->BufferStart = NULL;\r
+       pLogger->ShutdownClosed = FALSE;\r
+       pLogger->ToatalPrinted = 0;\r
+       pLogger->TotalSize = DataSize;\r
+\r
+       hFile = CreateFile( Name, GENERIC_READ|GENERIC_WRITE,\r
+               FILE_SHARE_READ | FILE_SHARE_WRITE, NULL, OPEN_ALWAYS,\r
+               FILE_ATTRIBUTE_NORMAL, NULL );\r
+\r
+       if (hFile != INVALID_HANDLE_VALUE)\r
+       {\r
+               IBSP_ERROR( ("CreateFile failed with error %d\n", GetLastError()) );\r
+               return;\r
+       }\r
+\r
+       hMapFile = CreateFileMapping(hFile,    // current file handle \r
+               NULL,                              // default security \r
+               PAGE_READWRITE,                    // read/write permission \r
+               0,                                 // max. object size \r
+               DataSize,                           // size of hFile \r
+               NULL);            // name of mapping object\r
+\r
+       CloseHandle( hFile );\r
+\r
+       if (hMapFile == NULL) \r
+       { \r
+               IBSP_ERROR( ("Could not create file mapping object.\n") );\r
+               return;\r
+       }\r
+\r
+       pLogger->BufferStart = MapViewOfFile(hMapFile, // handle to mapping object \r
+               FILE_MAP_ALL_ACCESS,               // read/write permission \r
+               0,                                 // max. object size \r
+               0,                                 // size of hFile \r
+               0);                                // map entire file \r
+\r
+       CloseHandle( hMapFile );\r
+\r
+       if( pLogger->BufferStart == NULL )\r
+       {\r
+               IBSP_ERROR( ("Could not MapViewOfFile.\n") );\r
+               return;\r
+       }\r
+\r
+       pLogger->NextPrint = pLogger->BufferStart;\r
+       cl_memclr(pLogger->NextPrint, DataSize);\r
+}\r
+\r
+\r
+VOID DataLogger_WriteData(\r
+                                       DataLogger                                      *pLogger,\r
+                                       long                                            Idx,\r
+                                       char                                            *Data,\r
+                                       DWORD                                           Len )\r
+{\r
+       char MessageHeader[16];\r
+       CL_ASSERT(Len < 64000);\r
+       CL_ASSERT(pLogger->ShutdownClosed == FALSE);\r
+       CL_ASSERT(Len < pLogger->TotalSize / 3);\r
+\r
+       if( !pLogger->BufferStart )\r
+               return;\r
+\r
+       cl_memset( MessageHeader, 0xff, sizeof(MessageHeader) );\r
+       cl_memcpy( MessageHeader+4, &Idx, sizeof(Idx) );\r
+       cl_memcpy( MessageHeader+8, &Len, sizeof(Len) );\r
+\r
+       pLogger->ToatalPrinted += Len;\r
+\r
+       if( pLogger->NextPrint + Len + (2 * sizeof (MessageHeader)) >\r
+               pLogger->BufferStart + pLogger->TotalSize )\r
+       {\r
+               /* We will now zero the remaing of the buffer, and restart */\r
+               cl_memclr( pLogger->NextPrint,\r
+                       pLogger->TotalSize - (pLogger->NextPrint - pLogger->BufferStart) );\r
+               pLogger->NextPrint = pLogger->BufferStart;\r
+       }\r
+\r
+       /* Just simple copy */\r
+       cl_memcpy( pLogger->NextPrint, MessageHeader, sizeof(MessageHeader) );\r
+       pLogger->NextPrint += sizeof(MessageHeader);\r
+\r
+       cl_memcpy( pLogger->NextPrint, Data, Len );\r
+       pLogger->NextPrint += Len;\r
+\r
+       /*\r
+        * Add the end marker but don't update NextPrint so the next message\r
+        * overwrites the previous message's end marker.\r
+        */\r
+       cl_memset( pLogger->NextPrint, 0xff, sizeof(MessageHeader) );\r
+}\r
+\r
+\r
+VOID DataLogger_Shutdown(\r
+                                       DataLogger                                      *pLogger )\r
+{\r
+       if( !pLogger->BufferStart )\r
+               return;\r
+\r
+       UnmapViewOfFile( pLogger->BufferStart );\r
+}\r
+\r
+#endif /* IBSP_LOGGING */\r

diff --git a/trunk/ulp/wsd/user/ibspdebug.h b/trunk/ulp/wsd/user/ibspdebug.h
index 7d14e5709559b5e599e645122bc4a47422bcef3c..3a9f84e781e8e409d109a2f52aa2f7cfc0348470 100644 (file)
--- a/trunk/ulp/wsd/user/ibspdebug.h
+++ b/trunk/ulp/wsd/user/ibspdebug.h
@@ -129,3 +129,41 @@ debug_dump_overlapped(
 #define STATS(expr)\r
 \r
 #endif /* _DEBUG_ */\r
+\r
+/*\r
+ * To enable logging of all Send/Receive data for each socket\r
+ * uncomment the following line.\r
+ */\r
+//#define IBSP_LOGGING\r
+\r
+#ifdef IBSP_LOGGING\r
+\r
+typedef struct DataLogger\r
+{\r
+       char                            *BufferStart;\r
+       size_t                          TotalSize;\r
+       char                            *NextPrint;\r
+       size_t                          ToatalPrinted;\r
+       BOOL                            ShutdownClosed;\r
+       HANDLE                          hMapFile;\r
+\r
+}DataLogger;\r
+\r
+\r
+VOID DataLogger_Init(\r
+                                       DataLogger                                      *pLoger,\r
+                                       char                                            *prefix,\r
+                                       struct sockaddr_in                      *addr1,\r
+                                       struct sockaddr_in                      *addr2 );\r
+\r
+\r
+VOID DataLogger_WriteData(\r
+                                       DataLogger                                      *pLoger,\r
+                                       long                                            Idx,\r
+                                       char                                            *Data,\r
+                                       DWORD                                           Len );\r
+\r
+VOID DataLogger_Shutdown(\r
+                                       DataLogger                                      *pLoger );\r
+\r
+#endif /* IBSP_LOGGING */\r

diff --git a/trunk/ulp/wsd/user/ibspdll.c b/trunk/ulp/wsd/user/ibspdll.c
index e12a86758cc2b58f490af4c38c27ca1dc45b2a16..1c372a7c5b4f752015d11746a38a6d4a45750518 100644 (file)
--- a/trunk/ulp/wsd/user/ibspdll.c
+++ b/trunk/ulp/wsd/user/ibspdll.c
@@ -143,6 +143,11 @@ _DllMain(
                        {\r
                                struct ibsp_socket_info *socket_info = NULL;\r
                                socket_info = PARENT_STRUCT(socket_item, struct ibsp_socket_info, item);\r
+\r
+#ifdef IBSP_LOGGING\r
+                               DataLogger_Shutdown(&socket_info->SendDataLogger);\r
+                               DataLogger_Shutdown(&socket_info->RecvDataLogger);\r
+#endif\r
                        }\r
 \r
                        cl_spinlock_release( &g_ibsp.socket_info_mutex );\r
@@ -275,6 +280,13 @@ accept_socket(
 \r
        new_socket_info->peer_addr = p_incoming->params.source;\r
 \r
+#ifdef IBSP_LOGGING\r
+       DataLogger_Init( &new_socket_info->SendDataLogger, "Send",\r
+               &new_socket_info->peer_addr, &new_socket_info->local_addr );\r
+       DataLogger_Init( &new_socket_info->RecvDataLogger, "Recv",\r
+               &new_socket_info->local_addr, &new_socket_info->peer_addr );\r
+#endif\r
+\r
        cl_spinlock_acquire( &new_socket_info->mutex );\r
        /* Update the state of the socket context */\r
        IBSP_CHANGE_SOCKET_STATE( new_socket_info, IBSP_CONNECTED );\r
@@ -785,6 +797,13 @@ IBSPConnect(
        /* Store the peer entity's address in socket context */\r
        socket_info->peer_addr = *addr;\r
 \r
+#ifdef IBSP_LOGGING\r
+       DataLogger_Init( &socket_info->SendDataLogger, "Send",\r
+               &socket_info->peer_addr, &socket_info->local_addr );\r
+       DataLogger_Init( &socket_info->RecvDataLogger, "Recv",\r
+               &socket_info->local_addr, &socket_info->peer_addr );\r
+#endif\r
+\r
        /* Update the socket state */\r
        IBSP_CHANGE_SOCKET_STATE( socket_info, IBSP_CONNECT );\r
 \r
@@ -1605,10 +1624,11 @@ IBSPRecv(
                         GetCurrentThreadId(), lpOverlapped,\r
                         g_ibsp.overlap_h0_count, g_ibsp.overlap_h1_count,\r
                         g_ibsp.overlap_h1_comp_count, g_ibsp.send_count, g_ibsp.recv_count));\r
-\r
-\r
 #endif\r
 \r
+#ifdef IBSP_LOGGING\r
+       wr->idx = socket_info->recv_log_idx++;\r
+#endif\r
 \r
        fzprint(("%s():%d:0x%x:0x%x: posting RECV socket=0x%p overlap=%p wr=0x%p\n",\r
                         __FUNCTION__, __LINE__, GetCurrentProcessId(), GetCurrentThreadId(), s,\r
@@ -1858,6 +1878,19 @@ IBSPSend(
        }\r
 #endif\r
 \r
+#ifdef IBSP_LOGGING\r
+       {\r
+               DWORD                                           i;\r
+\r
+               for( i=0; i < dwBufferCount; i++ )\r
+               {\r
+                       DataLogger_WriteData( &socket_info->SendDataLogger,\r
+                               socket_info->send_log_idx++, lpBuffers[i].buf,\r
+                               lpBuffers[i].len);\r
+               }\r
+       }\r
+#endif\r
+\r
        status = ib_post_send( socket_info->qp, &send_wr, NULL );\r
 \r
        if( status == IB_SUCCESS )\r

diff --git a/trunk/ulp/wsd/user/ibspstruct.h b/trunk/ulp/wsd/user/ibspstruct.h
index 7936050adf8df5a5c8faa9389221765ffffec71d..164d016608a1e348ea9eae7cf81325364bc416e3 100644 (file)
--- a/trunk/ulp/wsd/user/ibspstruct.h
+++ b/trunk/ulp/wsd/user/ibspstruct.h
@@ -109,6 +109,9 @@ struct _recv_wr
        struct _wr              wr;\r
        ib_recv_wr_t    recv;\r
        ib_local_ds_t   ds_array[QP_ATTRIB_RQ_SGE];\r
+#ifdef IBSP_LOGGING\r
+       LONG                    idx;\r
+#endif\r
 };\r
 \r
 \r
@@ -317,6 +320,13 @@ struct ibsp_socket_info
                DWORD identifier;               /* Unique identifier */\r
                DWORD dwProcessId;\r
        } duplicate;\r
+\r
+#ifdef IBSP_LOGGING\r
+       DataLogger              SendDataLogger;\r
+       DataLogger              RecvDataLogger;\r
+       long                    recv_log_idx;\r
+       long                    send_log_idx;\r
+#endif\r
 };\r
 \r
 \r