From b9d25e54d3dfc936915024aa294cdb5dd430673b Mon Sep 17 00:00:00 2001 From: Daniel Collins Date: Sun, 26 Nov 2023 20:38:46 +0000 Subject: [PATCH] Record more profiling data. --- src/coalesce.c | 21 ++++++++--- src/ipxwrapper.c | 12 ++++++ src/ipxwrapper.h | 3 ++ src/ipxwrapper_prof_defs.h | 6 +++ src/router.c | 3 ++ src/winsock.c | 77 ++++++++++++++++++++++++++------------ 6 files changed, 94 insertions(+), 28 deletions(-) diff --git a/src/coalesce.c b/src/coalesce.c index 5ea0173..7d4bb08 100644 --- a/src/coalesce.c +++ b/src/coalesce.c @@ -166,6 +166,10 @@ void coalesce_flush(coalesce_dest *cd) { log_printf(LOG_ERROR, "Error sending DOSBox IPX packet: %s", w32_error(WSAGetLastError())); } + else{ + __atomic_add_fetch(&send_packets_udp, 1, __ATOMIC_RELAXED); + __atomic_add_fetch(&send_bytes_udp, cd->payload_used, __ATOMIC_RELAXED); + } cd->payload_used = 0; DL_DELETE(coalesce_pending, cd); @@ -220,12 +224,19 @@ DWORD coalesce_send(const void *data, size_t data_size, addr32_t dest_net, addr4 } } - if(!queued && r_sendto(private_socket, (const void*)(data), data_size, 0, (struct sockaddr*)(&dosbox_server_addr), sizeof(dosbox_server_addr)) < 0) + if(!queued) { - DWORD error = WSAGetLastError(); - log_printf(LOG_ERROR, "Error sending DOSBox IPX packet: %s", w32_error(error)); - - return error; + if(r_sendto(private_socket, (const void*)(data), data_size, 0, (struct sockaddr*)(&dosbox_server_addr), sizeof(dosbox_server_addr)) < 0) + { + DWORD error = WSAGetLastError(); + log_printf(LOG_ERROR, "Error sending DOSBox IPX packet: %s", w32_error(error)); + + return error; + } + else{ + __atomic_add_fetch(&send_packets_udp, 1, __ATOMIC_RELAXED); + __atomic_add_fetch(&send_bytes_udp, data_size, __ATOMIC_RELAXED); + } } return ERROR_SUCCESS; diff --git a/src/ipxwrapper.c b/src/ipxwrapper.c index 55745bf..d36dce0 100644 --- a/src/ipxwrapper.c +++ b/src/ipxwrapper.c @@ -64,6 +64,9 @@ const unsigned int ipxwrapper_fstats_size = sizeof(ipxwrapper_fstats) / sizeof(* unsigned int send_packets = 0, send_bytes = 0; /* Sent from emulated socket */ unsigned int recv_packets = 0, recv_bytes = 0; /* Forwarded to emulated socket */ +unsigned int send_packets_udp = 0, send_bytes_udp = 0; /* Sent over UDP transport */ +unsigned int recv_packets_udp = 0, recv_bytes_udp = 0; /* Received over UDP transport */ + static void init_cs(CRITICAL_SECTION *cs) { if(!InitializeCriticalSectionAndSpinCount(cs, 0x80000000)) @@ -84,8 +87,17 @@ static void report_packet_stats(void) unsigned int my_recv_packets = __atomic_exchange_n(&recv_packets, 0, __ATOMIC_RELAXED); unsigned int my_recv_bytes = __atomic_exchange_n(&recv_bytes, 0, __ATOMIC_RELAXED); + unsigned int my_send_packets_udp = __atomic_exchange_n(&send_packets_udp, 0, __ATOMIC_RELAXED); + unsigned int my_send_bytes_udp = __atomic_exchange_n(&send_bytes_udp, 0, __ATOMIC_RELAXED); + + unsigned int my_recv_packets_udp = __atomic_exchange_n(&recv_packets_udp, 0, __ATOMIC_RELAXED); + unsigned int my_recv_bytes_udp = __atomic_exchange_n(&recv_bytes_udp, 0, __ATOMIC_RELAXED); + log_printf(LOG_INFO, "IPX sockets sent %u packets (%u bytes)", my_send_packets, my_send_bytes); log_printf(LOG_INFO, "IPX sockets received %u packets (%u bytes)", my_recv_packets, my_recv_bytes); + + log_printf(LOG_INFO, "UDP sockets sent %u packets (%u bytes)", my_send_packets_udp, my_send_bytes_udp); + log_printf(LOG_INFO, "UDP sockets received %u packets (%u bytes)", my_recv_packets_udp, my_recv_bytes_udp); } static DWORD WINAPI prof_thread_main(LPVOID lpParameter) diff --git a/src/ipxwrapper.h b/src/ipxwrapper.h index 8c064c3..559e1eb 100644 --- a/src/ipxwrapper.h +++ b/src/ipxwrapper.h @@ -201,6 +201,9 @@ enum { extern unsigned int send_packets, send_bytes; /* Sent from emulated socket */ extern unsigned int recv_packets, recv_bytes; /* Forwarded to emulated socket */ +extern unsigned int send_packets_udp, send_bytes_udp; /* Sent over UDP transport */ +extern unsigned int recv_packets_udp, recv_bytes_udp; /* Received over UDP transport */ + ipx_socket *get_socket(SOCKET sockfd); ipx_socket *get_socket_wait_for_ready(SOCKET sockfd, int timeout_ms); void lock_sockets(void); diff --git a/src/ipxwrapper_prof_defs.h b/src/ipxwrapper_prof_defs.h index 052f52a..99b142b 100644 --- a/src/ipxwrapper_prof_defs.h +++ b/src/ipxwrapper_prof_defs.h @@ -3,3 +3,9 @@ FPROF_DECL(_handle_udp_recv) FPROF_DECL(_handle_dosbox_recv) FPROF_DECL(_handle_pcap_frame) FPROF_DECL(lock_sockets) +FPROF_DECL(ioctlsocket_recv_pump) +FPROF_DECL(ioctlsocket_accumulate) +FPROF_DECL(recv_pump_select) +FPROF_DECL(recv_pump_find_slot) +FPROF_DECL(recv_pump_recv) +FPROF_DECL(recv_pump_reclaim_socket) diff --git a/src/router.c b/src/router.c index 696f1f9..0173498 100644 --- a/src/router.c +++ b/src/router.c @@ -655,6 +655,9 @@ static bool _do_udp_recv(int fd) return false; } + __atomic_add_fetch(&recv_packets_udp, 1, __ATOMIC_RELAXED); + __atomic_add_fetch(&recv_bytes_udp, len, __ATOMIC_RELAXED); + if(ipx_encap_type == ENCAP_TYPE_DOSBOX) { if(addr.sin_family != dosbox_server_addr.sin_family diff --git a/src/winsock.c b/src/winsock.c index 6f22f65..7662fc0 100644 --- a/src/winsock.c +++ b/src/winsock.c @@ -774,6 +774,8 @@ static int recv_pump(ipx_socket *sockptr, BOOL block) if(!block) { + FPROF_RECORD_SCOPE(&(ipxwrapper_fstats[IPXWRAPPER_FSTATS_recv_pump_select])); + fd_set read_fds; FD_ZERO(&read_fds); @@ -798,15 +800,19 @@ static int recv_pump(ipx_socket *sockptr, BOOL block) int recv_slot = -1; - for(int i = 0; i < RECV_QUEUE_MAX_PACKETS; ++i) { - if(queue->sizes[i] == IPX_RECV_QUEUE_FREE) + FPROF_RECORD_SCOPE(&(ipxwrapper_fstats[IPXWRAPPER_FSTATS_recv_pump_find_slot])); + + for(int i = 0; i < RECV_QUEUE_MAX_PACKETS; ++i) { - queue->sizes[i] = IPX_RECV_QUEUE_LOCKED; - recv_queue_adjust_refcount(queue, 1); - - recv_slot = i; - break; + if(queue->sizes[i] == IPX_RECV_QUEUE_FREE) + { + queue->sizes[i] = IPX_RECV_QUEUE_LOCKED; + recv_queue_adjust_refcount(queue, 1); + + recv_slot = i; + break; + } } } @@ -818,9 +824,19 @@ static int recv_pump(ipx_socket *sockptr, BOOL block) unlock_sockets(); - int r = r_recv(fd, (char*)(queue->data[recv_slot]), MAX_PKT_SIZE, 0); + int r; + { + FPROF_RECORD_SCOPE(&(ipxwrapper_fstats[IPXWRAPPER_FSTATS_recv_pump_recv])); + r = r_recv(fd, (char*)(queue->data[recv_slot]), MAX_PKT_SIZE, 0); + } - if(!reclaim_socket(sockptr, fd)) + bool ok; + { + FPROF_RECORD_SCOPE(&(ipxwrapper_fstats[IPXWRAPPER_FSTATS_recv_pump_reclaim_socket])); + ok = reclaim_socket(sockptr, fd); + } + + if(!ok) { /* The application closed the socket while we were in the recv() call. * Just discard our handle, let the queue be destroyed. @@ -1376,7 +1392,14 @@ static int send_packet(const ipx_packet *packet, int len, struct sockaddr *addr, log_printf(LOG_DEBUG, "Sending packet from %s to %s (%s:%hu)", src_addr, dest_addr, inet_ntoa(v4->sin_addr), ntohs(v4->sin_port)); } - return (r_sendto(private_socket, (char*)packet, len, 0, addr, addrlen) == len); + int r = r_sendto(private_socket, (char*)packet, len, 0, addr, addrlen); + if(r == len) + { + __atomic_add_fetch(&send_packets_udp, 1, __ATOMIC_RELAXED); + __atomic_add_fetch(&send_bytes_udp, len, __ATOMIC_RELAXED); + } + + return r; } static DWORD ipx_send_packet( @@ -1806,28 +1829,36 @@ int PASCAL ioctlsocket(SOCKET fd, long cmd, u_long *argp) if(cmd == FIONREAD && !(sock->flags & IPX_IS_SPX)) { - while(1) { - int r = recv_pump(sock, FALSE); - if(r < 0) - { - /* Error in recv_pump() */ - return -1; - } + FPROF_RECORD_SCOPE(&(ipxwrapper_fstats[IPXWRAPPER_FSTATS_ioctlsocket_recv_pump])); - if(r == 0) + while(1) { - /* No more packets ready to read from underlying socket. */ - break; + int r = recv_pump(sock, FALSE); + if(r < 0) + { + /* Error in recv_pump() */ + return -1; + } + + if(r == 0) + { + /* No more packets ready to read from underlying socket. */ + break; + } } } unsigned long accumulated_packet_data = 0; - for(int i = 0; i < sock->recv_queue->n_ready; ++i) { - const ipx_packet *packet = (const ipx_packet*)(sock->recv_queue->data[ sock->recv_queue->ready[i] ]); - accumulated_packet_data += packet->size; + FPROF_RECORD_SCOPE(&(ipxwrapper_fstats[IPXWRAPPER_FSTATS_ioctlsocket_accumulate])); + + for(int i = 0; i < sock->recv_queue->n_ready; ++i) + { + const ipx_packet *packet = (const ipx_packet*)(sock->recv_queue->data[ sock->recv_queue->ready[i] ]); + accumulated_packet_data += packet->size; + } } unlock_sockets();