Keep better statistics about channels and dump them from dumpstats() on SIGUSR1 (917a3c75) · Commits · Legacy / gitolite / user / andrea / Tor

src/or/channel.c

+399 −1

Original line number	Diff line number	Diff line
		@@ -1487,6 +1487,8 @@ channel_write_cell(channel_t chan, cell_t cell)
		channel_timestamp_xmit(chan);
		/* If we're here the queue is empty, so it's drained too */
		channel_timestamp_drained(chan);
		/* Update the counter */
		++(chan->u.cell_chan.n_cells_xmitted);
		}
		}

		@@ -1545,6 +1547,8 @@ channel_write_packed_cell(channel_t chan, packed_cell_t packed_cell)
		channel_timestamp_xmit(chan);
		/* If we're here the queue is empty, so it's drained too */
		channel_timestamp_drained(chan);
		/* Update the counter */
		++(chan->u.cell_chan.n_cells_xmitted);
		}
		}

		@@ -1608,6 +1612,8 @@ channel_write_var_cell(channel_t chan, var_cell_t var_cell)
		channel_timestamp_xmit(chan);
		/* If we're here the queue is empty, so it's drained too */
		channel_timestamp_drained(chan);
		/* Update the counter */
		++(chan->u.cell_chan.n_cells_xmitted);
		}
		}

		@@ -1882,6 +1888,7 @@ channel_flush_some_cells_from_outgoing_queue(channel_t *chan,
		tor_free(q);
		++flushed;
		channel_timestamp_xmit(chan);
		++(chan->u.cell_chan.n_cells_xmitted);
		}
		/* Else couldn't write it; leave it on the queue */
		} else {
		@@ -1901,6 +1908,7 @@ channel_flush_some_cells_from_outgoing_queue(channel_t *chan,
		tor_free(q);
		++flushed;
		channel_timestamp_xmit(chan);
		++(chan->u.cell_chan.n_cells_xmitted);
		}
		/* Else couldn't write it; leave it on the queue */
		} else {
		@@ -1920,6 +1928,7 @@ channel_flush_some_cells_from_outgoing_queue(channel_t *chan,
		tor_free(q);
		++flushed;
		channel_timestamp_xmit(chan);
		++(chan->u.cell_chan.n_cells_xmitted);
		}
		/* Else couldn't write it; leave it on the queue */
		} else {
		@@ -2178,6 +2187,11 @@ channel_queue_incoming(channel_t listener, channel_t incoming)
		listener->u.listener.incoming_list = smartlist_new();
		}

		/* Bump the counter and timestamp it */
		channel_timestamp_active(listener);
		channel_timestamp_accepted(listener);
		++(listener->u.listener.n_accepted);

		/* If we don't need to queue, process it right away */
		if (!need_to_queue) {
		tor_assert(listener->u.listener.listener);
		@@ -2300,6 +2314,9 @@ channel_queue_cell(channel_t chan, cell_t cell)
		/* Timestamp for receiving */
		channel_timestamp_recv(chan);

		/* Update the counter */
		++(chan->u.cell_chan.n_cells_recved);

		/* If we don't need to queue we can just call cell_handler */
		if (!need_to_queue) {
		tor_assert(chan->u.cell_chan.cell_handler);
		@@ -2359,6 +2376,9 @@ channel_queue_var_cell(channel_t chan, var_cell_t var_cell)
		/* Timestamp for receiving */
		channel_timestamp_recv(chan);

		/* Update the counter */
		++(chan->u.cell_chan.n_cells_recved);

		/* If we don't need to queue we can just call cell_handler */
		if (!need_to_queue) {
		tor_assert(chan->u.cell_chan.var_cell_handler);
		@@ -2415,6 +2435,41 @@ channel_send_destroy(circid_t circ_id, channel_t *chan, int reason)
		return 0;
		}

		/**
		* Channel statistics
		*
		* This is called from dumpstats() in main.c and spams the log with
		* statistics on channels.
		*/

		void
		channel_dumpstats(int severity)
		{
		if (all_channels && smartlist_len(all_channels) > 0) {
		log(severity, LD_GENERAL,
		"Dumping statistics about %d channels:",
		smartlist_len(all_channels));
		log(severity, LD_GENERAL,
		"%d are active, %d are listeners, and %d are done and "
		"waiting for cleanup",
		(active_channels != NULL) ?
		smartlist_len(active_channels) : 0,
		(listening_channels != NULL) ?
		smartlist_len(listening_channels) : 0,
		(finished_channels != NULL) ?
		smartlist_len(finished_channels) : 0);

		SMARTLIST_FOREACH(all_channels, channel_t *, chan,
		channel_dump_statistics(chan, severity));

		log(severity, LD_GENERAL,
		"Done spamming about channels now");
		} else {
		log(severity, LD_GENERAL,
		"No channels to dump");
		}
		}

		/**
		* Channel cleanup
		*
		@@ -2783,6 +2838,265 @@ channel_get_for_extend(const char *digest,
		}
		}

		/**
		* Describe the transport subclass
		*
		* Invoke a method to get a string description of the lower-layer
		* transport for this channel.
		*/

		const char *
		channel_describe_transport(channel_t *chan)
		{
		tor_assert(chan);
		tor_assert(chan->describe_transport);

		return chan->describe_transport(chan);
		}

		/**
		* Dump channel statistics
		*
		* Dump statistics for one channel to the log
		*/

		void
		channel_dump_statistics(channel_t *chan, int severity)
		{
		double avg, interval, age;
		time_t now = time(NULL);
		tor_addr_t remote_addr;
		int have_remote_addr;
		char *remote_addr_str;

		tor_assert(chan);

		age = (double)(now - chan->timestamp_created);

		log(severity, LD_GENERAL,
		"Channel %lu (at %p) with transport %s is in state %s (%d) and %s",
		chan->global_identifier, chan,
		channel_describe_transport(chan),
		channel_state_to_string(chan->state), chan->state,
		chan->is_listener ?
		"listens for incoming connections" :
		"transports cells");
		log(severity, LD_GENERAL,
		" * Channel %lu was created at %lu (%lu seconds ago) and last active "
		"at %lu (%lu seconds ago)",
		chan->global_identifier,
		chan->timestamp_created, now - chan->timestamp_created,
		chan->timestamp_active, now - chan->timestamp_active);
		if (chan->is_listener) {
		log(severity, LD_GENERAL,
		" * Listener channel %lu last accepted an incoming channel at %lu "
		"(%lu seconds ago) and has accepted %lu channels in total",
		chan->global_identifier,
		chan->u.listener.timestamp_accepted,
		now - chan->u.listener.timestamp_accepted,
		chan->u.listener.n_accepted);

		/*
		* If it's sensible to do so, get the rate of incoming channels on this
		* listener
		*/
		if (now > chan->timestamp_created &&
		chan->timestamp_created > 0 &&
		chan->u.listener.n_accepted > 0) {
		avg = (double)(chan->u.listener.n_accepted) / age;
		if (avg >= 1.0) {
		log(severity, LD_GENERAL,
		" * Listener channel %lu has averaged %f incoming channels per "
		"second",
		chan->global_identifier, avg);
		} else if (avg >= 0.0) {
		interval = 1.0 / avg;
		log(severity, LD_GENERAL,
		" * Listener channel %lu has averaged %f seconds between "
		"incoming channels",
		chan->global_identifier, interval);
		}
		}
		} else {
		/* Handle digest and nickname */
		if (!tor_digest_is_zero(chan->u.cell_chan.identity_digest)) {
		if (chan->u.cell_chan.nickname) {
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu says it is connected to an OR "
		"with digest %s and nickname %s",
		chan->global_identifier,
		hex_str(chan->u.cell_chan.identity_digest, DIGEST_LEN),
		chan->u.cell_chan.nickname);
		} else {
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu says it is connected to an OR "
		"with digest %s and no known nickname",
		chan->global_identifier,
		hex_str(chan->u.cell_chan.identity_digest, DIGEST_LEN));
		}
		} else {
		if (chan->u.cell_chan.nickname) {
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu does not know the digest of the "
		"OR it is connected to, but reports its nickname is %s",
		chan->global_identifier,
		chan->u.cell_chan.nickname);
		} else {
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu does not know the digest or the "
		"nickname of the OR it is connected to",
		chan->global_identifier);
		}
		}

		/* Handle remote address and descriptions */
		have_remote_addr = channel_get_addr_if_possible(chan, &remote_addr);
		if (have_remote_addr) {
		remote_addr_str = tor_dup_addr(&remote_addr);
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu says its remote address is %s, "
		"and gives a canonical description of \"%s\" and an "
		"actual description of \"%s\"",
		chan->global_identifier,
		remote_addr_str,
		channel_get_canonical_remote_descr(chan),
		channel_get_actual_remote_descr(chan));
		tor_free(remote_addr_str);
		} else {
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu does not know its remote address, "
		"but gives a canonical description of \"%s\" and an "
		"actual description of \"%s\"",
		chan->global_identifier,
		channel_get_canonical_remote_descr(chan),
		channel_get_actual_remote_descr(chan));
		}

		/* Handle marks */
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu has these marks: %s %s %s "
		"%s %s %s",
		chan->global_identifier,
		channel_is_bad_for_new_circs(chan) ?
		"bad_for_new_circs" : "!bad_for_new_circs",
		channel_is_canonical(chan) ?
		"canonical" : "!canonical",
		channel_is_canonical_is_reliable(chan) ?
		"is_canonical_is_reliable" :
		"!is_canonical_is_reliable",
		channel_is_client(chan) ?
		"client" : "!client",
		channel_is_local(chan) ?
		"local" : "!local",
		channel_is_incoming(chan) ?
		"incoming" : "outgoing");

		/* Describe queues */
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu has %d queued incoming cells "
		"and %d queued outgoing cells",
		chan->global_identifier,
		(chan->u.cell_chan.cell_queue != NULL) ?
		smartlist_len(chan->u.cell_chan.cell_queue) : 0,
		(chan->u.cell_chan.outgoing_queue != NULL) ?
		smartlist_len(chan->u.cell_chan.outgoing_queue) : 0);

		/* Describe circuits */
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu has %d active circuits out of %d"
		" in total",
		chan->global_identifier,
		(chan->u.cell_chan.active_circuit_pqueue != NULL) ?
		smartlist_len(chan->u.cell_chan.active_circuit_pqueue) : 0,
		chan->u.cell_chan.n_circuits);
		/* TODO better circuit info once circuit structure refactor is finished */

		/* Describe timestamps */
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu was last used by a client at %lu "
		"(%lu seconds ago)",
		chan->global_identifier,
		chan->u.cell_chan.timestamp_client,
		now - chan->u.cell_chan.timestamp_client);
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu was last drained at %lu "
		"(%lu seconds ago)",
		chan->global_identifier,
		chan->u.cell_chan.timestamp_drained,
		now - chan->u.cell_chan.timestamp_drained);
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu last received a cell at %lu "
		"(%lu seconds ago)",
		chan->global_identifier,
		chan->u.cell_chan.timestamp_recv,
		now - chan->u.cell_chan.timestamp_recv);
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu last trasmitted a cell at %lu "
		"(%lu seconds ago)",
		chan->global_identifier,
		chan->u.cell_chan.timestamp_xmit,
		now - chan->u.cell_chan.timestamp_xmit);

		/* Describe counters and rates */
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu has received %lu cells and "
		" transmitted %lu",
		chan->global_identifier,
		chan->u.cell_chan.n_cells_recved,
		chan->u.cell_chan.n_cells_xmitted);
		if (now > chan->timestamp_created &&
		chan->timestamp_created > 0) {
		if (chan->u.cell_chan.n_cells_recved > 0) {
		avg = (double)(chan->u.cell_chan.n_cells_recved) / age;
		if (avg >= 1.0) {
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu has averaged %f cells received "
		"per second",
		chan->global_identifier, avg);
		} else if (avg >= 0.0) {
		interval = 1.0 / avg;
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu has averaged %f seconds between "
		"received cells",
		chan->global_identifier, interval);
		}
		}
		if (chan->u.cell_chan.n_cells_xmitted > 0) {
		avg = (double)(chan->u.cell_chan.n_cells_xmitted) / age;
		if (avg >= 1.0) {
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu has averaged %f cells transmitted "
		"per second",
		chan->global_identifier, avg);
		} else if (avg >= 0.0) {
		interval = 1.0 / avg;
		log(severity, LD_GENERAL,
		" * Cell-bearing channel %lu has averaged %f seconds between "
		"transmitted cells",
		chan->global_identifier, interval);
		}
		}
		}
		}

		/* Dump anything the lower layer has to say */
		channel_dump_transport_statistics(chan, severity);
		}

		/**
		* Invoke transport-specific stats dump
		*
		* If there is a lower-layer statistics dump method, invoke it
		*/

		void
		channel_dump_transport_statistics(channel_t *chan, int severity)
		{
		tor_assert(chan);

		if (chan->dumpstats) chan->dumpstats(chan, severity);
		}

		/**
		* Return text description of the remote endpoint
		*
		@@ -3137,7 +3451,7 @@ channel_timestamp_created(channel_t *chan)
		/**
		* Update the last active timestamp.
		*
		* This function updates the channe's last active timestamp; it should be
		* This function updates the channel's last active timestamp; it should be
		* called by the lower layer whenever there is activity on the channel which
		* does not lead to a cell being transmitted or received; the active timestamp
		* is also updated from channel_timestamp_recv() and channel_timestamp_xmit(),
		@@ -3157,6 +3471,26 @@ channel_timestamp_active(channel_t *chan)
		chan->timestamp_active = now;
		}

		/**
		* Update the last accepted timestamp.
		*
		* This function updates the channel's last accepted timestamp; it should be
		* called whenever a new incoming channel is accepted on a listener.
		*
		* @param chan Channel to update
		*/

		void
		channel_timestamp_accepted(channel_t *chan)
		{
		time_t now = time(NULL);

		tor_assert(chan);
		tor_assert(chan->is_listener);

		chan->u.listener.timestamp_accepted = now;
		}

		/**
		* Update client timestamp
		*
		@@ -3274,6 +3608,22 @@ channel_when_last_active(channel_t *chan)
		return chan->timestamp_active;
		}

		/**
		* Query last accepted timestamp
		*
		* @param chan Channel to query
		* @return Last accepted timestamp value for chan
		*/

		time_t
		channel_when_last_accepted(channel_t *chan)
		{
		tor_assert(chan);
		tor_assert(chan->is_listener);

		return chan->u.listener.timestamp_accepted;
		}

		/**
		* Query client timestamp
		*
		@@ -3338,6 +3688,54 @@ channel_when_last_xmit(channel_t *chan)
		return chan->u.cell_chan.timestamp_xmit;
		}

		/**
		* Query accepted counter
		*
		* @param chan Channel to query
		* @return Number of incoming channels accepted by this listener
		*/

		uint64_t
		channel_count_accepted(channel_t *chan)
		{
		tor_assert(chan);

		if (chan->is_listener) return chan->u.listener.n_accepted;
		else return 0;
		}

		/**
		* Query received cell counter
		*
		* @param chan Channel to query
		* @return Number of cells received by this channel
		*/

		uint64_t
		channel_count_recved(channel_t *chan)
		{
		tor_assert(chan);

		if (!(chan->is_listener)) return chan->u.cell_chan.n_cells_recved;
		else return 0;
		}

		/**
		* Query transmitted cell counter
		*
		* @param chan Channel to query
		* @return Number of cells transmitted by this channel
		*/

		uint64_t
		channel_count_xmitted(channel_t *chan)
		{
		tor_assert(chan);

		if (!(chan->is_listener)) return chan->u.cell_chan.n_cells_xmitted;
		else return 0;
		}

		/**
		* Check if a channel matches an extend_info_t
		*

src/or/channel.h

+27 −6

Original line number	Diff line number	Diff line
		@@ -57,6 +57,10 @@ struct channel_s {
		void (free)(channel_t );
		/* Close an open channel */
		void (close)(channel_t );
		/* Describe the transport subclass for this channel */
		const char * (describe_transport)(channel_t );
		/* Optional method to dump transport-specific statistics on the channel */
		void (dumpstats)(channel_t , int);

		union {
		struct {
		@@ -65,6 +69,12 @@ struct channel_s {

		/* List of pending incoming connections */
		smartlist_t *incoming_list;

		/* Timestamps for listeners */
		time_t timestamp_accepted;

		/* Counters for listeners */
		uint64_t n_accepted;
		} listener;
		struct {
		/* Registered handlers for incoming cells */
		@@ -127,12 +137,6 @@ struct channel_s {
		/* List of queued outgoing cells */
		smartlist_t *outgoing_queue;

		/*
		* When we last used this conn for any client traffic. If not
		* recent, we can rate limit it further.
		*/
		time_t client_used;

		/* Circuit stuff for use by relay.c */

		/*
		@@ -210,6 +214,10 @@ struct channel_s {
		* come over a circuit_t, which has a dirreq_id field as well, but is a
		* distinct namespace. */
		uint64_t dirreq_id;

		/** Channel counters for cell channels */
		uint64_t n_cells_recved;
		uint64_t n_cells_xmitted;
		} cell_chan;
		} u;
		};
		@@ -257,6 +265,9 @@ void channel_run_cleanup(void);
		/* Close all channels and deallocate everything */
		void channel_free_all(void);

		/* Dump some statistics in the log */
		void channel_dumpstats(int severity);

		#ifdef _TOR_CHANNEL_INTERNAL

		/* Channel operations for subclasses and internal use only */
		@@ -297,6 +308,7 @@ void channel_set_remote_end(channel_t *chan,

		/* Timestamp updates */
		void channel_timestamp_created(channel_t *chan);
		void channel_timestamp_accepted(channel_t *chan);
		void channel_timestamp_active(channel_t *chan);
		void channel_timestamp_drained(channel_t *chan);
		void channel_timestamp_recv(channel_t *chan);
		@@ -368,6 +380,9 @@ channel_t * channel_prev_with_digest(channel_t *chan);
		* Metadata queries/updates
		*/

		const char * channel_describe_transport(channel_t *chan);
		void channel_dump_statistics(channel_t *chan, int severity);
		void channel_dump_transport_statistics(channel_t *chan, int severity);
		const char * channel_get_actual_remote_descr(channel_t *chan);
		int channel_get_addr_if_possible(channel_t chan, tor_addr_t addr_out);
		const char * channel_get_canonical_remote_descr(channel_t *chan);
		@@ -389,11 +404,17 @@ void channel_timestamp_client(channel_t *chan);

		/* Timestamp queries */
		time_t channel_when_created(channel_t *chan);
		time_t channel_when_last_accepted(channel_t *chan);
		time_t channel_when_last_active(channel_t *chan);
		time_t channel_when_last_client(channel_t *chan);
		time_t channel_when_last_drained(channel_t *chan);
		time_t channel_when_last_recv(channel_t *chan);
		time_t channel_when_last_xmit(channel_t *chan);

		/* Counter queries */
		uint64_t channel_count_accepted(channel_t *chan);
		uint64_t channel_count_recved(channel_t *chan);
		uint64_t channel_count_xmitted(channel_t *chan);

		#endif

src/or/channeltls.c

+43 −0

Original line number	Diff line number	Diff line
		@@ -47,6 +47,7 @@ channel_tls_t *channel_tls_listener = NULL;
		/* channel_tls_t method declarations */

		static void channel_tls_close_method(channel_t *chan);
		static const char * channel_tls_describe_transport_method(channel_t *chan);
		static int
		channel_tls_get_remote_addr_method(channel_t chan, tor_addr_t addr_out);
		static const char *
		@@ -104,6 +105,7 @@ channel_tls_connect(const tor_addr_t *addr, uint16_t port,
		channel_init_for_cells(chan);
		chan->state = CHANNEL_STATE_OPENING;
		chan->close = channel_tls_close_method;
		chan->describe_transport = channel_tls_describe_transport_method;
		chan->u.cell_chan.get_remote_addr = channel_tls_get_remote_addr_method;
		chan->u.cell_chan.get_remote_descr = channel_tls_get_remote_descr_method;
		chan->u.cell_chan.has_queued_writes = channel_tls_has_queued_writes_method;
		@@ -188,12 +190,15 @@ channel_tls_start_listener(void)
		channel_init_listener(lchan);
		lchan->state = CHANNEL_STATE_LISTENING;
		lchan->close = channel_tls_close_method;
		lchan->describe_transport = channel_tls_describe_transport_method;

		channel_tls_listener = listener;

		log_debug(LD_CHANNEL,
		"Starting TLS listener channel %p with global id %lu",
		lchan, lchan->global_identifier);

		channel_register(lchan);
		} else lchan = TLS_CHAN_TO_BASE(channel_tls_listener);

		return lchan;
		@@ -245,6 +250,7 @@ channel_tls_handle_incoming(or_connection_t *orconn)
		channel_init_for_cells(chan);
		chan->state = CHANNEL_STATE_OPENING;
		chan->close = channel_tls_close_method;
		chan->describe_transport = channel_tls_describe_transport_method;
		chan->u.cell_chan.get_remote_descr = channel_tls_get_remote_descr_method;
		chan->u.cell_chan.has_queued_writes = channel_tls_has_queued_writes_method;
		chan->u.cell_chan.is_canonical = channel_tls_is_canonical_method;
		@@ -334,6 +340,43 @@ channel_tls_close_method(channel_t *chan)
		}
		}

		/**
		* Describe the transport for a channel_tls_t
		*
		* This returns the string "TLS channel on connection <id>" to the upper
		* layer.
		*/

		static const char *
		channel_tls_describe_transport_method(channel_t *chan)
		{
		static char *buf = NULL;
		uint64_t id;
		channel_tls_t *tlschan;
		const char *rv = NULL;

		tor_assert(chan);

		if (chan->is_listener) {
		rv = "TLS channel (listening)";
		} else {
		tlschan = BASE_CHAN_TO_TLS(chan);

		if (tlschan->conn) {
		id = TO_CONN(tlschan->conn)->global_identifier;

		if (buf) tor_free(buf);
		tor_asprintf(&buf, "TLS channel (connection %lu)", id);

		rv = buf;
		} else {
		rv = "TLS channel (no connection)";
		}
		}

		return rv;
		}

		/**
		* Get the remote address of a channel_tls_t
		*

src/or/main.c

+3 −1

Original line number	Diff line number	Diff line
		@@ -2166,10 +2166,12 @@ dumpstats(int severity)
		}
		}
		}
		/* TODO add dump for channels with circuit_dump_by_chan() */
		circuit_dump_by_conn(conn, severity); /* dump info about all the circuits
		* using this conn */
		} SMARTLIST_FOREACH_END(conn);

		channel_dumpstats(severity);

		log(severity, LD_NET,
		"Cells processed: "U64_FORMAT" padding\n"
		" "U64_FORMAT" create\n"