commit 219c969d7bf858c4df5fc6ee9b0c472a525b6b2a Author: Nick Mathewson <nickm@torproject.org> Date: Wed Dec 13 09:34:20 2017 -0500 Use monotime_coarse for transfer times and padding times Using absolute_msec requires a 64-bit division operation every time we calculate it, which gets expensive on 32-bit architectures. Instead, just use the lazy "monotime_coarse_get()" operation, and don't convert to milliseconds until we absolutely must. In this case, it seemed fine to use a full monotime_coarse_t rather than a truncated "stamp" as we did to solve this problem for the timerstamps in buf_t and packed_cell_t: There are vastly more cells and buffer chunks than there are channels, and using 16 bytes per channel in the worst case is not a big deal. There are still more millisecond operations here than strictly necessary; let's see any divisions show up in profiles. --- changes/bug24613 | 4 ++ src/or/channel.c | 12 ++--- src/or/channel.h | 11 ++-- src/or/channelpadding.c | 54 +++++++++++--------- src/test/test_channel.c | 6 +-- src/test/test_channelpadding.c | 112 ++++++++++++++++++++++++++--------------- 6 files changed, 118 insertions(+), 81 deletions(-) diff --git a/changes/bug24613 b/changes/bug24613 new file mode 100644 index 000000000..d718f8f94 --- /dev/null +++ b/changes/bug24613 @@ -0,0 +1,4 @@ + o Minor features (performance, 32-bit): + - Improve performance on 32-bit systems by avoiding 64-bit division + to calculate the current timestamp in milliseconds for channel + padding computations. Implements ticket 24613. diff --git a/src/or/channel.c b/src/or/channel.c index 7fa976817..845fc3cb4 100644 --- a/src/or/channel.c +++ b/src/or/channel.c @@ -3241,12 +3241,12 @@ channel_timestamp_active(channel_t *chan) time_t now = time(NULL); tor_assert(chan); - chan->timestamp_xfer_ms = monotime_coarse_absolute_msec(); + monotime_coarse_get(&chan->timestamp_xfer); chan->timestamp_active = now; /* Clear any potential netflow padding timer. We're active */ - chan->next_padding_time_ms = 0; + monotime_coarse_zero(&chan->next_padding_time); } /** @@ -3311,13 +3311,13 @@ channel_timestamp_recv(channel_t *chan) { time_t now = time(NULL); tor_assert(chan); - chan->timestamp_xfer_ms = monotime_coarse_absolute_msec(); + monotime_coarse_get(&chan->timestamp_xfer); chan->timestamp_active = now; chan->timestamp_recv = now; /* Clear any potential netflow padding timer. We're active */ - chan->next_padding_time_ms = 0; + monotime_coarse_zero(&chan->next_padding_time); } /** @@ -3332,13 +3332,13 @@ channel_timestamp_xmit(channel_t *chan) time_t now = time(NULL); tor_assert(chan); - chan->timestamp_xfer_ms = monotime_coarse_absolute_msec(); + monotime_coarse_get(&chan->timestamp_xfer); chan->timestamp_active = now; chan->timestamp_xmit = now; /* Clear any potential netflow padding timer. We're active */ - chan->next_padding_time_ms = 0; + monotime_coarse_zero(&chan->next_padding_time); } /*************************************************************** diff --git a/src/or/channel.h b/src/or/channel.h index 0f685011a..4b60b7a7d 100644 --- a/src/or/channel.h +++ b/src/or/channel.h @@ -88,10 +88,9 @@ struct channel_s { * Used to decide what channels to pad, and when. */ channel_usage_info_t channel_usage; - /** When should we send a cell for netflow padding, in absolute - * milliseconds since monotime system start. 0 means no padding - * is scheduled. */ - uint64_t next_padding_time_ms; + /** When should we send a cell for netflow padding? 0 means no padding is + * scheduled. */ + monotime_coarse_t next_padding_time; /** The callback pointer for the padding callbacks */ tor_timer_t *padding_timer; @@ -158,7 +157,7 @@ struct channel_s { time_t timestamp_active; /* Any activity */ /** - * This is a high-resolution monotonic timestamp that marks when we + * This is a monotonic timestamp that marks when we * believe the channel has actually sent or received data to/from * the wire. Right now, it is used to determine when we should send * a padding cell for channelpadding. @@ -167,7 +166,7 @@ struct channel_s { * accurately reflect actual network data transfer? Or might this be * very wrong wrt when bytes actually go on the wire? */ - uint64_t timestamp_xfer_ms; + monotime_coarse_t timestamp_xfer; /* Methods implemented by the lower layer */ diff --git a/src/or/channelpadding.c b/src/or/channelpadding.c index 435436c45..70a906d23 100644 --- a/src/or/channelpadding.c +++ b/src/or/channelpadding.c @@ -23,7 +23,8 @@ #include <event2/event.h> #include "rendservice.h" -STATIC int channelpadding_get_netflow_inactive_timeout_ms(const channel_t *); +STATIC int32_t channelpadding_get_netflow_inactive_timeout_ms( + const channel_t *); STATIC int channelpadding_send_disable_command(channel_t *); STATIC int64_t channelpadding_compute_time_until_pad_for_netflow(channel_t *); @@ -165,7 +166,7 @@ channelpadding_new_consensus_params(networkstatus_t *ns) * Returns the next timeout period (in milliseconds) after which we should * send a padding packet, or 0 if padding is disabled. */ -STATIC int +STATIC int32_t channelpadding_get_netflow_inactive_timeout_ms(const channel_t *chan) { int low_timeout = consensus_nf_ito_low; @@ -377,15 +378,16 @@ channelpadding_send_padding_cell_for_callback(channel_t *chan) chan->pending_padding_callback = 0; - if (!chan->next_padding_time_ms || + if (monotime_coarse_is_zero(&chan->next_padding_time) || chan->has_queued_writes(chan)) { /* We must have been active before the timer fired */ - chan->next_padding_time_ms = 0; + monotime_coarse_zero(&chan->next_padding_time); return; } { - uint64_t now = monotime_coarse_absolute_msec(); + monotime_coarse_t now; + monotime_coarse_get(&now); log_fn(LOG_INFO,LD_OR, "Sending netflow keepalive on "U64_FORMAT" to %s (%s) after " @@ -393,12 +395,13 @@ channelpadding_send_padding_cell_for_callback(channel_t *chan) U64_PRINTF_ARG(chan->global_identifier), safe_str_client(chan->get_remote_descr(chan, 0)), safe_str_client(hex_str(chan->identity_digest, DIGEST_LEN)), - U64_PRINTF_ARG(now - chan->timestamp_xfer_ms), - U64_PRINTF_ARG(now - chan->next_padding_time_ms)); + I64_PRINTF_ARG(monotime_coarse_diff_msec(&chan->timestamp_xfer,&now)), + I64_PRINTF_ARG( + monotime_coarse_diff_msec(&chan->next_padding_time,&now))); } /* Clear the timer */ - chan->next_padding_time_ms = 0; + monotime_coarse_zero(&chan->next_padding_time); /* Send the padding cell. This will cause the channel to get a * fresh timestamp_active */ @@ -500,38 +503,42 @@ channelpadding_schedule_padding(channel_t *chan, int in_ms) STATIC int64_t channelpadding_compute_time_until_pad_for_netflow(channel_t *chan) { - uint64_t long_now = monotime_coarse_absolute_msec(); + monotime_coarse_t now; + monotime_coarse_get(&now); - if (!chan->next_padding_time_ms) { + if (monotime_coarse_is_zero(&chan->next_padding_time)) { /* If the below line or crypto_rand_int() shows up on a profile, * we can avoid getting a timeout until we're at least nf_ito_lo * from a timeout window. That will prevent us from setting timers * on connections that were active up to 1.5 seconds ago. * Idle connections should only call this once every 5.5s on average * though, so that might be a micro-optimization for little gain. */ - int64_t padding_timeout = + int32_t padding_timeout = channelpadding_get_netflow_inactive_timeout_ms(chan); if (!padding_timeout) return CHANNELPADDING_TIME_DISABLED; - chan->next_padding_time_ms = padding_timeout - + chan->timestamp_xfer_ms; + monotime_coarse_add_msec(&chan->next_padding_time, + &chan->timestamp_xfer, + padding_timeout); } + const int64_t ms_till_pad = + monotime_coarse_diff_msec(&now, &chan->next_padding_time); + /* If the next padding time is beyond the maximum possible consensus value, * then this indicates a clock jump, so just send padding now. This is * better than using monotonic time because we want to avoid the situation * where we wait around forever for monotonic time to move forward after * a clock jump far into the past. */ - if (chan->next_padding_time_ms > long_now + - DFLT_NETFLOW_INACTIVE_KEEPALIVE_MAX) { + if (ms_till_pad > DFLT_NETFLOW_INACTIVE_KEEPALIVE_MAX) { tor_fragile_assert(); log_warn(LD_BUG, "Channel padding timeout scheduled "I64_FORMAT"ms in the future. " "Did the monotonic clock just jump?", - I64_PRINTF_ARG(chan->next_padding_time_ms - long_now)); + I64_PRINTF_ARG(ms_till_pad)); return 0; /* Clock jumped: Send padding now */ } @@ -540,11 +547,8 @@ channelpadding_compute_time_until_pad_for_netflow(channel_t *chan) from now which we should send padding, so we can schedule a callback then. */ - if (long_now + - (TOR_HOUSEKEEPING_CALLBACK_MSEC + TOR_HOUSEKEEPING_CALLBACK_SLACK_MSEC) - >= chan->next_padding_time_ms) { - int64_t ms_until_pad_for_netflow = chan->next_padding_time_ms - - long_now; + if (ms_till_pad < (TOR_HOUSEKEEPING_CALLBACK_MSEC + + TOR_HOUSEKEEPING_CALLBACK_SLACK_MSEC)) { /* If the padding time is in the past, that means that libevent delayed * calling the once-per-second callback due to other work taking too long. * See https://bugs.torproject.org/22212 and @@ -554,16 +558,16 @@ channelpadding_compute_time_until_pad_for_netflow(channel_t *chan) * and allowed a router to emit a netflow frame, just so we don't forget * about it entirely.. */ #define NETFLOW_MISSED_WINDOW (150000 - DFLT_NETFLOW_INACTIVE_KEEPALIVE_HIGH) - if (ms_until_pad_for_netflow < 0) { - int severity = (ms_until_pad_for_netflow < -NETFLOW_MISSED_WINDOW) + if (ms_till_pad < 0) { + int severity = (ms_till_pad < -NETFLOW_MISSED_WINDOW) ? LOG_NOTICE : LOG_INFO; log_fn(severity, LD_OR, "Channel padding timeout scheduled "I64_FORMAT"ms in the past. ", - I64_PRINTF_ARG(-ms_until_pad_for_netflow)); + I64_PRINTF_ARG(-ms_till_pad)); return 0; /* Clock jumped: Send padding now */ } - return ms_until_pad_for_netflow; + return ms_till_pad; } return CHANNELPADDING_TIME_LATER; } diff --git a/src/test/test_channel.c b/src/test/test_channel.c index 55d43a04e..425c93f42 100644 --- a/src/test/test_channel.c +++ b/src/test/test_channel.c @@ -703,7 +703,7 @@ test_channel_inbound_cell(void *arg) old_count = test_chan_fixed_cells_recved; channel_process_cell(chan, cell); tt_int_op(test_chan_fixed_cells_recved, OP_EQ, old_count); - tt_u64_op(chan->timestamp_xfer_ms, OP_EQ, 0); + tt_assert(monotime_coarse_is_zero(&chan->timestamp_xfer)); tt_u64_op(chan->timestamp_active, OP_EQ, 0); tt_u64_op(chan->timestamp_recv, OP_EQ, 0); @@ -716,10 +716,10 @@ test_channel_inbound_cell(void *arg) channel_process_cell(chan, cell); tt_int_op(test_chan_fixed_cells_recved, OP_EQ, old_count + 1); /* We should have a series of timestamp set. */ - tt_u64_op(chan->timestamp_xfer_ms, OP_NE, 0); + tt_assert(!monotime_coarse_is_zero(&chan->timestamp_xfer)); tt_u64_op(chan->timestamp_active, OP_NE, 0); tt_u64_op(chan->timestamp_recv, OP_NE, 0); - tt_u64_op(chan->next_padding_time_ms, OP_EQ, 0); + tt_assert(monotime_is_zero(&chan->next_padding_time)); tt_u64_op(chan->n_cells_recved, OP_EQ, 1); tt_u64_op(chan->n_bytes_recved, OP_EQ, get_cell_network_size(0)); diff --git a/src/test/test_channelpadding.c b/src/test/test_channelpadding.c index 4346ee343..4cc33cbe7 100644 --- a/src/test/test_channelpadding.c +++ b/src/test/test_channelpadding.c @@ -279,7 +279,6 @@ test_channelpadding_timers(void *arg) { channelpadding_decision_t decision; channel_t *chans[CHANNELS_TO_TEST]; - int64_t new_time; (void)arg; tor_libevent_postfork(); @@ -289,8 +288,9 @@ test_channelpadding_timers(void *arg) monotime_init(); monotime_enable_test_mocking(); - monotime_set_mock_time_nsec(1); - monotime_coarse_set_mock_time_nsec(1); + uint64_t nsec_mock = 1; + monotime_set_mock_time_nsec(nsec_mock); + monotime_coarse_set_mock_time_nsec(nsec_mock); timers_initialize(); channelpadding_new_consensus_params(NULL); @@ -304,11 +304,14 @@ test_channelpadding_timers(void *arg) tried_to_write_cell = 0; int i = 0; + monotime_coarse_t now; + monotime_coarse_get(&now); + /* This loop fills our timerslot array with timers of increasing time * until they fire */ for (; i < CHANNELPADDING_MAX_TIMERS; i++) { - chans[i]->next_padding_time_ms = monotime_coarse_absolute_msec() - + 10 + i*4; + monotime_coarse_add_msec(&chans[i]->next_padding_time, + &now, 10 + i*4); decision = channelpadding_decide_to_pad_channel(chans[i]); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(chans[i]->pending_padding_callback); @@ -318,7 +321,8 @@ test_channelpadding_timers(void *arg) /* This loop should add timers to the first position in the timerslot * array, since its timeout is before all other timers. */ for (; i < CHANNELS_TO_TEST/3; i++) { - chans[i]->next_padding_time_ms = monotime_coarse_absolute_msec() + 1; + monotime_coarse_add_msec(&chans[i]->next_padding_time, + &now, 1); decision = channelpadding_decide_to_pad_channel(chans[i]); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(chans[i]->pending_padding_callback); @@ -329,8 +333,8 @@ test_channelpadding_timers(void *arg) * pseudorandom pattern. It ensures that the lists can grow with multiple * timers in them. */ for (; i < CHANNELS_TO_TEST/2; i++) { - chans[i]->next_padding_time_ms = monotime_coarse_absolute_msec() + 10 + - i*3 % CHANNELPADDING_MAX_TIMERS; + monotime_coarse_add_msec(&chans[i]->next_padding_time, + &now, 10 + i*3 % CHANNELPADDING_MAX_TIMERS); decision = channelpadding_decide_to_pad_channel(chans[i]); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(chans[i]->pending_padding_callback); @@ -340,8 +344,8 @@ test_channelpadding_timers(void *arg) /* This loop should add timers to the last position in the timerslot * array, since its timeout is after all other timers. */ for (; i < CHANNELS_TO_TEST; i++) { - chans[i]->next_padding_time_ms = monotime_coarse_absolute_msec() + 500 + - i % CHANNELPADDING_MAX_TIMERS; + monotime_coarse_add_msec(&chans[i]->next_padding_time, + &now, 500 + i % CHANNELPADDING_MAX_TIMERS); decision = channelpadding_decide_to_pad_channel(chans[i]); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(chans[i]->pending_padding_callback); @@ -349,9 +353,9 @@ test_channelpadding_timers(void *arg) } // Wait for the timers and then kill the event loop. - new_time = (monotime_coarse_absolute_msec()+1001)*NSEC_PER_MSEC; - monotime_coarse_set_mock_time_nsec(new_time); - monotime_set_mock_time_nsec(new_time); + nsec_mock += 1001 * NSEC_PER_MSEC; + monotime_coarse_set_mock_time_nsec(nsec_mock); + monotime_set_mock_time_nsec(nsec_mock); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, CHANNELS_TO_TEST); @@ -388,6 +392,7 @@ test_channelpadding_killonehop(void *arg) monotime_enable_test_mocking(); monotime_set_mock_time_nsec(1); monotime_coarse_set_mock_time_nsec(1); + new_time = 1; timers_initialize(); setup_mock_consensus(); @@ -401,9 +406,12 @@ test_channelpadding_killonehop(void *arg) smartlist_clear(current_md_consensus->net_params); channelpadding_new_consensus_params(current_md_consensus); + monotime_coarse_t now; + monotime_coarse_get(&now); + tried_to_write_cell = 0; get_options_mutable()->Tor2webMode = 1; - client_relay3->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&client_relay3->next_padding_time, &now, 100); decision = channelpadding_decide_to_pad_channel(client_relay3); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(client_relay3->pending_padding_callback); @@ -413,9 +421,10 @@ test_channelpadding_killonehop(void *arg) tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED); // Wait for the timer - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time += 101*NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_assert(!client_relay3->pending_padding_callback); @@ -427,7 +436,7 @@ test_channelpadding_killonehop(void *arg) // Before the client tries to pad, the relay will still pad: tried_to_write_cell = 0; - relay3_client->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&relay3_client->next_padding_time, &now, 100); get_options_mutable()->ORPort_set = 1; get_options_mutable()->Tor2webMode = 0; decision = channelpadding_decide_to_pad_channel(relay3_client); @@ -435,9 +444,10 @@ test_channelpadding_killonehop(void *arg) tt_assert(relay3_client->pending_padding_callback); // Wait for the timer - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time += 101*NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_assert(!client_relay3->pending_padding_callback); @@ -474,7 +484,8 @@ test_channelpadding_killonehop(void *arg) get_options_mutable()->ORPort_set = 0; get_options_mutable()->HiddenServiceSingleHopMode = 1; get_options_mutable()->HiddenServiceNonAnonymousMode = 1; - client_relay3->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + + monotime_coarse_add_msec(&client_relay3->next_padding_time, &now, 100); decision = channelpadding_decide_to_pad_channel(client_relay3); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(client_relay3->pending_padding_callback); @@ -484,9 +495,10 @@ test_channelpadding_killonehop(void *arg) tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED); // Wait for the timer - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time += 101 * NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_assert(!client_relay3->pending_padding_callback); @@ -498,7 +510,7 @@ test_channelpadding_killonehop(void *arg) // Before the client tries to pad, the relay will still pad: tried_to_write_cell = 0; - relay3_client->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&relay3_client->next_padding_time, &now, 100); get_options_mutable()->ORPort_set = 1; get_options_mutable()->HiddenServiceSingleHopMode = 0; get_options_mutable()->HiddenServiceNonAnonymousMode = 0; @@ -507,9 +519,10 @@ test_channelpadding_killonehop(void *arg) tt_assert(relay3_client->pending_padding_callback); // Wait for the timer - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time += 101 * NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_assert(!client_relay3->pending_padding_callback); @@ -573,6 +586,9 @@ test_channelpadding_consensus(void *arg) monotime_enable_test_mocking(); monotime_set_mock_time_nsec(1); monotime_coarse_set_mock_time_nsec(1); + new_time = 1; + monotime_coarse_t now; + monotime_coarse_get(&now); timers_initialize(); if (!connection_array) @@ -586,7 +602,7 @@ test_channelpadding_consensus(void *arg) /* Test 1: Padding can be completely disabled via consensus */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&chan->next_padding_time, &now, 100); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(chan->pending_padding_callback); @@ -596,9 +612,10 @@ test_channelpadding_consensus(void *arg) tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED); // Wait for the timer - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time += 101*NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_assert(!chan->pending_padding_callback); @@ -628,7 +645,7 @@ test_channelpadding_consensus(void *arg) tt_i64_op(val, OP_EQ, 0); val = channelpadding_compute_time_until_pad_for_netflow(chan); tt_i64_op(val, OP_EQ, -2); - tt_assert(!chan->next_padding_time_ms); + tt_assert(monotime_coarse_is_zero(&chan->next_padding_time)); smartlist_clear(current_md_consensus->net_params); @@ -641,7 +658,7 @@ test_channelpadding_consensus(void *arg) channelpadding_new_consensus_params(current_md_consensus); tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&chan->next_padding_time, &now, 100); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(chan->pending_padding_callback); @@ -653,9 +670,10 @@ test_channelpadding_consensus(void *arg) tt_i64_op(val, OP_LE, 200); // Wait for the timer - new_time = (monotime_coarse_absolute_msec()+201)*NSEC_PER_MSEC; + new_time += 201*NSEC_PER_MSEC; monotime_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_assert(!chan->pending_padding_callback); @@ -944,6 +962,9 @@ test_channelpadding_decide_to_pad_channel(void *arg) monotime_enable_test_mocking(); monotime_set_mock_time_nsec(1); monotime_coarse_set_mock_time_nsec(1); + new_time = 1; + monotime_coarse_t now; + monotime_coarse_get(&now); timers_initialize(); setup_full_capture_of_logs(LOG_WARN); channelpadding_new_consensus_params(NULL); @@ -960,7 +981,7 @@ test_channelpadding_decide_to_pad_channel(void *arg) /* Test case #2a: > 1.1s until timeout */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 1200; + monotime_coarse_add_msec(&chan->next_padding_time, &now, 1200); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADLATER); tt_assert(!chan->pending_padding_callback); @@ -968,23 +989,27 @@ test_channelpadding_decide_to_pad_channel(void *arg) /* Test case #2b: >= 1.0s until timeout */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 1000; + monotime_coarse_add_msec(&chan->next_padding_time, &now, 1000); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(chan->pending_padding_callback); tt_int_op(tried_to_write_cell, OP_EQ, 0); + // Set up a timer for the <0 case below. + monotime_coarse_t now_minus_100s; + monotime_coarse_add_msec(&now_minus_100s, &now, 900); // Wait for the timer from case #2b - new_time = (monotime_coarse_absolute_msec() + 1000)*NSEC_PER_MSEC; + new_time += 1000*NSEC_PER_MSEC; monotime_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_assert(!chan->pending_padding_callback); /* Test case #2c: > 0.1s until timeout */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&chan->next_padding_time, &now, 100); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(chan->pending_padding_callback); @@ -995,16 +1020,17 @@ test_channelpadding_decide_to_pad_channel(void *arg) tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED); // Wait for the timer - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time += 101*NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_assert(!chan->pending_padding_callback); /* Test case #2e: 0s until timeout */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec(); + monotime_coarse_add_msec(&chan->next_padding_time, &now, 0); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SENT); tt_int_op(tried_to_write_cell, OP_EQ, 1); @@ -1012,7 +1038,7 @@ test_channelpadding_decide_to_pad_channel(void *arg) /* Test case #2f: <0s until timeout */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() - 100; + monotime_coarse_add_msec(&chan->next_padding_time, &now_minus_100s, 0); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SENT); tt_int_op(tried_to_write_cell, OP_EQ, 1); @@ -1020,7 +1046,7 @@ test_channelpadding_decide_to_pad_channel(void *arg) /* Test case #3: Channel that sends a packet while timeout is scheduled */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&chan->next_padding_time, &now, 100); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(tried_to_write_cell, OP_EQ, 0); @@ -1031,9 +1057,10 @@ test_channelpadding_decide_to_pad_channel(void *arg) // We don't expect any timer callbacks here. Make a dummy one to be sure. // Wait for the timer - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time += 101*NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 0); @@ -1041,7 +1068,7 @@ test_channelpadding_decide_to_pad_channel(void *arg) /* Test case #4: Channel that closes while a timeout is scheduled */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&chan->next_padding_time, &now, 100); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(tried_to_write_cell, OP_EQ, 0); @@ -1051,9 +1078,10 @@ test_channelpadding_decide_to_pad_channel(void *arg) chan->state = CHANNEL_STATE_MAINT; // We don't expect any timer callbacks here. Make a dummy one to be sure. - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time += 101*NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 0); @@ -1062,16 +1090,17 @@ test_channelpadding_decide_to_pad_channel(void *arg) /* Test case #5: Make sure previous test case didn't break everything */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&chan->next_padding_time, &now, 100); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_assert(chan->pending_padding_callback); tt_int_op(tried_to_write_cell, OP_EQ, 0); // Wait for the timer - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time += 101*NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 1); @@ -1090,7 +1119,7 @@ test_channelpadding_decide_to_pad_channel(void *arg) * It must be last. */ tried_to_write_cell = 0; - chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; + monotime_coarse_add_msec(&chan->next_padding_time, &now, 100); decision = channelpadding_decide_to_pad_channel(chan); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(tried_to_write_cell, OP_EQ, 0); @@ -1100,9 +1129,10 @@ test_channelpadding_decide_to_pad_channel(void *arg) free_fake_channeltls((channel_tls_t*)chan); // We don't expect any timer callbacks here. Make a dummy one to be sure. - new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; + new_time = 101*NSEC_PER_MSEC; monotime_coarse_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time); + monotime_coarse_get(&now); timers_run_pending(); tt_int_op(tried_to_write_cell, OP_EQ, 0);