commit c386d2d6ce4c4f58163acb385c7a5de1da8c5e30 Author: Karsten Loesing karsten.loesing@gmx.net Date: Wed Feb 6 14:37:38 2013 +0100
Add new CELL_STATS event.
Jointly authored with Rob Jansen jansen@cs.umn.edu. --- src/or/control.c | 165 +++++++++++++++++++++++++++++++++++++++++++++++++++++- src/or/control.h | 1 + src/or/main.c | 1 + src/or/or.h | 36 ++++++++++++ src/or/relay.c | 97 ++++++++++++++++++++++++++++---- src/or/relay.h | 3 +- 6 files changed, 290 insertions(+), 13 deletions(-)
diff --git a/src/or/control.c b/src/or/control.c index 0a49c29..6625877 100644 --- a/src/or/control.c +++ b/src/or/control.c @@ -83,7 +83,8 @@ #define EVENT_SIGNAL 0x0018 #define EVENT_CONF_CHANGED 0x0019 #define EVENT_CONN_BW 0x001A -#define EVENT_MAX_ 0x001A +#define EVENT_CELL_STATS 0x001B +#define EVENT_MAX_ 0x001B /* If EVENT_MAX_ ever hits 0x0020, we need to make the mask wider. */
/** Bitfield: The bit 1<<e is set if <b>any</b> open control @@ -960,6 +961,7 @@ static const struct control_event_t control_event_table[] = { { EVENT_SIGNAL, "SIGNAL" }, { EVENT_CONF_CHANGED, "CONF_CHANGED"}, { EVENT_CONN_BW, "CONN_BW" }, + { EVENT_CELL_STATS, "CELL_STATS" }, { 0, NULL }, };
@@ -3956,6 +3958,167 @@ control_event_conn_bandwidth_used(void) return 0; }
+extern circuit_t *global_circuitlist; + +/** Convert the cell <b>command</b> into a lower-case, human-readable + * string. */ +static const char * +cell_command_to_string(uint8_t command) +{ + switch (command) { + case CELL_PADDING: return "padding"; + case CELL_CREATE: return "create"; + case CELL_CREATED: return "created"; + case CELL_RELAY: return "relay"; + case CELL_DESTROY: return "destroy"; + case CELL_CREATE_FAST: return "create_fast"; + case CELL_CREATED_FAST: return "created_fast"; + case CELL_VERSIONS: return "versions"; + case CELL_NETINFO: return "netinfo"; + case CELL_RELAY_EARLY: return "relay_early"; + case CELL_CREATE2: return "create2"; + case CELL_CREATED2: return "created2"; + case CELL_VPADDING: return "vpadding"; + case CELL_CERTS: return "certs"; + case CELL_AUTH_CHALLENGE: return "auth_challenge"; + case CELL_AUTHENTICATE: return "authenticate"; + case CELL_AUTHORIZE: return "authorize"; + default: return "unrecognized"; + } +} + +/** Helper: append a cell statistics string to <code>event_parts</code>, + * prefixed with <code>key</code>=. Statistics consist of comma-separated + * key:value pairs with lower-case command strings as keys and cell + * numbers or total waiting times as values. A key:value pair is included + * if the entry in <code>include_if_positive</code> is positive, but with + * the (possibly zero) entry from <code>number_to_include</code>. If no + * entry in <code>include_if_positive</code> is positive, no string will + * be added to <code>event_parts</code>. */ +static void +append_cell_stats_by_command(smartlist_t *event_parts, const char *key, + uint64_t *include_if_positive, + uint64_t *number_to_include) +{ + smartlist_t *key_value_strings = smartlist_new(); + int i; + for (i = 0; i <= CELL_MAX_; i++) { + if (include_if_positive[i] > 0) { + smartlist_add_asprintf(key_value_strings, "%s:"U64_FORMAT, + cell_command_to_string(i), + U64_PRINTF_ARG(number_to_include[i])); + } + } + if (key_value_strings->num_used > 0) { + char *joined = smartlist_join_strings(key_value_strings, ",", 0, NULL); + char *result; + tor_asprintf(&result, "%s=%s", key, joined); + smartlist_add(event_parts, result); + SMARTLIST_FOREACH(key_value_strings, char *, cp, tor_free(cp)); + tor_free(joined); + } + smartlist_free(key_value_strings); +} + +/** A second or more has elapsed: tell any interested control connection + * how many cells have been processed for a given circuit. */ +int +control_event_circuit_cell_stats(void) +{ + /* These arrays temporarily consume slightly over 6 KiB on the stack + * every second, most of which are wasted for the non-existant commands + * between CELL_RELAY_EARLY (9) and CELL_VPADDING (128). But nothing + * beats the stack when it comes to performance. */ + uint64_t added_cells_appward[CELL_MAX_ + 1], + added_cells_exitward[CELL_MAX_ + 1], + removed_cells_appward[CELL_MAX_ + 1], + removed_cells_exitward[CELL_MAX_ + 1], + total_time_appward[CELL_MAX_ + 1], + total_time_exitward[CELL_MAX_ + 1]; + circuit_t *circ; + if (!get_options()->TestingTorNetwork || + !EVENT_IS_INTERESTING(EVENT_CELL_STATS)) + return 0; + for (circ = global_circuitlist; circ; circ = circ->next) { + smartlist_t *event_parts; + char *event_string; + + if (!circ->testing_cell_stats) + continue; + + memset(added_cells_appward, 0, (CELL_MAX_ + 1) * sizeof(uint64_t)); + memset(added_cells_exitward, 0, (CELL_MAX_ + 1) * sizeof(uint64_t)); + memset(removed_cells_appward, 0, (CELL_MAX_ + 1) * sizeof(uint64_t)); + memset(removed_cells_exitward, 0, (CELL_MAX_ + 1) * sizeof(uint64_t)); + memset(total_time_appward, 0, (CELL_MAX_ + 1) * sizeof(uint64_t)); + memset(total_time_exitward, 0, (CELL_MAX_ + 1) * sizeof(uint64_t)); + SMARTLIST_FOREACH_BEGIN(circ->testing_cell_stats, + testing_cell_stats_entry_t *, ent) { + tor_assert(ent->command <= CELL_MAX_); + if (!ent->removed && !ent->exit_ward) { + added_cells_appward[ent->command] += 1; + } else if (!ent->removed && ent->exit_ward) { + added_cells_exitward[ent->command] += 1; + } else if (!ent->exit_ward) { + removed_cells_appward[ent->command] += 1; + total_time_appward[ent->command] += ent->waiting_time * 10; + } else { + removed_cells_exitward[ent->command] += 1; + total_time_exitward[ent->command] += ent->waiting_time * 10; + } + tor_free(ent); + } SMARTLIST_FOREACH_END(ent); + smartlist_free(circ->testing_cell_stats); + circ->testing_cell_stats = NULL; + + event_parts = smartlist_new(); + if (CIRCUIT_IS_ORIGIN(circ)) { + origin_circuit_t *ocirc = TO_ORIGIN_CIRCUIT(circ); + char *id_string; + tor_asprintf(&id_string, "ID=%lu", + (unsigned long)ocirc->global_identifier); + smartlist_add(event_parts, id_string); + } else { + or_circuit_t *or_circ = TO_OR_CIRCUIT(circ); + char *queue_string, *conn_string; + tor_asprintf(&queue_string, "InboundQueue=%lu", + (unsigned long)or_circ->p_circ_id); + tor_asprintf(&conn_string, "InboundConn="U64_FORMAT, + U64_PRINTF_ARG(or_circ->p_chan->global_identifier)); + smartlist_add(event_parts, queue_string); + smartlist_add(event_parts, conn_string); + append_cell_stats_by_command(event_parts, "InboundAdded", + added_cells_appward, added_cells_appward); + append_cell_stats_by_command(event_parts, "InboundRemoved", + removed_cells_appward, removed_cells_appward); + append_cell_stats_by_command(event_parts, "InboundTime", + removed_cells_appward, total_time_appward); + } + if (circ->n_chan) { + char *queue_string, *conn_string; + tor_asprintf(&queue_string, "OutboundQueue=%lu", + (unsigned long)circ->n_circ_id); + tor_asprintf(&conn_string, "OutboundConn="U64_FORMAT, + U64_PRINTF_ARG(circ->n_chan->global_identifier)); + smartlist_add(event_parts, queue_string); + smartlist_add(event_parts, conn_string); + append_cell_stats_by_command(event_parts, "OutboundAdded", + added_cells_exitward, added_cells_exitward); + append_cell_stats_by_command(event_parts, "OutboundRemoved", + removed_cells_exitward, removed_cells_exitward); + append_cell_stats_by_command(event_parts, "OutboundTime", + removed_cells_exitward, total_time_exitward); + } + event_string = smartlist_join_strings(event_parts, " ", 0, NULL); + send_control_event(EVENT_CELL_STATS, ALL_FORMATS, + "650 CELL_STATS %s\r\n", event_string); + SMARTLIST_FOREACH(event_parts, char *, cp, tor_free(cp)); + smartlist_free(event_parts); + tor_free(event_string); + } + return 0; +} + /** A second or more has elapsed: tell any interested control * connections how much bandwidth we used. */ int diff --git a/src/or/control.h b/src/or/control.h index fe5c0ef..4d950bf 100644 --- a/src/or/control.h +++ b/src/or/control.h @@ -52,6 +52,7 @@ int control_event_stream_bandwidth(edge_connection_t *edge_conn); int control_event_stream_bandwidth_used(void); int control_event_conn_bandwidth(connection_t *conn); int control_event_conn_bandwidth_used(void); +int control_event_circuit_cell_stats(void); void control_event_logmsg(int severity, uint32_t domain, const char *msg); int control_event_descriptors_changed(smartlist_t *routers); int control_event_address_mapped(const char *from, const char *to, diff --git a/src/or/main.c b/src/or/main.c index c145f9d..ae60548 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -1641,6 +1641,7 @@ second_elapsed_callback(periodic_timer_t *timer, void *arg) control_event_bandwidth_used((uint32_t)bytes_read,(uint32_t)bytes_written); control_event_stream_bandwidth_used(); control_event_conn_bandwidth_used(); + control_event_circuit_cell_stats();
if (server_mode(options) && !net_is_disabled() && diff --git a/src/or/or.h b/src/or/or.h index 08a94aa..22e4b96 100644 --- a/src/or/or.h +++ b/src/or/or.h @@ -839,6 +839,7 @@ typedef enum { #define CELL_AUTH_CHALLENGE 130 #define CELL_AUTHENTICATE 131 #define CELL_AUTHORIZE 132 +#define CELL_MAX_ 132
/** How long to test reachability before complaining to the user. */ #define TIMEOUT_UNTIL_UNREACHABILITY_COMPLAINT (20*60) @@ -1087,6 +1088,21 @@ typedef struct insertion_time_queue_t { struct insertion_time_elem_t *last; /**< Last element in queue. */ } insertion_time_queue_t;
+/** Number of cells with the same command consecutively added to a circuit + * queue; used for cell statistics only in TestingTorNetwork mode. */ +typedef struct insertion_command_elem_t { + struct insertion_command_elem_t *next; /**< Next element in queue. */ + /** Which command did these consecutively added cells have? */ + uint8_t command; + unsigned counter; /**< How many cells were inserted? */ +} insertion_command_elem_t; + +/** Queue of insertion commands. */ +typedef struct insertion_command_queue_t { + struct insertion_command_elem_t *first; /**< First element in queue. */ + struct insertion_command_elem_t *last; /**< Last element in queue. */ +} insertion_command_queue_t; + /** A queue of cells on a circuit, waiting to be added to the * or_connection_t's outbuf. */ typedef struct cell_queue_t { @@ -1094,6 +1110,8 @@ typedef struct cell_queue_t { packed_cell_t *tail; /**< The last cell, or NULL if the queue is empty. */ int n; /**< The number of cells in the queue. */ insertion_time_queue_t *insertion_times; /**< Insertion times of cells. */ + /** Commands of inserted cells. */ + insertion_command_queue_t *insertion_commands; } cell_queue_t;
/** Beginning of a RELAY cell payload. */ @@ -2730,6 +2748,19 @@ typedef struct {
struct create_cell_t;
+/** Entry in the cell stats list of a circuit; used only when + * TestingTorNetwork is set. */ +typedef struct testing_cell_stats_entry_t { + uint8_t command; /**< cell command number. */ + /** Waiting time in centiseconds if this event is for a removed cell, + * or 0 if this event is for adding a cell to the queue. 22 bits can + * store more than 11 hours, enough to assume that a circuit with this + * delay would long have been closed. */ + unsigned int waiting_time:22; + unsigned int removed:1; /**< 0 for added to, 1 for removed from queue. */ + unsigned int exit_ward:1; /**< 0 for app-ward, 1 for exit-ward. */ +} testing_cell_stats_entry_t; + /** * A circuit is a path over the onion routing * network. Applications can connect to one end of the circuit, and can @@ -2855,6 +2886,11 @@ typedef struct circuit_t { * cells to n_conn. NULL if we have no cells pending, or if we're not * linked to an OR connection. */ struct circuit_t *prev_active_on_n_chan; + + /** Various statistics about cells being added to or removed from this + * circuit's queues; used only when TestingTorNetwork is set and cleared + * after being sent to control port. */ + smartlist_t *testing_cell_stats; } circuit_t;
/** Largest number of relay_early cells that we can send on a given diff --git a/src/or/relay.c b/src/or/relay.c index 52ff32f..02b3b1c 100644 --- a/src/or/relay.c +++ b/src/or/relay.c @@ -2045,6 +2045,10 @@ static mp_pool_t *cell_pool = NULL; * statistics. */ static mp_pool_t *it_pool = NULL;
+/** Memory pool to allocate insertion_command_elem_t objects used for cell + * statistics in TestingTorNetwork mode. */ +static mp_pool_t *ic_pool = NULL; + /** Allocate structures to hold cells. */ void init_cell_pool(void) @@ -2053,8 +2057,8 @@ init_cell_pool(void) cell_pool = mp_pool_new(sizeof(packed_cell_t), 128*1024); }
-/** Free all storage used to hold cells (and insertion times if we measure - * cell statistics). */ +/** Free all storage used to hold cells (and insertion times/commands if we + * measure cell statistics and/or are in TestingTorNetwork mode). */ void free_cell_pool(void) { @@ -2067,6 +2071,10 @@ free_cell_pool(void) mp_pool_destroy(it_pool); it_pool = NULL; } + if (ic_pool) { + mp_pool_destroy(ic_pool); + ic_pool = NULL; + } }
/** Free excess storage in cell pool. */ @@ -2145,14 +2153,16 @@ cell_queue_append(cell_queue_t *queue, packed_cell_t *cell) ++queue->n; }
-/** Append a newly allocated copy of <b>cell</b> to the end of <b>queue</b> */ +/** Append a newly allocated copy of <b>cell</b> to the end of the + * <b>exit_ward</b> (or app-ward) <b>queue</b> of <b>circ</b>. */ void -cell_queue_append_packed_copy(cell_queue_t *queue, const cell_t *cell, +cell_queue_append_packed_copy(circuit_t *circ, cell_queue_t *queue, + int exit_ward, const cell_t *cell, int wide_circ_ids) { packed_cell_t *copy = packed_cell_copy(cell, wide_circ_ids); /* Remember the time when this cell was put in the queue. */ - if (get_options()->CellStatistics) { + if (get_options()->CellStatistics || get_options()->TestingTorNetwork) { struct timeval now; uint32_t added; insertion_time_queue_t *it_queue = queue->insertion_times; @@ -2181,6 +2191,38 @@ cell_queue_append_packed_copy(cell_queue_t *queue, const cell_t *cell, } } } + /* Remember that we added a cell to the queue, and remember the cell + * command. */ + if (get_options()->TestingTorNetwork) { + insertion_command_queue_t *ic_queue = queue->insertion_commands; + testing_cell_stats_entry_t *ent = + tor_malloc_zero(sizeof(testing_cell_stats_entry_t)); + ent->command = cell->command; + ent->exit_ward = exit_ward; + if (!circ->testing_cell_stats) + circ->testing_cell_stats = smartlist_new(); + smartlist_add(circ->testing_cell_stats, ent); + if (!ic_pool) + ic_pool = mp_pool_new(sizeof(insertion_command_elem_t), 1024); + if (!ic_queue) { + ic_queue = tor_malloc_zero(sizeof(insertion_command_queue_t)); + queue->insertion_commands = ic_queue; + } + if (ic_queue->last && ic_queue->last->command == cell->command) { + ic_queue->last->counter++; + } else { + insertion_command_elem_t *elem = mp_pool_get(ic_pool); + elem->next = NULL; + elem->command = cell->command; + elem->counter = 1; + if (ic_queue->last) { + ic_queue->last->next = elem; + ic_queue->last = elem; + } else { + ic_queue->first = ic_queue->last = elem; + } + } + } cell_queue_append(queue, copy); }
@@ -2386,7 +2428,8 @@ channel_flush_from_first_active_circuit(channel_t *chan, int max) cell = cell_queue_pop(queue);
/* Calculate the exact time that this cell has spent in the queue. */ - if (get_options()->CellStatistics && !CIRCUIT_IS_ORIGIN(circ)) { + if (get_options()->CellStatistics || + get_options()->TestingTorNetwork) { struct timeval tvnow; uint32_t flushed; uint32_t cell_waiting_time; @@ -2400,7 +2443,6 @@ channel_flush_from_first_active_circuit(channel_t *chan, int max) "recently enabled."); } else { insertion_time_elem_t *elem = it_queue->first; - or_circ = TO_OR_CIRCUIT(circ); cell_waiting_time = (uint32_t)((flushed * 10L + SECONDS_IN_A_DAY * 1000L - elem->insertion_time * 10L) % @@ -2413,8 +2455,38 @@ channel_flush_from_first_active_circuit(channel_t *chan, int max) it_queue->last = NULL; mp_pool_release(elem); } - or_circ->total_cell_waiting_time += cell_waiting_time; - or_circ->processed_cells++; + if (get_options()->CellStatistics && !CIRCUIT_IS_ORIGIN(circ)) { + or_circ = TO_OR_CIRCUIT(circ); + or_circ->total_cell_waiting_time += cell_waiting_time; + or_circ->processed_cells++; + } + if (get_options()->TestingTorNetwork) { + insertion_command_queue_t *ic_queue = queue->insertion_commands; + if (!ic_queue || !ic_queue->first) { + log_info(LD_BUG, "Cannot determine command of cell, which " + "is a bug, because TestingTorNetwork cannot " + "be enabled while running."); + } else { + testing_cell_stats_entry_t *ent = + tor_malloc_zero(sizeof(testing_cell_stats_entry_t)); + insertion_command_elem_t *ic_elem = ic_queue->first; + ent->command = ic_elem->command; + ic_elem->counter--; + if (ic_elem->counter < 1) { + ic_queue->first = ic_elem->next; + if (ic_elem == ic_queue->last) + ic_queue->last = NULL; + mp_pool_release(ic_elem); + } + ent->waiting_time = (unsigned int)cell_waiting_time / 10; + ent->removed = 1; + if (circ->n_chan == chan) + ent->exit_ward = 1; + if (!circ->testing_cell_stats) + circ->testing_cell_stats = smartlist_new(); + smartlist_add(circ->testing_cell_stats, ent); + } + } } }
@@ -2470,10 +2542,12 @@ append_cell_to_circuit_queue(circuit_t *circ, channel_t *chan, { cell_queue_t *queue; int streams_blocked; + int exit_ward; if (circ->marked_for_close) return;
- if (direction == CELL_DIRECTION_OUT) { + exit_ward = (direction == CELL_DIRECTION_OUT); + if (exit_ward) { queue = &circ->n_chan_cells; streams_blocked = circ->streams_blocked_on_n_chan; } else { @@ -2482,7 +2556,8 @@ append_cell_to_circuit_queue(circuit_t *circ, channel_t *chan, streams_blocked = circ->streams_blocked_on_p_chan; }
- cell_queue_append_packed_copy(queue, cell, chan->wide_circ_ids); + cell_queue_append_packed_copy(circ, queue, exit_ward, cell, + chan->wide_circ_ids);
/* If we have too many cells on the circuit, we should stop reading from * the edge streams for a while. */ diff --git a/src/or/relay.h b/src/or/relay.h index 229fb4f..e3b392c 100644 --- a/src/or/relay.h +++ b/src/or/relay.h @@ -52,7 +52,8 @@ void packed_cell_free(packed_cell_t *cell);
void cell_queue_clear(cell_queue_t *queue); void cell_queue_append(cell_queue_t *queue, packed_cell_t *cell); -void cell_queue_append_packed_copy(cell_queue_t *queue, const cell_t *cell, +void cell_queue_append_packed_copy(circuit_t *circ, cell_queue_t *queue, + int exit_ward, const cell_t *cell, int wide_circ_ids);
void append_cell_to_circuit_queue(circuit_t *circ, channel_t *chan,