[or-cvs] per-second cell statistics to help with profiling
Roger Dingledine
arma at seul.org
Sun Nov 24 08:45:56 UTC 2002
Update of /home/or/cvsroot/src/or
In directory moria.seul.org:/home/arma/work/onion/cvs/src/or
Modified Files:
command.c main.c or.h
Log Message:
per-second cell statistics to help with profiling
Index: command.c
===================================================================
RCS file: /home/or/cvsroot/src/or/command.c,v
retrieving revision 1.13
retrieving revision 1.14
diff -u -d -r1.13 -r1.14
--- command.c 23 Nov 2002 08:49:03 -0000 1.13
+++ command.c 24 Nov 2002 08:45:54 -0000 1.14
@@ -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 @@
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 @@
/* 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;
Index: main.c
===================================================================
RCS file: /home/or/cvsroot/src/or/main.c,v
retrieving revision 1.34
retrieving revision 1.35
diff -u -d -r1.34 -r1.35
--- main.c 23 Nov 2002 08:49:03 -0000 1.34
+++ main.c 24 Nov 2002 08:45:54 -0000 1.35
@@ -376,6 +376,7 @@
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 @@
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 @@
connection_array[i]->onions_handled_this_second = 0;
}
current_second = now.tv_sec; /* remember which second it is, for next time */
- } 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? */
}
- }
+// } 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 @@
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 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 */
Index: or.h
===================================================================
RCS file: /home/or/cvsroot/src/or/or.h,v
retrieving revision 1.37
retrieving revision 1.38
diff -u -d -r1.37 -r1.38
--- or.h 23 Nov 2002 08:49:03 -0000 1.37
+++ or.h 24 Nov 2002 08:45:54 -0000 1.38
@@ -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
More information about the tor-commits
mailing list