Add TRACE_SOCKIO tracing for client<->storage server connections

App/net.cpp

@@ -351,6 +351,11 @@ void NetIO::ing_authenticate_new_client(tcp::socket* csocket,
     ing_start_accept();
 }
 
+#ifdef TRACE_SOCKIO
+static size_t stg_clients_connected = 0;
+static size_t stg_clients_authenticated = 0;
+#endif
+
 /*
     Handle new client connections.
     New clients always send an authentication message.
@@ -384,6 +389,15 @@ void NetIO::stg_authenticate_new_client(tcp::socket* csocket,
             return;
         }
         else {
+#ifdef TRACE_SOCKIO
+                ++stg_clients_connected;
+                if (stg_clients_connected % 1000 == 0) {
+                    struct timeval now;
+                    gettimeofday(&now, NULL);
+                    printf("%lu.%06lu: STG %lu clients connected\n",
+                        now.tv_sec, now.tv_usec, stg_clients_connected);
+                }
+#endif
             clientid_t c_simid = *((clientid_t *)(auth_message));
             // Read the authentication token
             unsigned char *auth_ptr = auth_message + sizeof(clientid_t);
@@ -397,6 +411,15 @@ void NetIO::stg_authenticate_new_client(tcp::socket* csocket,
             if(ret) {
                 uint32_t lcid = c_simid / num_stg_nodes;
                 client_sockets[lcid] = csocket;
+#ifdef TRACE_SOCKIO
+                ++stg_clients_authenticated;
+                if (stg_clients_authenticated % 1000 == 0) {
+                    struct timeval now;
+                    gettimeofday(&now, NULL);
+                    printf("%lu.%06lu: STG %lu clients authenticated\n",
+                        now.tv_sec, now.tv_usec, stg_clients_authenticated);
+                }
+#endif
             }
             else{
                 printf("Client <-> Storage authentication failed\n");
@@ -442,6 +465,11 @@ void NetIO::send_client_mailbox()
     unsigned long start = tp.tv_sec * 1000000 + tp.tv_nsec/1000;
 #endif
 
+#ifdef TRACE_SOCKIO
+    size_t clients_without_sockets = 0;
+    size_t mailboxes_queued = 0;
+#endif
+
     // Send each client their tokens for the next epoch
     for(uint32_t lcid = 0; lcid < num_clients_per_stg; lcid++)
     {
@@ -482,14 +510,22 @@ void NetIO::send_client_mailbox()
                     }
                 });
             });
+#ifdef TRACE_SOCKIO
+            ++mailboxes_queued;
+        } else {
+            ++clients_without_sockets;
+#endif
         }
-        /*
-        else {
-            printf("Client did not have a socket!\n");
-        }
-        */
     }
 
+#ifdef TRACE_SOCKIO
+    struct timeval now;
+    gettimeofday(&now, NULL);
+    printf("%lu.%06lu: STG queued %lu mailboxes; %lu clients without sockets\n",
+        now.tv_sec, now.tv_usec, mailboxes_queued,
+        clients_without_sockets);
+#endif
+
 #ifdef PROFILE_NET_CLIENTS
     clock_gettime(CLOCK_REALTIME_COARSE, &tp);
     unsigned long end = tp.tv_sec * 1000000 + tp.tv_nsec/1000;

Client/clients.cpp

@@ -560,6 +560,46 @@ bool Client::encryptMessageBundle(uint32_t enc_bundle_size, unsigned char *pt_ms
     return 1;
 }
 
+#ifdef TRACE_SOCKIO
+class LimitLogger {
+    std::string label;
+    std::string thrid;
+    struct timeval last_log;
+    size_t num_items;
+public:
+    LimitLogger(const char *_label): label(_label), last_log({0,0}),
+        num_items(0) {
+        std::stringstream ss;
+        ss << boost::this_thread::get_id();
+        thrid = ss.str();
+    }
+
+    void log() {
+        struct timeval now;
+        gettimeofday(&now, NULL);
+        long elapsedus = (now.tv_sec - last_log.tv_sec) * 1000000
+            + (now.tv_usec - last_log.tv_usec);
+        if (num_items > 0 && elapsedus > 500000) {
+            printf("%lu.%06lu: Thread %s end %s of %lu items\n",
+                last_log.tv_sec, last_log.tv_usec,
+                thrid.c_str(), label.c_str(),
+                num_items);
+            num_items = 0;
+        }
+        if (num_items == 0) {
+            printf("%lu.%06lu: Thread %s begin %s\n", now.tv_sec,
+                now.tv_usec, thrid.c_str(), label.c_str());
+        }
+        gettimeofday(&last_log, NULL);
+        ++num_items;
+    }
+};
+
+
+static thread_local LimitLogger
+    recvlogger("recv"), queuelogger("queue"), sentlogger("sent");
+#endif
+
 
 void Client::sendMessageBundle()
 {
@@ -589,10 +629,16 @@ void Client::sendMessageBundle()
     displayPtMessageBundle(send_pt_msgbundle, priv_out, msg_size);
 #endif
 
+#ifdef TRACE_SOCKIO
+    queuelogger.log();
+#endif
     boost::asio::async_write(*ingestion_sock,
         boost::asio::buffer(send_enc_msgbundle, send_enc_msgbundle_size),
         [this, send_enc_msgbundle] (boost::system::error_code ecc, std::size_t) {
 
+#ifdef TRACE_SOCKIO
+    sentlogger.log();
+#endif
 #ifdef VERBOSE_CLIENT
         if(sim_id==0){
             printf("TEST: Client 0 send their msgbundle\n");
@@ -867,6 +913,9 @@ void Client::epoch_process() {
                 [this, recv_pt_mailbox, recv_enc_mailbox]
                 (boost::system::error_code ecc, std::size_t) {
 
+#ifdef TRACE_SOCKIO
+                recvlogger.log();
+#endif
                 if (ecc) {
                     if(ecc == boost::asio::error::eof) {
                         delete(storage_sock);
@@ -907,6 +956,9 @@ void Client::epoch_process() {
             [this, recv_pt_mailbox, recv_enc_mailbox]
             (boost::system::error_code ecc, std::size_t) {
 
+#ifdef TRACE_SOCKIO
+            recvlogger.log();
+#endif
             if (ecc) {
                 if(ecc == boost::asio::error::eof) {
                     delete(storage_sock);

Makefile

@@ -121,6 +121,9 @@ Client_Cpp_Files := $(wildcard Client/*.cpp)
 Client_Include_Paths := -IApp -IUntrusted -I$(SGX_SDK)/include
 
 Client_Cpp_Flags := -fPIC -Wno-attributes $(Client_Include_Paths)
+ifeq ($(TRACE_SOCKIO), 1)
+	Client_Cpp_Flags += -DTRACE_SOCKIO
+endif
 
 Client_Cpp_Objects := $(Client_Cpp_Files:.cpp=.o)