From d77cacb7ab97e876900063f4d7c852a458bdab93 Mon Sep 17 00:00:00 2001 From: ArunaMaurya221B Date: Thu, 7 Dec 2017 19:58:02 +0530 Subject: [PATCH 01/10] Bug:24531 Add function to change scheduler state and always use it --- src/or/scheduler.c | 37 +++++++++++++++++++++---------------- src/or/scheduler.h | 3 +++ 2 files changed, 24 insertions(+), 16 deletions(-) diff --git a/src/or/scheduler.c b/src/or/scheduler.c index cd047d5a75..38b2ee5ef8 100644 --- a/src/or/scheduler.c +++ b/src/or/scheduler.c @@ -361,7 +361,12 @@ set_scheduler(void) * * Functions that can only be accessed from scheduler*.c *****************************************************************************/ +/* Function to log and change all the old and new states*/ +void scheduler_set_channel(chan,new_state){ + log_debug(LD_SCHED, "chan %d changed from scheduler state %d to %d",chan->global_id, chan->scheduler_state, new_state); + chan->scheduler_state = new_state; +} /** Return the pending channel list. */ smartlist_t * get_channels_pending(void) @@ -510,8 +515,8 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan)) * either not in any of the lists (nothing to do) or it's already in * 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; + if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_FOR_CELLS) { + scheduler_set_channel(chan,new_state) = SCHED_CHAN_IDLE; log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p left waiting_for_cells", U64_PRINTF_ARG(chan->global_identifier), chan); @@ -531,13 +536,13 @@ scheduler_channel_has_waiting_cells,(channel_t *chan)) } /* First, check if it's also writeable */ - if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS) { + if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_FOR_CELLS) { /* * It's in channels_waiting_for_cells, so it shouldn't be in any of * the other lists. It has waiting cells now, so it goes to * channels_pending. */ - chan->scheduler_state = SCHED_CHAN_PENDING; + scheduler_set_channel(chan,new_state) = SCHED_CHAN_PENDING; smartlist_pqueue_add(channels_pending, scheduler_compare_channels, offsetof(channel_t, sched_heap_idx), @@ -555,9 +560,9 @@ scheduler_channel_has_waiting_cells,(channel_t *chan)) * either not in any of the lists (we add it to waiting_to_write) * or it's already in waiting_to_write or pending (we do nothing) */ - if (!(chan->scheduler_state == SCHED_CHAN_WAITING_TO_WRITE || - chan->scheduler_state == SCHED_CHAN_PENDING)) { - chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE; + if (!(scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_TO_WRITE || + scheduler_set_channel(chan,new_state) == SCHED_CHAN_PENDING)) { + scheduler_set_channel(chan,new_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); @@ -627,7 +632,7 @@ scheduler_release_channel,(channel_t *chan)) return; } - if (chan->scheduler_state == SCHED_CHAN_PENDING) { + if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_PENDING) { if (SCHED_BUG(smartlist_pos(channels_pending, chan) == -1, chan)) { log_warn(LD_SCHED, "Scheduler asked to release channel %" PRIu64 " " "but it wasn't in channels_pending", @@ -643,7 +648,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(chan,new_state) = SCHED_CHAN_IDLE; } /** Mark a channel as ready to accept writes */ @@ -659,7 +664,7 @@ scheduler_channel_wants_writes(channel_t *chan) } /* If it's already in waiting_to_write, we can put it in pending */ - if (chan->scheduler_state == SCHED_CHAN_WAITING_TO_WRITE) { + if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_TO_WRITE) { /* * It can write now, so it goes to channels_pending. */ @@ -669,7 +674,7 @@ scheduler_channel_wants_writes(channel_t *chan) scheduler_compare_channels, offsetof(channel_t, sched_heap_idx), chan); - chan->scheduler_state = SCHED_CHAN_PENDING; + scheduler_set_channel(chan,new_state) = SCHED_CHAN_PENDING; log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p went from waiting_to_write " "to pending", @@ -681,9 +686,9 @@ scheduler_channel_wants_writes(channel_t *chan) * It's not in SCHED_CHAN_WAITING_TO_WRITE, so it can't become pending; * it's either idle and goes to WAITING_FOR_CELLS, or it's a no-op. */ - if (!(chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS || - chan->scheduler_state == SCHED_CHAN_PENDING)) { - chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS; + if (!(scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_FOR_CELLS || + scheduler_set_channel(chan,new_state) == SCHED_CHAN_PENDING)) { + scheduler_set_channel(chan,new_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); @@ -707,7 +712,7 @@ scheduler_bug_occurred(const channel_t *chan) " 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), + scheduler_set_channel(chan,new_state), circuitmux_num_cells(chan->cmux), (unsigned long)outbuf_len); } @@ -740,7 +745,7 @@ scheduler_touch_channel(channel_t *chan) return; } - if (chan->scheduler_state == SCHED_CHAN_PENDING) { + if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_PENDING) { /* Remove and re-add it */ smartlist_pqueue_remove(channels_pending, scheduler_compare_channels, diff --git a/src/or/scheduler.h b/src/or/scheduler.h index 47c98f096a..b2d05166a4 100644 --- a/src/or/scheduler.h +++ b/src/or/scheduler.h @@ -143,6 +143,9 @@ MOCK_DECL(void, scheduler_channel_has_waiting_cells, (channel_t *chan)); /********************************* * Defined in scheduler.c *********************************/ +/* Function to log and change all the old and new states*/ + +void scheduler_set_channel(chan,new_state); /* Triggers a BUG() and extra information with chan if available. */ #define SCHED_BUG(cond, chan) \ From ad5cfa30396fcbf8e60806594a1a59fd411bc325 Mon Sep 17 00:00:00 2001 From: ArunaMaurya221B Date: Fri, 8 Dec 2017 16:48:27 +0530 Subject: [PATCH 02/10] Bug:24531 Function to change channel scheduler state for easy debugging added. --- src/or/scheduler.c | 41 +++++++++++++++++++++-------------------- src/or/scheduler.h | 2 +- 2 files changed, 22 insertions(+), 21 deletions(-) diff --git a/src/or/scheduler.c b/src/or/scheduler.c index 38b2ee5ef8..36aa6ba921 100644 --- a/src/or/scheduler.c +++ b/src/or/scheduler.c @@ -363,8 +363,8 @@ set_scheduler(void) *****************************************************************************/ /* Function to log and change all the old and new states*/ -void scheduler_set_channel(chan,new_state){ - log_debug(LD_SCHED, "chan %d changed from scheduler state %d to %d",chan->global_id, chan->scheduler_state, new_state); +void scheduler_set_channel_state(channel_t *chan,int new_state){ + log_debug(LD_SCHED, "chan %s changed from scheduler state %d to %d",chan->global_identifier, chan->scheduler_state, new_state); chan->scheduler_state = new_state; } /** Return the pending channel list. */ @@ -494,7 +494,7 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan)) } /* If it's already in pending, we can put it in waiting_to_write */ - if (chan->scheduler_state == SCHED_CHAN_PENDING) { + if (chan->scheduler_state == SCHED_CHAN_PENDING){ /* * It's in channels_pending, so it shouldn't be in any of * the other lists. It can't write any more, so it goes to @@ -504,7 +504,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; + scheduler_set_channel_state(chan,SCHED_CHAN_WAITING_TO_WRITE); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p went from pending " "to waiting_to_write", @@ -515,8 +515,8 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan)) * either not in any of the lists (nothing to do) or it's already in * waiting_for_cells (remove it, can't write any more). */ - if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_FOR_CELLS) { - scheduler_set_channel(chan,new_state) = SCHED_CHAN_IDLE; + if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS){ + scheduler_set_channel_state(chan,SCHED_CHAN_IDLE); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p left waiting_for_cells", U64_PRINTF_ARG(chan->global_identifier), chan); @@ -536,13 +536,13 @@ scheduler_channel_has_waiting_cells,(channel_t *chan)) } /* First, check if it's also writeable */ - if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_FOR_CELLS) { + if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS){ /* * It's in channels_waiting_for_cells, so it shouldn't be in any of * the other lists. It has waiting cells now, so it goes to * channels_pending. */ - scheduler_set_channel(chan,new_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), @@ -560,9 +560,9 @@ scheduler_channel_has_waiting_cells,(channel_t *chan)) * either not in any of the lists (we add it to waiting_to_write) * or it's already in waiting_to_write or pending (we do nothing) */ - if (!(scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_TO_WRITE || - scheduler_set_channel(chan,new_state) == SCHED_CHAN_PENDING)) { - scheduler_set_channel(chan,new_state) = SCHED_CHAN_WAITING_TO_WRITE; + if (!(chan->scheduler_state == SCHED_CHAN_WAITING_TO_WRITE || + chan->scheduler_state== SCHED_CHAN_PENDING)) { + scheduler_set_channel_state(chan, 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); @@ -632,7 +632,7 @@ scheduler_release_channel,(channel_t *chan)) return; } - if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_PENDING) { + if (chan->scheduler_state == SCHED_CHAN_PENDING) { if (SCHED_BUG(smartlist_pos(channels_pending, chan) == -1, chan)) { log_warn(LD_SCHED, "Scheduler asked to release channel %" PRIu64 " " "but it wasn't in channels_pending", @@ -648,7 +648,7 @@ scheduler_release_channel,(channel_t *chan)) if (the_scheduler->on_channel_free) { the_scheduler->on_channel_free(chan); } - scheduler_set_channel(chan,new_state) = SCHED_CHAN_IDLE; + scheduler_set_channel_state(chan,SCHED_CHAN_IDLE); } /** Mark a channel as ready to accept writes */ @@ -664,7 +664,7 @@ scheduler_channel_wants_writes(channel_t *chan) } /* If it's already in waiting_to_write, we can put it in pending */ - if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_TO_WRITE) { + if (chan->scheduler_state == SCHED_CHAN_WAITING_TO_WRITE) { /* * It can write now, so it goes to channels_pending. */ @@ -674,7 +674,7 @@ scheduler_channel_wants_writes(channel_t *chan) scheduler_compare_channels, offsetof(channel_t, sched_heap_idx), chan); - scheduler_set_channel(chan,new_state) = SCHED_CHAN_PENDING; + scheduler_set_channel_state(chan,SCHED_CHAN_PENDING); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p went from waiting_to_write " "to pending", @@ -686,9 +686,9 @@ scheduler_channel_wants_writes(channel_t *chan) * It's not in SCHED_CHAN_WAITING_TO_WRITE, so it can't become pending; * it's either idle and goes to WAITING_FOR_CELLS, or it's a no-op. */ - if (!(scheduler_set_channel(chan,new_state) == SCHED_CHAN_WAITING_FOR_CELLS || - scheduler_set_channel(chan,new_state) == SCHED_CHAN_PENDING)) { - scheduler_set_channel(chan,new_state) = SCHED_CHAN_WAITING_FOR_CELLS; + if (!(chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS || + chan->scheduler_state == SCHED_CHAN_PENDING)) { + scheduler_set_channel_state(chan, 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); @@ -705,6 +705,7 @@ scheduler_bug_occurred(const channel_t *chan) char buf[128]; if (chan != NULL) { + int new_state=0; const size_t outbuf_len = buf_datalen(TO_CONN(BASE_CHAN_TO_TLS((channel_t *) chan)->conn)->outbuf); tor_snprintf(buf, sizeof(buf), @@ -712,7 +713,7 @@ scheduler_bug_occurred(const channel_t *chan) " Num cells on cmux: %d. Connection outbuf len: %lu.", chan->global_identifier, channel_state_to_string(chan->state), - scheduler_set_channel(chan,new_state), circuitmux_num_cells(chan->cmux), + chan->scheduler_state, circuitmux_num_cells(chan->cmux), (unsigned long)outbuf_len); } @@ -745,7 +746,7 @@ scheduler_touch_channel(channel_t *chan) return; } - if (scheduler_set_channel(chan,new_state) == SCHED_CHAN_PENDING) { + if (chan->scheduler_state == SCHED_CHAN_PENDING) { /* Remove and re-add it */ smartlist_pqueue_remove(channels_pending, scheduler_compare_channels, diff --git a/src/or/scheduler.h b/src/or/scheduler.h index b2d05166a4..2c2559f2c9 100644 --- a/src/or/scheduler.h +++ b/src/or/scheduler.h @@ -145,7 +145,7 @@ MOCK_DECL(void, scheduler_channel_has_waiting_cells, (channel_t *chan)); *********************************/ /* Function to log and change all the old and new states*/ -void scheduler_set_channel(chan,new_state); +void scheduler_set_channel_state(channel_t *chan,int new_state); /* Triggers a BUG() and extra information with chan if available. */ #define SCHED_BUG(cond, chan) \ From 5e7fdb8b3f397c8f9b1cecacf07a6bacf0d47e2d Mon Sep 17 00:00:00 2001 From: Matt Traudt Date: Mon, 11 Dec 2017 08:56:03 -0500 Subject: [PATCH 03/10] Fix cosmetic issues around scheduler_set_channel_state Whitespace issues Line length Unused variable --- src/or/scheduler.c | 28 +++++++++++++++------------- src/or/scheduler.h | 3 +-- 2 files changed, 16 insertions(+), 15 deletions(-) diff --git a/src/or/scheduler.c b/src/or/scheduler.c index 36aa6ba921..1d51550f9f 100644 --- a/src/or/scheduler.c +++ b/src/or/scheduler.c @@ -361,12 +361,15 @@ set_scheduler(void) * * Functions that can only be accessed from scheduler*.c *****************************************************************************/ -/* Function to log and change all the old and new states*/ -void scheduler_set_channel_state(channel_t *chan,int new_state){ - log_debug(LD_SCHED, "chan %s changed from scheduler state %d to %d",chan->global_identifier, chan->scheduler_state, new_state); +/** 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 %s changed from scheduler state %d to %d", + chan->global_identifier, chan->scheduler_state, new_state); chan->scheduler_state = new_state; } + /** Return the pending channel list. */ smartlist_t * get_channels_pending(void) @@ -494,7 +497,7 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan)) } /* If it's already in pending, we can put it in waiting_to_write */ - if (chan->scheduler_state == SCHED_CHAN_PENDING){ + if (chan->scheduler_state == SCHED_CHAN_PENDING) { /* * It's in channels_pending, so it shouldn't be in any of * the other lists. It can't write any more, so it goes to @@ -504,7 +507,7 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan)) scheduler_compare_channels, offsetof(channel_t, sched_heap_idx), chan); - scheduler_set_channel_state(chan,SCHED_CHAN_WAITING_TO_WRITE); + scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p went from pending " "to waiting_to_write", @@ -515,8 +518,8 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan)) * either not in any of the lists (nothing to do) or it's already in * waiting_for_cells (remove it, can't write any more). */ - if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS){ - scheduler_set_channel_state(chan,SCHED_CHAN_IDLE); + if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS) { + scheduler_set_channel_state(chan, SCHED_CHAN_IDLE); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p left waiting_for_cells", U64_PRINTF_ARG(chan->global_identifier), chan); @@ -536,13 +539,13 @@ scheduler_channel_has_waiting_cells,(channel_t *chan)) } /* First, check if it's also writeable */ - if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS){ + if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS) { /* * It's in channels_waiting_for_cells, so it shouldn't be in any of * the other lists. It has waiting cells now, so it goes to * channels_pending. */ - scheduler_set_channel_state(chan,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), @@ -561,7 +564,7 @@ scheduler_channel_has_waiting_cells,(channel_t *chan)) * or it's already in waiting_to_write or pending (we do nothing) */ if (!(chan->scheduler_state == SCHED_CHAN_WAITING_TO_WRITE || - chan->scheduler_state== SCHED_CHAN_PENDING)) { + chan->scheduler_state == SCHED_CHAN_PENDING)) { scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p entered waiting_to_write", @@ -648,7 +651,7 @@ scheduler_release_channel,(channel_t *chan)) if (the_scheduler->on_channel_free) { the_scheduler->on_channel_free(chan); } - scheduler_set_channel_state(chan,SCHED_CHAN_IDLE); + scheduler_set_channel_state(chan, SCHED_CHAN_IDLE); } /** Mark a channel as ready to accept writes */ @@ -674,7 +677,7 @@ scheduler_channel_wants_writes(channel_t *chan) scheduler_compare_channels, offsetof(channel_t, sched_heap_idx), chan); - scheduler_set_channel_state(chan,SCHED_CHAN_PENDING); + scheduler_set_channel_state(chan, SCHED_CHAN_PENDING); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p went from waiting_to_write " "to pending", @@ -705,7 +708,6 @@ scheduler_bug_occurred(const channel_t *chan) char buf[128]; if (chan != NULL) { - int new_state=0; const size_t outbuf_len = buf_datalen(TO_CONN(BASE_CHAN_TO_TLS((channel_t *) chan)->conn)->outbuf); tor_snprintf(buf, sizeof(buf), diff --git a/src/or/scheduler.h b/src/or/scheduler.h index 2c2559f2c9..da212c50c5 100644 --- a/src/or/scheduler.h +++ b/src/or/scheduler.h @@ -143,9 +143,8 @@ MOCK_DECL(void, scheduler_channel_has_waiting_cells, (channel_t *chan)); /********************************* * Defined in scheduler.c *********************************/ -/* Function to log and change all the old and new states*/ -void scheduler_set_channel_state(channel_t *chan,int new_state); +void scheduler_set_channel_state(channel_t *chan, int new_state); /* Triggers a BUG() and extra information with chan if available. */ #define SCHED_BUG(cond, chan) \ From 273325e216ff10b2ce938b243122d08f075f7881 Mon Sep 17 00:00:00 2001 From: Matt Traudt Date: Mon, 11 Dec 2017 09:03:16 -0500 Subject: [PATCH 04/10] Add all the missed scheduler_state assignments --- src/or/scheduler_kist.c | 14 +++++++------- src/or/scheduler_vanilla.c | 12 ++++++------ 2 files changed, 13 insertions(+), 13 deletions(-) diff --git a/src/or/scheduler_kist.c b/src/or/scheduler_kist.c index e02926e478..6a5b8d4f41 100644 --- a/src/or/scheduler_kist.c +++ b/src/or/scheduler_kist.c @@ -611,7 +611,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 */ @@ -632,7 +632,7 @@ kist_scheduler_run(void) "stop scheduling it this round.", channel_state_to_string(chan->state), chan->scheduler_state); - chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS; + scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS); continue; } } @@ -659,14 +659,14 @@ 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; + scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS); log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_for_cells", chan->global_identifier); } 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; + scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS); log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_for_cells", chan->global_identifier); } else if (!socket_can_write(&socket_table, chan)) { @@ -680,7 +680,7 @@ 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(); } @@ -691,7 +691,7 @@ kist_scheduler_run(void) /* 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); } @@ -711,7 +711,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); diff --git a/src/or/scheduler_vanilla.c b/src/or/scheduler_vanilla.c index 303b3dbba8..64655c0243 100644 --- a/src/or/scheduler_vanilla.c +++ b/src/or/scheduler_vanilla.c @@ -89,7 +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; + scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p " "entered waiting_for_cells from pending", @@ -110,7 +110,7 @@ vanilla_scheduler_run(void) chan); } else { /* It's waiting to be able to write more */ - chan->scheduler_state = SCHED_CHAN_WAITING_TO_WRITE; + scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_TO_WRITE); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p " "entered waiting_to_write from pending", @@ -124,7 +124,7 @@ vanilla_scheduler_run(void) * It can still accept writes, so it goes to * waiting_for_cells */ - chan->scheduler_state = SCHED_CHAN_WAITING_FOR_CELLS; + scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p " "entered waiting_for_cells from pending", @@ -135,7 +135,7 @@ vanilla_scheduler_run(void) * We exactly filled up the output queue with all available * cells; go to idle. */ - chan->scheduler_state = SCHED_CHAN_IDLE; + scheduler_set_channel_state(chan, SCHED_CHAN_IDLE); log_debug(LD_SCHED, "Channel " U64_FORMAT " at %p " "become idle from pending", @@ -156,14 +156,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), From 07898fb2a66b9cbfbfb015750b10ef0316258452 Mon Sep 17 00:00:00 2001 From: Matt Traudt Date: Mon, 11 Dec 2017 09:12:24 -0500 Subject: [PATCH 05/10] Helper to log chan scheduler_states as strings not ints --- src/or/scheduler.c | 24 ++++++++++++++++++++++-- 1 file changed, 22 insertions(+), 2 deletions(-) diff --git a/src/or/scheduler.c b/src/or/scheduler.c index 1d51550f9f..42d9c9f081 100644 --- a/src/or/scheduler.c +++ b/src/or/scheduler.c @@ -198,6 +198,24 @@ get_scheduler_type_string(scheduler_types_t type) } } +/** Returns human readable string for the given channel scheduler state. */ +static 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)"; + } +} + /** * Scheduler event callback; this should get triggered once per event loop * if any scheduling work was created during the event loop. @@ -365,8 +383,10 @@ set_scheduler(void) /** 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 %s changed from scheduler state %d to %d", - chan->global_identifier, chan->scheduler_state, 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; } From 8797c8fbd34132f462be4a4544270ee1b8a071cf Mon Sep 17 00:00:00 2001 From: Matt Traudt Date: Mon, 11 Dec 2017 09:20:54 -0500 Subject: [PATCH 06/10] Remove now-duplicate log_debug lines --- src/or/scheduler.c | 23 ----------------------- src/or/scheduler_kist.c | 6 ------ src/or/scheduler_vanilla.c | 20 -------------------- 3 files changed, 49 deletions(-) diff --git a/src/or/scheduler.c b/src/or/scheduler.c index 42d9c9f081..1b6d160b84 100644 --- a/src/or/scheduler.c +++ b/src/or/scheduler.c @@ -528,10 +528,6 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan)) offsetof(channel_t, sched_heap_idx), chan); scheduler_set_channel_state(chan, 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); } else { /* * It's not in pending, so it can't become waiting_to_write; it's @@ -540,9 +536,6 @@ scheduler_channel_doesnt_want_writes,(channel_t *chan)) */ if (chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS) { scheduler_set_channel_state(chan, SCHED_CHAN_IDLE); - log_debug(LD_SCHED, - "Channel " U64_FORMAT " at %p left waiting_for_cells", - U64_PRINTF_ARG(chan->global_identifier), chan); } } } @@ -570,10 +563,6 @@ scheduler_channel_has_waiting_cells,(channel_t *chan)) 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(); @@ -586,9 +575,6 @@ scheduler_channel_has_waiting_cells,(channel_t *chan)) if (!(chan->scheduler_state == SCHED_CHAN_WAITING_TO_WRITE || chan->scheduler_state == SCHED_CHAN_PENDING)) { scheduler_set_channel_state(chan, 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); } } } @@ -691,17 +677,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); scheduler_set_channel_state(chan, 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); /* We just made a channel pending, we have scheduling work to do. */ the_scheduler->schedule(); } else { @@ -712,9 +692,6 @@ scheduler_channel_wants_writes(channel_t *chan) if (!(chan->scheduler_state == SCHED_CHAN_WAITING_FOR_CELLS || chan->scheduler_state == SCHED_CHAN_PENDING)) { scheduler_set_channel_state(chan, 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); } } } diff --git a/src/or/scheduler_kist.c b/src/or/scheduler_kist.c index 6a5b8d4f41..5e0e8be45c 100644 --- a/src/or/scheduler_kist.c +++ b/src/or/scheduler_kist.c @@ -660,15 +660,11 @@ kist_scheduler_run(void) * starts having serious throughput issues. Best done in shadow/chutney. */ scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS); - log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_for_cells", - chan->global_identifier); } else if (!channel_more_to_flush(chan)) { /* Case 2: no more cells to send, but still open for writes */ scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS); - log_debug(LD_SCHED, "chan=%" PRIu64 " now waiting_for_cells", - chan->global_identifier); } else if (!socket_can_write(&socket_table, chan)) { /* Case 3: cells to send, but cannot write */ @@ -685,8 +681,6 @@ kist_scheduler_run(void) 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 */ diff --git a/src/or/scheduler_vanilla.c b/src/or/scheduler_vanilla.c index 64655c0243..7a83b9da18 100644 --- a/src/or/scheduler_vanilla.c +++ b/src/or/scheduler_vanilla.c @@ -90,11 +90,6 @@ vanilla_scheduler_run(void) if (flushed < n_cells) { /* We ran out of cells to flush */ scheduler_set_channel_state(chan, 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); } else { /* The channel may still have some cells */ if (channel_more_to_flush(chan)) { @@ -111,11 +106,6 @@ vanilla_scheduler_run(void) } else { /* It's waiting to be able to write more */ scheduler_set_channel_state(chan, 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); } } else { /* No cells left; it can go to idle or waiting_for_cells */ @@ -125,22 +115,12 @@ vanilla_scheduler_run(void) * waiting_for_cells */ scheduler_set_channel_state(chan, 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); } else { /* * We exactly filled up the output queue with all available * cells; go to idle. */ scheduler_set_channel_state(chan, SCHED_CHAN_IDLE); - log_debug(LD_SCHED, - "Channel " U64_FORMAT " at %p " - "become idle from pending", - U64_PRINTF_ARG(chan->global_identifier), - chan); } } } From 667f9311776af65f7546a70c8ad5c27e0d23a02b Mon Sep 17 00:00:00 2001 From: Matt Traudt Date: Mon, 11 Dec 2017 09:32:47 -0500 Subject: [PATCH 07/10] Make get_scheduler_state_string available to scheduler*.c --- src/or/scheduler.c | 36 ++++++++++++++++++------------------ src/or/scheduler.h | 1 + src/or/scheduler_kist.c | 4 ++-- 3 files changed, 21 insertions(+), 20 deletions(-) diff --git a/src/or/scheduler.c b/src/or/scheduler.c index 1b6d160b84..09e8894a41 100644 --- a/src/or/scheduler.c +++ b/src/or/scheduler.c @@ -198,24 +198,6 @@ get_scheduler_type_string(scheduler_types_t type) } } -/** Returns human readable string for the given channel scheduler state. */ -static 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)"; - } -} - /** * Scheduler event callback; this should get triggered once per event loop * if any scheduling work was created during the event loop. @@ -380,6 +362,24 @@ 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){ diff --git a/src/or/scheduler.h b/src/or/scheduler.h index da212c50c5..ac405c21b7 100644 --- a/src/or/scheduler.h +++ b/src/or/scheduler.h @@ -145,6 +145,7 @@ MOCK_DECL(void, scheduler_channel_has_waiting_cells, (channel_t *chan)); *********************************/ 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) \ diff --git a/src/or/scheduler_kist.c b/src/or/scheduler_kist.c index 5e0e8be45c..f3e6243a86 100644 --- a/src/or/scheduler_kist.c +++ b/src/or/scheduler_kist.c @@ -627,11 +627,11 @@ 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); + get_scheduler_state_string(chan->scheduler_state)); scheduler_set_channel_state(chan, SCHED_CHAN_WAITING_FOR_CELLS); continue; } From 67793b615b581b23ff8b49ab560801b59039695a Mon Sep 17 00:00:00 2001 From: Matt Traudt Date: Mon, 11 Dec 2017 09:33:07 -0500 Subject: [PATCH 08/10] One more missed chance to use get_scheduler_state_string --- src/or/scheduler.c | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/or/scheduler.c b/src/or/scheduler.c index 09e8894a41..c42c567f9c 100644 --- a/src/or/scheduler.c +++ b/src/or/scheduler.c @@ -708,11 +708,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); } From 265b8e8645c36a4be9391c66ac4b7c4da3e2b59e Mon Sep 17 00:00:00 2001 From: Matt Traudt Date: Mon, 11 Dec 2017 09:36:20 -0500 Subject: [PATCH 09/10] Function declaration whitespace --- src/or/scheduler.c | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/or/scheduler.c b/src/or/scheduler.c index c42c567f9c..058efc7bee 100644 --- a/src/or/scheduler.c +++ b/src/or/scheduler.c @@ -382,7 +382,9 @@ get_scheduler_state_string(int scheduler_state) /** 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){ +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), From d4c7bd98accb6999a95997c8a4df678d79a05f8f Mon Sep 17 00:00:00 2001 From: Matt Traudt Date: Mon, 11 Dec 2017 10:30:37 -0500 Subject: [PATCH 10/10] Add changes file for 24531 --- changes/ticket24531 | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 changes/ticket24531 diff --git a/changes/ticket24531 b/changes/ticket24531 new file mode 100644 index 0000000000..96a8eea5c3 --- /dev/null +++ b/changes/ticket24531 @@ -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.