per-second cell statistics to help with profiling

svn:r140

src/or/command.c

@@ -6,26 +6,89 @@
 
 extern or_options_t options; /* command-line and config-file options */
 
+void command_time_process_cell(cell_t *cell, connection_t *conn,
+                               int *num, int *time,
+                               void (*func)(cell_t *, connection_t *)) {
+  struct timeval start, end;
+  int time_passed; 
+
+  *num += 1;
+
+  if(gettimeofday(&start,NULL) < 0) {
+    log(LOG_ERR,"command_time_process_cell(): gettimeofday failed.");
+    return;
+  }
+
+  (*func)(cell, conn);
+
+  if(gettimeofday(&end,NULL) < 0) {
+    log(LOG_ERR,"command_time_process_cell(): gettimeofday failed.");
+    return;
+  }
+
+  if(end.tv_usec < start.tv_usec) {
+    end.tv_sec--;
+    end.tv_usec += 1000000;
+  }
+  time_passed = ((end.tv_sec - start.tv_sec)*1000000) + (end.tv_usec - start.tv_usec);
+  if(time_passed > 5000) { /* more than 5ms */
+    log(LOG_INFO,"command_time_process_cell(): That call just took %d ms.",time_passed/1000);
+  }
+  *time += time_passed;
+}
+
 void command_process_cell(cell_t *cell, connection_t *conn) {
+  static int num_create=0, num_data=0, num_destroy=0, num_sendme=0, num_connected=0;
+  static int create_time=0, data_time=0, destroy_time=0, sendme_time=0, connected_time=0;
+  static long current_second = 0; /* from previous calls to gettimeofday */
+  struct timeval now;
+
+  if(gettimeofday(&now,NULL) < 0) {
+    log(LOG_ERR,"command_process_cell(): gettimeofday failed.");
+    return;
+  }
+
+  if(now.tv_sec > current_second) { /* the second has rolled over */
+    /* print stats */
+    log(LOG_INFO,"At end of second:"); 
+    log(LOG_INFO,"Create:    %d (%d ms)", num_create, create_time/1000);
+    log(LOG_INFO,"Data:      %d (%d ms)", num_data, data_time/1000);
+    log(LOG_INFO,"Destroy:   %d (%d ms)", num_destroy, destroy_time/1000);
+    log(LOG_INFO,"Sendme:    %d (%d ms)", num_sendme, sendme_time/1000);
+    log(LOG_INFO,"Connected: %d (%d ms)", num_connected, connected_time/1000);
+
+    /* zero out stats */
+    num_create = num_data = num_destroy = num_sendme = num_connected = 0;
+    create_time = data_time = destroy_time = sendme_time = connected_time = 0;
+
+    /* remember which second it is, for next time */
+    current_second = now.tv_sec; 
+  }
 
   switch(cell->command) {
     case CELL_PADDING:
       /* do nothing */
       break;
     case CELL_CREATE:
-      command_process_create_cell(cell, conn);
+      log(LOG_INFO,"Starting to process create cell.");
+      command_time_process_cell(cell, conn, &num_create, &create_time,
+                                command_process_create_cell);
       break;
     case CELL_DATA:
-      command_process_data_cell(cell, conn);
+      command_time_process_cell(cell, conn, &num_data, &data_time,
+                                command_process_data_cell);
       break;
     case CELL_DESTROY:
-      command_process_destroy_cell(cell, conn);
+      command_time_process_cell(cell, conn, &num_destroy, &destroy_time,
+                                command_process_destroy_cell);
       break;
     case CELL_SENDME:
-      command_process_sendme_cell(cell, conn);
+      command_time_process_cell(cell, conn, &num_sendme, &sendme_time,
+                                command_process_sendme_cell);
       break;
     case CELL_CONNECTED:
-      command_process_connected_cell(cell, conn);
+      command_time_process_cell(cell, conn, &num_connected, &connected_time,
+                                command_process_connected_cell);
       break;
     default:
       log(LOG_DEBUG,"Cell of unknown type (%d) received. Dropping.", cell->command);
@@ -134,7 +197,7 @@ void command_process_create_cell(cell_t *cell, connection_t *conn) {
   conn->onions_handled_this_second++;
   log(LOG_DEBUG,"command_process_create_cell(): Processing onion %d for this second.",conn->onions_handled_this_second);
   if(conn->onions_handled_this_second > options.OnionsPerSecond) {
-    log(LOG_DEBUG,"command_process_create_cell(): Received too many onions (now %d) this second. Closing.", conn->onions_handled_this_second);
+    log(LOG_INFO,"command_process_create_cell(): Received too many onions (now %d) this second. Closing.", conn->onions_handled_this_second);
     circuit_close(circ);
     return;
   }
@@ -223,7 +286,10 @@ void command_process_sendme_cell(cell_t *cell, connection_t *conn) {
 
   /* at this point both circ->n_conn and circ->p_conn are guaranteed to be set */
 
-  assert(cell->length == RECEIVE_WINDOW_INCREMENT);
+  if(cell->length != RECEIVE_WINDOW_INCREMENT) {
+    log(LOG_WARNING,"command_process_sendme_cell(): non-standard sendme value %d.",cell->length);
+  }
+//  assert(cell->length == RECEIVE_WINDOW_INCREMENT);
 
   if(cell->aci == circ->p_aci) { /* it's an outgoing cell */
     circ->n_receive_window += cell->length;

src/or/main.c

@@ -376,6 +376,7 @@ int prepare_for_poll(int *timeout) {
   for(i=0;i<nfds;i++)
     check_conn_marked(i); 
 
+#if 0
   /* check if we need to refill buckets or zero out any per-second stats */
   for(i=0;i<nfds;i++) {
     if(connection_receiver_bucket_should_increase(connection_array[i]) ||
@@ -384,8 +385,9 @@ int prepare_for_poll(int *timeout) {
       break;
     }
   }
+#endif
 
-  if(need_to_wake_soon) {
+//  if(need_to_wake_soon) {
     if(now.tv_sec > current_second) { /* the second has already rolled over! */
 //      log(LOG_DEBUG,"prepare_for_poll(): The second has rolled over, immediately refilling.");
       for(i=0;i<nfds;i++) {
@@ -393,11 +395,12 @@ int prepare_for_poll(int *timeout) {
         connection_array[i]->onions_handled_this_second = 0;
       }
       current_second = now.tv_sec; /* remember which second it is, for next time */
-    } else {
+    }
+//    } else {
       /* this timeout is definitely sooner than any of the above ones */
     *timeout = 1000 - (now.tv_usec / 1000); /* how many milliseconds til the next second? */
-    }
-  }
+//    }
+//  }
 
   if(options.LinkPadding) {
     /* now check which conn wants to speak soonest */
@@ -530,7 +533,7 @@ int do_main_loop(void) {
 static void catch(int the_signal) {
 
   switch(the_signal) {
-    case SIGABRT:
+//    case SIGABRT:
     case SIGTERM:
     case SIGINT:
       log(LOG_NOTICE,"Catching signal %d, exiting cleanly.", the_signal);
@@ -644,7 +647,7 @@ int main(int argc, char *argv[]) {
   int retval = 0;
 
   signal (SIGINT, catch); /* catch kills so we can exit cleanly */
-  signal (SIGABRT, catch);
+//  signal (SIGABRT, catch);
   signal (SIGTERM, catch);
   signal (SIGUSR1, catch); /* to dump stats to stdout */
   signal (SIGHUP, catch); /* to reload directory */

src/or/or.h

@@ -130,8 +130,8 @@
 /* default cipher function */
 #define ONION_DEFAULT_CIPHER ONION_CIPHER_DES
 
-#define RECEIVE_WINDOW_START 100
-#define RECEIVE_WINDOW_INCREMENT 10
+#define RECEIVE_WINDOW_START 1000
+#define RECEIVE_WINDOW_INCREMENT 100
 
 /* cell commands */
 #define CELL_PADDING 0