From: ftillier Date: Wed, 2 Nov 2005 22:31:26 +0000 (+0000) Subject: [WSD] Add support for logging last 20MB for each of sent and received X-Git-Url: https://openfabrics.org/gitweb/?a=commitdiff_plain;h=1b170e03474c41b5c56e7bdfc7a4b4655f3e44a3;p=~shefty%2Frdma-win.git [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 7c28c0b0..b77376a8 100644 --- a/trunk/ulp/wsd/user/ib_cm.c +++ b/trunk/ulp/wsd/user/ib_cm.c @@ -156,12 +156,14 @@ cm_req_callback( { int ret; - wait_cq_drain( socket_info ); - /* Non-blocking cancel since we're in CM callback context */ ib_cm_cancel( socket_info->listen.handle, NULL ); socket_info->listen.handle = NULL; + cl_spinlock_release( &socket_info->mutex ); + + wait_cq_drain( socket_info ); + cl_spinlock_acquire( &socket_info->mutex ); ret = ib_accept( socket_info, p_cm_req_rec ); if( ret ) { diff --git a/trunk/ulp/wsd/user/ibsp_duplicate.c b/trunk/ulp/wsd/user/ibsp_duplicate.c index 6a1d0adc..4d093bf9 100644 --- a/trunk/ulp/wsd/user/ibsp_duplicate.c +++ b/trunk/ulp/wsd/user/ibsp_duplicate.c @@ -310,10 +310,10 @@ prepare_duplicate_socket( cl_spinlock_release( &socket_info->mutex ); ib_disconnect( socket_info, &reason ); - cl_spinlock_acquire( &socket_info->mutex ); wait_cq_drain( socket_info ); + cl_spinlock_acquire( &socket_info->mutex ); ib_destroy_socket( socket_info ); /* Put enough info in dup_info so that the remote socket can recreate the connection. */ diff --git a/trunk/ulp/wsd/user/ibsp_iblow.c b/trunk/ulp/wsd/user/ibsp_iblow.c index ca682509..67ec7acf 100644 --- 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() */ if( wc->wc_type == IB_WC_RECV ) + { lpOverlapped->InternalHigh = wc->length; +#ifdef IBSP_LOGGING + cl_spinlock_acquire( &socket_info->recv_lock ); + DataLogger_WriteData(&socket_info->RecvDataLogger, + p_recv_wr->idx, (void * __ptr64)p_recv_wr->ds_array[0].vaddr, + wc->length); + cl_spinlock_release( &socket_info->recv_lock ); +#endif + } + lpOverlapped->OffsetHigh = 0; break; @@ -127,6 +137,7 @@ complete_wq( cl_spinlock_release( &socket_info->recv_lock ); cl_spinlock_release( &socket_info->mutex ); + p_io_info->p_ov = NULL; IBSP_EXIT( IBSP_DBG_IO ); return; } @@ -269,12 +280,6 @@ complete_wq( g_ibsp.overlap_h1_comp_count, g_ibsp.send_count, g_ibsp.recv_count)); #endif - IBSP_TRACE1( IBSP_DBG_IO, - ("Calling lpWPUCompleteOverlappedRequest: " - "socket=%p, ov=%p OffsetHigh=%d InternalHigh=%d hEvent=%p\n", - socket_info, lpOverlapped, lpOverlapped->OffsetHigh, - lpOverlapped->InternalHigh, lpOverlapped->hEvent) ); - p_io_info->p_ov = lpOverlapped; cl_atomic_inc( &socket_info->ref_cnt ); } @@ -372,8 +377,11 @@ ib_cq_comp( if( info[i].p_ov ) { IBSP_TRACE1( IBSP_DBG_IO, - ("Calling WPUCompleteOverlappedRequest for ov=%p\n", - info[i].p_ov) ); + ("Calling lpWPUCompleteOverlappedRequest: " + "socket=%p, ov=%p OffsetHigh=%d " + "InternalHigh=%d hEvent=%p\n", + info[i].p_socket, info[i].p_ov, info[i].p_ov->OffsetHigh, + info[i].p_ov->InternalHigh, info[i].p_ov->hEvent) ); ret = g_ibsp.up_call_table.lpWPUCompleteOverlappedRequest( info[i].p_socket->switch_socket, info[i].p_ov, @@ -438,7 +446,7 @@ ib_cq_thread( } /* - * TODO: By rearanging thread creation and cq creation, this check + * TODO: By rearranging thread creation and cq creation, this check * may be eliminated. */ if( cq_tinfo->cq != NULL ) @@ -515,7 +523,6 @@ ib_alloc_cq_tinfo( cq_tinfo->hca = hca; cq_tinfo->ib_cq_thread_exit_wanted = FALSE; - /* Create a cleanup thread */ cq_tinfo->ib_cq_thread = CreateThread( NULL, 0, ib_cq_thread, cq_tinfo, 0, (LPDWORD)&cq_tinfo->ib_cq_thread_id ); if( cq_tinfo->ib_cq_thread == NULL ) @@ -533,9 +540,8 @@ ib_alloc_cq_tinfo( cq_create.pfn_comp_cb = NULL; cq_create.h_wait_obj = cq_tinfo->cq_waitobj; - status = ib_create_cq( hca->hca_handle, &cq_create, cq_tinfo, /* context */ - NULL, /* async handler */ - &cq_tinfo->cq ); + status = ib_create_cq( hca->hca_handle, &cq_create, cq_tinfo, + NULL, &cq_tinfo->cq ); if( status ) { ib_destroy_cq_tinfo( cq_tinfo ); @@ -1147,6 +1153,11 @@ shutdown_and_destroy_socket_info( ib_destroy_socket( socket_info ); +#ifdef IBSP_LOGGING + DataLogger_Shutdown(&socket_info->SendDataLogger); + DataLogger_Shutdown(&socket_info->RecvDataLogger); +#endif + /* Release the initial reference and clean up. */ deref_socket_info( socket_info ); diff --git a/trunk/ulp/wsd/user/ibspdebug.c b/trunk/ulp/wsd/user/ibspdebug.c index a2e98c00..a8da7d98 100644 --- a/trunk/ulp/wsd/user/ibspdebug.c +++ b/trunk/ulp/wsd/user/ibspdebug.c @@ -161,3 +161,137 @@ debug_dump_overlapped( } #endif /* _DEBUG_ */ + + +#ifdef IBSP_LOGGING + +VOID DataLogger_Init( + DataLogger *pLogger, + char *prefix, + struct sockaddr_in *addr1, + struct sockaddr_in *addr2 ) +{ + HANDLE hFile; + HANDLE hMapFile; + + char Name[100]; + DWORD DataSize = 20 * 1024 * 1024; + + sprintf(Name,"c:\\%s_%d.%d.%d.%d_%d_%d.%d.%d.%d_%d", + prefix, + addr1->sin_addr.S_un.S_un_b.s_b1, + addr1->sin_addr.S_un.S_un_b.s_b2, + addr1->sin_addr.S_un.S_un_b.s_b3, + addr1->sin_addr.S_un.S_un_b.s_b4, + CL_NTOH16(addr1->sin_port), + addr2->sin_addr.S_un.S_un_b.s_b1, + addr2->sin_addr.S_un.S_un_b.s_b2, + addr2->sin_addr.S_un.S_un_b.s_b3, + addr2->sin_addr.S_un.S_un_b.s_b4, + CL_NTOH16(addr2->sin_port) + ); + + pLogger->NextPrint = NULL; + pLogger->BufferStart = NULL; + pLogger->ShutdownClosed = FALSE; + pLogger->ToatalPrinted = 0; + pLogger->TotalSize = DataSize; + + hFile = CreateFile( Name, GENERIC_READ|GENERIC_WRITE, + FILE_SHARE_READ | FILE_SHARE_WRITE, NULL, OPEN_ALWAYS, + FILE_ATTRIBUTE_NORMAL, NULL ); + + if (hFile != INVALID_HANDLE_VALUE) + { + IBSP_ERROR( ("CreateFile failed with error %d\n", GetLastError()) ); + return; + } + + hMapFile = CreateFileMapping(hFile, // current file handle + NULL, // default security + PAGE_READWRITE, // read/write permission + 0, // max. object size + DataSize, // size of hFile + NULL); // name of mapping object + + CloseHandle( hFile ); + + if (hMapFile == NULL) + { + IBSP_ERROR( ("Could not create file mapping object.\n") ); + return; + } + + pLogger->BufferStart = MapViewOfFile(hMapFile, // handle to mapping object + FILE_MAP_ALL_ACCESS, // read/write permission + 0, // max. object size + 0, // size of hFile + 0); // map entire file + + CloseHandle( hMapFile ); + + if( pLogger->BufferStart == NULL ) + { + IBSP_ERROR( ("Could not MapViewOfFile.\n") ); + return; + } + + pLogger->NextPrint = pLogger->BufferStart; + cl_memclr(pLogger->NextPrint, DataSize); +} + + +VOID DataLogger_WriteData( + DataLogger *pLogger, + long Idx, + char *Data, + DWORD Len ) +{ + char MessageHeader[16]; + CL_ASSERT(Len < 64000); + CL_ASSERT(pLogger->ShutdownClosed == FALSE); + CL_ASSERT(Len < pLogger->TotalSize / 3); + + if( !pLogger->BufferStart ) + return; + + cl_memset( MessageHeader, 0xff, sizeof(MessageHeader) ); + cl_memcpy( MessageHeader+4, &Idx, sizeof(Idx) ); + cl_memcpy( MessageHeader+8, &Len, sizeof(Len) ); + + pLogger->ToatalPrinted += Len; + + if( pLogger->NextPrint + Len + (2 * sizeof (MessageHeader)) > + pLogger->BufferStart + pLogger->TotalSize ) + { + /* We will now zero the remaing of the buffer, and restart */ + cl_memclr( pLogger->NextPrint, + pLogger->TotalSize - (pLogger->NextPrint - pLogger->BufferStart) ); + pLogger->NextPrint = pLogger->BufferStart; + } + + /* Just simple copy */ + cl_memcpy( pLogger->NextPrint, MessageHeader, sizeof(MessageHeader) ); + pLogger->NextPrint += sizeof(MessageHeader); + + cl_memcpy( pLogger->NextPrint, Data, Len ); + pLogger->NextPrint += Len; + + /* + * Add the end marker but don't update NextPrint so the next message + * overwrites the previous message's end marker. + */ + cl_memset( pLogger->NextPrint, 0xff, sizeof(MessageHeader) ); +} + + +VOID DataLogger_Shutdown( + DataLogger *pLogger ) +{ + if( !pLogger->BufferStart ) + return; + + UnmapViewOfFile( pLogger->BufferStart ); +} + +#endif /* IBSP_LOGGING */ diff --git a/trunk/ulp/wsd/user/ibspdebug.h b/trunk/ulp/wsd/user/ibspdebug.h index 7d14e570..3a9f84e7 100644 --- a/trunk/ulp/wsd/user/ibspdebug.h +++ b/trunk/ulp/wsd/user/ibspdebug.h @@ -129,3 +129,41 @@ debug_dump_overlapped( #define STATS(expr) #endif /* _DEBUG_ */ + +/* + * To enable logging of all Send/Receive data for each socket + * uncomment the following line. + */ +//#define IBSP_LOGGING + +#ifdef IBSP_LOGGING + +typedef struct DataLogger +{ + char *BufferStart; + size_t TotalSize; + char *NextPrint; + size_t ToatalPrinted; + BOOL ShutdownClosed; + HANDLE hMapFile; + +}DataLogger; + + +VOID DataLogger_Init( + DataLogger *pLoger, + char *prefix, + struct sockaddr_in *addr1, + struct sockaddr_in *addr2 ); + + +VOID DataLogger_WriteData( + DataLogger *pLoger, + long Idx, + char *Data, + DWORD Len ); + +VOID DataLogger_Shutdown( + DataLogger *pLoger ); + +#endif /* IBSP_LOGGING */ diff --git a/trunk/ulp/wsd/user/ibspdll.c b/trunk/ulp/wsd/user/ibspdll.c index e12a8675..1c372a7c 100644 --- a/trunk/ulp/wsd/user/ibspdll.c +++ b/trunk/ulp/wsd/user/ibspdll.c @@ -143,6 +143,11 @@ _DllMain( { struct ibsp_socket_info *socket_info = NULL; socket_info = PARENT_STRUCT(socket_item, struct ibsp_socket_info, item); + +#ifdef IBSP_LOGGING + DataLogger_Shutdown(&socket_info->SendDataLogger); + DataLogger_Shutdown(&socket_info->RecvDataLogger); +#endif } cl_spinlock_release( &g_ibsp.socket_info_mutex ); @@ -275,6 +280,13 @@ accept_socket( new_socket_info->peer_addr = p_incoming->params.source; +#ifdef IBSP_LOGGING + DataLogger_Init( &new_socket_info->SendDataLogger, "Send", + &new_socket_info->peer_addr, &new_socket_info->local_addr ); + DataLogger_Init( &new_socket_info->RecvDataLogger, "Recv", + &new_socket_info->local_addr, &new_socket_info->peer_addr ); +#endif + cl_spinlock_acquire( &new_socket_info->mutex ); /* Update the state of the socket context */ IBSP_CHANGE_SOCKET_STATE( new_socket_info, IBSP_CONNECTED ); @@ -785,6 +797,13 @@ IBSPConnect( /* Store the peer entity's address in socket context */ socket_info->peer_addr = *addr; +#ifdef IBSP_LOGGING + DataLogger_Init( &socket_info->SendDataLogger, "Send", + &socket_info->peer_addr, &socket_info->local_addr ); + DataLogger_Init( &socket_info->RecvDataLogger, "Recv", + &socket_info->local_addr, &socket_info->peer_addr ); +#endif + /* Update the socket state */ IBSP_CHANGE_SOCKET_STATE( socket_info, IBSP_CONNECT ); @@ -1605,10 +1624,11 @@ IBSPRecv( GetCurrentThreadId(), lpOverlapped, g_ibsp.overlap_h0_count, g_ibsp.overlap_h1_count, g_ibsp.overlap_h1_comp_count, g_ibsp.send_count, g_ibsp.recv_count)); - - #endif +#ifdef IBSP_LOGGING + wr->idx = socket_info->recv_log_idx++; +#endif fzprint(("%s():%d:0x%x:0x%x: posting RECV socket=0x%p overlap=%p wr=0x%p\n", __FUNCTION__, __LINE__, GetCurrentProcessId(), GetCurrentThreadId(), s, @@ -1858,6 +1878,19 @@ IBSPSend( } #endif +#ifdef IBSP_LOGGING + { + DWORD i; + + for( i=0; i < dwBufferCount; i++ ) + { + DataLogger_WriteData( &socket_info->SendDataLogger, + socket_info->send_log_idx++, lpBuffers[i].buf, + lpBuffers[i].len); + } + } +#endif + status = ib_post_send( socket_info->qp, &send_wr, NULL ); if( status == IB_SUCCESS ) diff --git a/trunk/ulp/wsd/user/ibspstruct.h b/trunk/ulp/wsd/user/ibspstruct.h index 7936050a..164d0166 100644 --- a/trunk/ulp/wsd/user/ibspstruct.h +++ b/trunk/ulp/wsd/user/ibspstruct.h @@ -109,6 +109,9 @@ struct _recv_wr struct _wr wr; ib_recv_wr_t recv; ib_local_ds_t ds_array[QP_ATTRIB_RQ_SGE]; +#ifdef IBSP_LOGGING + LONG idx; +#endif }; @@ -317,6 +320,13 @@ struct ibsp_socket_info DWORD identifier; /* Unique identifier */ DWORD dwProcessId; } duplicate; + +#ifdef IBSP_LOGGING + DataLogger SendDataLogger; + DataLogger RecvDataLogger; + long recv_log_idx; + long send_log_idx; +#endif };