Merge remote-tracking branch 'pastly2/ticket24531_033_01'

This commit is contained in:
Nick Mathewson 2018-01-03 11:56:35 -05:00
commit 943134e886
5 changed files with 61 additions and 73 deletions

3
changes/ticket24531 Normal file
View File

@ -0,0 +1,3 @@
o Code simplification and refactoring:
Add a function to log channels' scheduler state changes to aide debugging
efforts. Closes ticket 24531.

View File

@ -362,6 +362,36 @@ set_scheduler(void)
* Functions that can only be accessed from scheduler*.c
*****************************************************************************/
/** Returns human readable string for the given channel scheduler state. */
const char *
get_scheduler_state_string(int scheduler_state)
{
switch (scheduler_state) {
case SCHED_CHAN_IDLE:
return "IDLE";
case SCHED_CHAN_WAITING_FOR_CELLS:
return "WAITING_FOR_CELLS";
case SCHED_CHAN_WAITING_TO_WRITE:
return "WAITING_TO_WRITE";
case SCHED_CHAN_PENDING:
return "PENDING";
default:
return "(invalid)";
}
}
/** Helper that logs channel scheduler_state changes. Use this instead of
* setting scheduler_state directly. */
void
scheduler_set_channel_state(channel_t *chan, int new_state)
{
log_debug(LD_SCHED, "chan %" PRIu64 " changed from scheduler state %s to %s",
chan->global_identifier,
get_scheduler_state_string(chan->scheduler_state),
get_scheduler_state_string(new_state));
chan->scheduler_state = new_state;
}
/** Return the pending channel list. */
smartlist_t *
get_channels_pending(void)
@ -499,11 +529,7 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan))
scheduler_compare_channels,
offsetof(channel_t, sched_heap_idx),
chan);
chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p went from pending "
"to waiting_to_write",
U64_PRINTF_ARG(chan->global_identifier), chan);
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
} else {
/*
* It's not in pending, so it can't become waiting_to_write; it's
@ -511,10 +537,7 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan))
* waiting_for_cells (remove it, can't write any more).
*/
if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS) {
chan->scheduler_state = SCHED_CHAN_IDLE;
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p left waiting_for_cells",
U64_PRINTF_ARG(chan->global_identifier), chan);
scheduler_set_channel_state(chan, SCHED_CHAN_IDLE);
}
}
}
@ -537,15 +560,11 @@ scheduler_channel_has_waiting_cells,(channel_t *chan))
* the other lists. It has waiting cells now, so it goes to
* channels_pending.
*/
chan->scheduler_state = SCHED_CHAN_PENDING;
scheduler_set_channel_state(chan, SCHED_CHAN_PENDING);
smartlist_pqueue_add(channels_pending,
scheduler_compare_channels,
offsetof(channel_t, sched_heap_idx),
chan);
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p went from waiting_for_cells "
"to pending",
U64_PRINTF_ARG(chan->global_identifier), chan);
/* If we made a channel pending, we potentially have scheduling work to
* do. */
the_scheduler->schedule();
@ -557,10 +576,7 @@ scheduler_channel_has_waiting_cells,(channel_t *chan))
*/
if (!(chan->scheduler_state == SCHED_CHAN_WAITING_TO_WRITE ||
chan->scheduler_state == SCHED_CHAN_PENDING)) {
chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p entered waiting_to_write",
U64_PRINTF_ARG(chan->global_identifier), chan);
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
}
}
}
@ -643,7 +659,7 @@ scheduler_release_channel,(channel_t *chan))
if (the_scheduler->on_channel_free) {
the_scheduler->on_channel_free(chan);
}
chan->scheduler_state = SCHED_CHAN_IDLE;
scheduler_set_channel_state(chan, SCHED_CHAN_IDLE);
}
/** Mark a channel as ready to accept writes */
@ -663,17 +679,11 @@ scheduler_channel_wants_writes(channel_t *chan)
/*
* It can write now, so it goes to channels_pending.
*/
log_debug(LD_SCHED, "chan=%" PRIu64 " became pending",
chan->global_identifier);
smartlist_pqueue_add(channels_pending,
scheduler_compare_channels,
offsetof(channel_t, sched_heap_idx),
chan);
chan->scheduler_state = SCHED_CHAN_PENDING;
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p went from waiting_to_write "
"to pending",
U64_PRINTF_ARG(chan->global_identifier), chan);
scheduler_set_channel_state(chan, SCHED_CHAN_PENDING);
/* We just made a channel pending, we have scheduling work to do. */
the_scheduler->schedule();
} else {
@ -683,10 +693,7 @@ scheduler_channel_wants_writes(channel_t *chan)
*/
if (!(chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS ||
chan->scheduler_state == SCHED_CHAN_PENDING)) {
chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p entered waiting_for_cells",
U64_PRINTF_ARG(chan->global_identifier), chan);
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
}
}
}
@ -703,11 +710,12 @@ scheduler_bug_occurred(const channel_t *chan)
const size_t outbuf_len =
buf_datalen(TO_CONN(BASE_CHAN_TO_TLS((channel_t *) chan)->conn)->outbuf);
tor_snprintf(buf, sizeof(buf),
"Channel %" PRIu64 " in state %s and scheduler state %d."
"Channel %" PRIu64 " in state %s and scheduler state %s."
" Num cells on cmux: %d. Connection outbuf len: %lu.",
chan->global_identifier,
channel_state_to_string(chan->state),
chan->scheduler_state, circuitmux_num_cells(chan->cmux),
get_scheduler_state_string(chan->scheduler_state),
circuitmux_num_cells(chan->cmux),
(unsigned long)outbuf_len);
}

View File

@ -144,6 +144,9 @@ MOCK_DECL(void, scheduler_channel_has_waiting_cells, (channel_t *chan));
* Defined in scheduler.c
*********************************/
void scheduler_set_channel_state(channel_t *chan, int new_state);
const char *get_scheduler_state_string(int scheduler_state);
/* Triggers a BUG() and extra information with chan if available. */
#define SCHED_BUG(cond, chan) \
(PREDICT_UNLIKELY(cond) ? \

View File

@ -624,7 +624,7 @@ kist_scheduler_run(void)
if (!CHANNEL_IS_OPEN(chan)) {
/* Channel isn't open so we put it back in IDLE mode. It is either
* renegotiating its TLS session or about to be released. */
chan->scheduler_state = SCHED_CHAN_IDLE;
scheduler_set_channel_state(chan, SCHED_CHAN_IDLE);
continue;
}
/* flush_result has the # cells flushed */
@ -640,12 +640,12 @@ kist_scheduler_run(void)
log_debug(LD_SCHED,
"We didn't flush anything on a chan that we think "
"can write and wants to write. The channel's state is '%s' "
"and in scheduler state %d. We're going to mark it as "
"and in scheduler state '%s'. We're going to mark it as "
"waiting_for_cells (as that's most likely the issue) and "
"stop scheduling it this round.",
channel_state_to_string(chan->state),
chan->scheduler_state);
chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
get_scheduler_state_string(chan->scheduler_state));
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
continue;
}
}
@ -672,16 +672,12 @@ kist_scheduler_run(void)
* SCHED_CHAN_WAITING_FOR_CELLS to SCHED_CHAN_IDLE and seeing if Tor
* starts having serious throughput issues. Best done in shadow/chutney.
*/
chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_for_cells",
chan->global_identifier);
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
} else if (!channel_more_to_flush(chan)) {
/* Case 2: no more cells to send, but still open for writes */
chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_for_cells",
chan->global_identifier);
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
} else if (!socket_can_write(&socket_table, chan)) {
/* Case 3: cells to send, but cannot write */
@ -693,18 +689,16 @@ kist_scheduler_run(void)
* after the scheduling loop is over. They can hopefully be taken care of
* in the next scheduling round.
*/
chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
if (!to_readd) {
to_readd = smartlist_new();
}
smartlist_add(to_readd, chan);
log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_to_write",
chan->global_identifier);
} else {
/* Case 4: cells to send, and still open for writes */
chan->scheduler_state = SCHED_CHAN_PENDING;
scheduler_set_channel_state(chan, SCHED_CHAN_PENDING);
smartlist_pqueue_add(cp, scheduler_compare_channels,
offsetof(channel_t, sched_heap_idx), chan);
}
@ -724,7 +718,7 @@ kist_scheduler_run(void)
/* Re-add any channels we need to */
if (to_readd) {
SMARTLIST_FOREACH_BEGIN(to_readd, channel_t *, readd_chan) {
readd_chan->scheduler_state = SCHED_CHAN_PENDING;
scheduler_set_channel_state(readd_chan, SCHED_CHAN_PENDING);
if (!smartlist_contains(cp, readd_chan)) {
smartlist_pqueue_add(cp, scheduler_compare_channels,
offsetof(channel_t, sched_heap_idx), readd_chan);

View File

@ -89,12 +89,7 @@ vanilla_scheduler_run(void)
if (flushed < n_cells) {
/* We ran out of cells to flush */
chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p "
"entered waiting_for_cells from pending",
U64_PRINTF_ARG(chan->global_identifier),
chan);
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
} else {
/* The channel may still have some cells */
if (channel_more_to_flush(chan)) {
@ -110,12 +105,7 @@ vanilla_scheduler_run(void)
chan);
} else {
/* It's waiting to be able to write more */
chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p "
"entered waiting_to_write from pending",
U64_PRINTF_ARG(chan->global_identifier),
chan);
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
}
} else {
/* No cells left; it can go to idle or waiting_for_cells */
@ -124,23 +114,13 @@ vanilla_scheduler_run(void)
* It can still accept writes, so it goes to
* waiting_for_cells
*/
chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS;
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p "
"entered waiting_for_cells from pending",
U64_PRINTF_ARG(chan->global_identifier),
chan);
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS);
} else {
/*
* We exactly filled up the output queue with all available
* cells; go to idle.
*/
chan->scheduler_state = SCHED_CHAN_IDLE;
log_debug(LD_SCHED,
"Channel " U64_FORMAT " at %p "
"become idle from pending",
U64_PRINTF_ARG(chan->global_identifier),
chan);
scheduler_set_channel_state(chan, SCHED_CHAN_IDLE);
}
}
}
@ -156,14 +136,14 @@ vanilla_scheduler_run(void)
"no cells writeable",
U64_PRINTF_ARG(chan->global_identifier), chan);
/* Put it back to WAITING_TO_WRITE */
chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE;
scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE);
}
}
/* Readd any channels we need to */
if (to_readd) {
SMARTLIST_FOREACH_BEGIN(to_readd, channel_t *, readd_chan) {
readd_chan->scheduler_state = SCHED_CHAN_PENDING;
scheduler_set_channel_state(readd_chan, SCHED_CHAN_PENDING);
smartlist_pqueue_add(cp,
scheduler_compare_channels,
offsetof(channel_t, sched_heap_idx),