From 67a1763bc4aa67ad16c884626c82c0a3686df0a4 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Tue, 24 Jan 2012 14:33:10 -0500 Subject: [PATCH] Make regression tests run over 3x faster. This was mainly a matter of reducing timeouts and delays, paying special attention to every test that took longer than a second to finish. We could do better here; IMO anything over .7 sec is probably too long, but it's a big win as it is. Remember, interactive computing is a big win over batch processing: anything that makes you get up and walk away from the terminal might as well be making you carry your punch cards over to the mainframe. --- test/regress.c | 79 ++++++++++++++++++-------------------- test/regress_bufferevent.c | 4 +- test/regress_dns.c | 20 +++++++--- test/regress_http.c | 41 ++++++++++++-------- test/regress_rpc.c | 4 +- test/regress_thread.c | 39 +++++++++++-------- 6 files changed, 104 insertions(+), 83 deletions(-) diff --git a/test/regress.c b/test/regress.c index 0fdfeb35..f7686d4d 100644 --- a/test/regress.c +++ b/test/regress.c @@ -87,7 +87,6 @@ static struct timeval tcalled; #define TEST1 "this is a test" -#define SECONDS 1 #ifndef SHUT_WR #define SHUT_WR 1 @@ -233,21 +232,7 @@ multiple_read_cb(evutil_socket_t fd, short event, void *arg) static void timeout_cb(evutil_socket_t fd, short event, void *arg) { - struct timeval tv; - int diff; - evutil_gettimeofday(&tcalled, NULL); - if (evutil_timercmp(&tcalled, &tset, >)) - evutil_timersub(&tcalled, &tset, &tv); - else - evutil_timersub(&tset, &tcalled, &tv); - - diff = tv.tv_sec*1000 + tv.tv_usec/1000 - SECONDS * 1000; - if (diff < 0) - diff = -diff; - - if (diff < 100) - test_ok = 1; } struct both { @@ -578,19 +563,26 @@ end: static void test_simpletimeout(void) { - struct timeval tv; + struct timeval tv, elapsed; struct event ev; setup_test("Simple timeout: "); - tv.tv_usec = 0; - tv.tv_sec = SECONDS; + tv.tv_usec = 200*1000; + tv.tv_sec = 0; + evutil_timerclear(&tcalled); evtimer_set(&ev, timeout_cb, NULL); evtimer_add(&ev, &tv); evutil_gettimeofday(&tset, NULL); event_dispatch(); + evutil_timersub(&tcalled, &tset, &elapsed); + tt_int_op(0, ==, elapsed.tv_sec); + tt_int_op(elapsed.tv_usec, >, 150000); + tt_int_op(elapsed.tv_usec, <, 300000); + test_ok = 1; +end: cleanup_test(); } @@ -707,7 +699,7 @@ common_timeout_cb(evutil_socket_t fd, short event, void *arg) struct common_timeout_info *ti = arg; ++ti->count; evutil_gettimeofday(&ti->called_at, NULL); - if (ti->count >= 6) + if (ti->count >= 4) event_del(&ti->ev); } @@ -720,7 +712,7 @@ test_common_timeout(void *ptr) int i; struct common_timeout_info info[100]; - struct timeval now; + struct timeval start; struct timeval tmp_100_ms = { 0, 100*1000 }; struct timeval tmp_200_ms = { 0, 200*1000 }; @@ -751,23 +743,23 @@ test_common_timeout(void *ptr) } event_base_assert_ok(base); + evutil_gettimeofday(&start, NULL); event_base_dispatch(base); - evutil_gettimeofday(&now, NULL); event_base_assert_ok(base); for (i=0; i<10; ++i) { struct timeval tmp; - int ms_diff; - tt_int_op(info[i].count, ==, 6); - evutil_timersub(&now, &info[i].called_at, &tmp); - ms_diff = tmp.tv_usec/1000 + tmp.tv_sec*1000; + int ms_elapsed; + tt_int_op(info[i].count, ==, 4); + evutil_timersub(&info[i].called_at, &start, &tmp); + ms_elapsed = tmp.tv_usec/1000 + tmp.tv_sec*1000; if (i % 2) { - tt_int_op(ms_diff, >, 500); - tt_int_op(ms_diff, <, 700); + tt_int_op(ms_elapsed, >, 300); + tt_int_op(ms_elapsed, <, 500); } else { - tt_int_op(ms_diff, >, -100); - tt_int_op(ms_diff, <, 100); + tt_int_op(ms_elapsed, >, 700); + tt_int_op(ms_elapsed, <, 900); } } @@ -927,7 +919,8 @@ test_simplesignal(void) evsignal_add(&ev, NULL); memset(&itv, 0, sizeof(itv)); - itv.it_value.tv_sec = 1; + itv.it_value.tv_sec = 0; + itv.it_value.tv_usec = 100000; if (setitimer(ITIMER_REAL, &itv, NULL) == -1) goto skip_simplesignal; @@ -954,7 +947,8 @@ test_multiplesignal(void) evsignal_add(&ev_two, NULL); memset(&itv, 0, sizeof(itv)); - itv.it_value.tv_sec = 1; + itv.it_value.tv_sec = 0; + itv.it_value.tv_usec = 100000; if (setitimer(ITIMER_REAL, &itv, NULL) == -1) goto skip_simplesignal; @@ -1343,23 +1337,22 @@ test_loopexit(void) evtimer_set(&ev, timeout_cb, NULL); evtimer_add(&ev, &tv); - tv.tv_usec = 0; - tv.tv_sec = 1; + tv.tv_usec = 300*1000; + tv.tv_sec = 0; event_loopexit(&tv); evutil_gettimeofday(&tv_start, NULL); event_dispatch(); evutil_gettimeofday(&tv_end, NULL); - evutil_timersub(&tv_end, &tv_start, &tv_end); evtimer_del(&ev); tt_assert(event_base_got_exit(global_base)); tt_assert(!event_base_got_break(global_base)); - if (tv.tv_sec < 2) - test_ok = 1; + test_timeval_diff_eq(&tv_start, &tv_end, 300); + test_ok = 1; end: cleanup_test(); } @@ -1367,28 +1360,32 @@ end: static void test_loopexit_multiple(void) { - struct timeval tv; + struct timeval tv, tv_start, tv_end; struct event_base *base; setup_test("Loop Multiple exit: "); base = event_base_new(); - tv.tv_usec = 0; - tv.tv_sec = 1; + tv.tv_usec = 200*1000; + tv.tv_sec = 0; event_base_loopexit(base, &tv); tv.tv_usec = 0; - tv.tv_sec = 2; + tv.tv_sec = 3; event_base_loopexit(base, &tv); + evutil_gettimeofday(&tv_start, NULL); event_base_dispatch(base); + evutil_gettimeofday(&tv_end, NULL); tt_assert(event_base_got_exit(base)); tt_assert(!event_base_got_break(base)); event_base_free(base); + test_timeval_diff_eq(&tv_start, &tv_end, 200); + test_ok = 1; end: @@ -1662,7 +1659,7 @@ test_want_only_once(void) /* Setup the loop termination */ evutil_timerclear(&tv); - tv.tv_sec = 1; + tv.tv_usec = 300*1000; event_loopexit(&tv); event_set(&ev, pair[1], EV_READ, read_once_cb, &ev); diff --git a/test/regress_bufferevent.c b/test/regress_bufferevent.c index 26273f6c..82d582cd 100644 --- a/test/regress_bufferevent.c +++ b/test/regress_bufferevent.c @@ -746,8 +746,8 @@ test_bufferevent_timeouts(void *arg) bufferevent_set_timeouts(bev2, &tv_r, &tv_w); bufferevent_enable(bev2, EV_WRITE); - tv_r.tv_sec = 1; - tv_r.tv_usec = 0; + tv_r.tv_sec = 0; + tv_r.tv_usec = 350000; event_base_loopexit(data->base, &tv_r); event_base_dispatch(data->base); diff --git a/test/regress_dns.c b/test/regress_dns.c index be3e7220..9c24061c 100644 --- a/test/regress_dns.c +++ b/test/regress_dns.c @@ -684,9 +684,9 @@ dns_retry_test(void *arg) dns = evdns_base_new(base, 0); tt_assert(!evdns_base_nameserver_ip_add(dns, buf)); - tt_assert(! evdns_base_set_option(dns, "timeout", "0.3")); + tt_assert(! evdns_base_set_option(dns, "timeout", "0.2")); tt_assert(! evdns_base_set_option(dns, "max-timeouts:", "10")); - tt_assert(! evdns_base_set_option(dns, "initial-probe-timeout", "0.5")); + tt_assert(! evdns_base_set_option(dns, "initial-probe-timeout", "0.1")); evdns_base_resolve_ipv4(dns, "host.example.com", 0, generic_dns_callback, &r1); @@ -705,8 +705,8 @@ dns_retry_test(void *arg) /* Now try again, but this time have the server get treated as * failed, so we can send it a test probe. */ drop_count = 4; - tt_assert(! evdns_base_set_option(dns, "max-timeouts:", "3")); - tt_assert(! evdns_base_set_option(dns, "attempts:", "4")); + tt_assert(! evdns_base_set_option(dns, "max-timeouts:", "2")); + tt_assert(! evdns_base_set_option(dns, "attempts:", "3")); memset(&r1, 0, sizeof(r1)); evdns_base_resolve_ipv4(dns, "host.example.com", 0, @@ -883,6 +883,8 @@ be_getaddrinfo_server_cb(struct evdns_server_request *req, void *data) struct in6_addr ans6; memset(&ans6, 0, sizeof(ans6)); + TT_BLATHER(("Got question about %s, type=%d", qname, qtype)); + if (qtype == EVDNS_TYPE_A && qclass == EVDNS_CLASS_INET && !evutil_ascii_strcasecmp(qname, "nobodaddy.example.com")) { @@ -983,10 +985,13 @@ be_getaddrinfo_server_cb(struct evdns_server_request *req, void *data) TT_GRIPE(("Got weird request for %s",qname)); } } - if (added_any) + if (added_any) { + TT_BLATHER(("answering")); evdns_server_request_respond(req, 0); - else + } else { + TT_BLATHER(("saying nexist.")); evdns_server_request_respond(req, 3); + } } /* Implements a listener for connect_hostname test. */ @@ -1215,6 +1220,9 @@ test_getaddrinfo_async(void *arg) /* for localhost */ evdns_base_load_hosts(dns_base, NULL); + tt_assert(! evdns_base_set_option(dns_base, "timeout", "0.3")); + tt_assert(! evdns_base_set_option(dns_base, "getaddrinfo-allow-skew", "0.2")); + memset(a_out, 0, sizeof(a_out)); n_gai_results_pending = 10000; /* don't think about exiting yet. */ diff --git a/test/regress_http.c b/test/regress_http.c index 81632b93..31eef55b 100644 --- a/test/regress_http.c +++ b/test/regress_http.c @@ -628,7 +628,7 @@ http_large_delay_cb(struct evhttp_request *req, void *arg) { struct timeval tv; evutil_timerclear(&tv); - tv.tv_sec = 3; + tv.tv_usec = 500000; event_base_once(arg, -1, EV_TIMEOUT, http_delay_reply, req, &tv); evhttp_connection_fail(delayed_client, EVCON_HTTP_EOF); @@ -1769,7 +1769,7 @@ close_detect_done(struct evhttp_request *req, void *arg) end: evutil_timerclear(&tv); - tv.tv_sec = 3; + tv.tv_usec = 150000; event_base_loopexit(arg, &tv); } @@ -1803,9 +1803,10 @@ close_detect_cb(struct evhttp_request *req, void *arg) } evutil_timerclear(&tv); - tv.tv_sec = 3; /* longer than the http time out */ + tv.tv_sec = 0; /* longer than the http time out */ + tv.tv_usec = 600000; /* longer than the http time out */ - /* launch a new request on the persistent connection in 3 seconds */ + /* launch a new request on the persistent connection in .3 seconds */ event_base_once(base, -1, EV_TIMEOUT, close_detect_launch, evcon, &tv); end: ; @@ -1818,15 +1819,19 @@ _http_close_detection(struct basic_test_data *data, int with_delay) ev_uint16_t port = 0; struct evhttp_connection *evcon = NULL; struct evhttp_request *req = NULL; + const struct timeval sec_tenth = { 0, 100000 }; test_ok = 0; http = http_setup(&port, data->base); - /* 2 second timeout */ - evhttp_set_timeout(http, 1); + /* .1 second timeout */ + evhttp_set_timeout_tv(http, &sec_tenth); evcon = evhttp_connection_base_new(data->base, NULL, "127.0.0.1", port); + evhttp_connection_set_timeout_tv(evcon, &sec_tenth); + + tt_assert(evcon); delayed_client = evcon; @@ -3143,7 +3148,12 @@ http_connection_retry_test(void *arg) */ test_ok = 0; - evhttp_connection_set_timeout(evcon, 1); + { + const struct timeval tv_timeout = { 0, 300000 }; + const struct timeval tv_retry = { 0, 200000 }; + evhttp_connection_set_timeout_tv(evcon, &tv_timeout); + evhttp_connection_set_initial_retry_tv(evcon, &tv_retry); + } evhttp_connection_set_retries(evcon, 1); req = evhttp_request_new(http_connection_retry_done, data->base); @@ -3160,9 +3170,9 @@ http_connection_retry_test(void *arg) evutil_gettimeofday(&tv_start, NULL); event_base_dispatch(data->base); evutil_gettimeofday(&tv_end, NULL); - evutil_timersub(&tv_end, &tv_start, &tv_end); - tt_int_op(tv_end.tv_sec, >, 1); - tt_int_op(tv_end.tv_sec, <, 6); + + /* fails fast, .2 sec to wait to retry, fails fast again. */ + test_timeval_diff_eq(&tv_start, &tv_end, 200); tt_assert(test_ok == 1); @@ -3186,22 +3196,19 @@ http_connection_retry_test(void *arg) tt_abort_msg("Couldn't make request"); } - /* start up a web server one second after the connection tried + /* start up a web server .2 seconds after the connection tried * to send a request */ evutil_timerclear(&tv); - tv.tv_sec = 1; + tv.tv_usec = 200000; http_make_web_server_base = data->base; event_base_once(data->base, -1, EV_TIMEOUT, http_make_web_server, &port, &tv); evutil_gettimeofday(&tv_start, NULL); event_base_dispatch(data->base); evutil_gettimeofday(&tv_end, NULL); - - evutil_timersub(&tv_end, &tv_start, &tv_end); - - tt_int_op(tv_end.tv_sec, >, 1); - tt_int_op(tv_end.tv_sec, <, 6); + /* We'll wait twice as long as we did last time. */ + test_timeval_diff_eq(&tv_start, &tv_end, 400); tt_int_op(test_ok, ==, 1); diff --git a/test/regress_rpc.c b/test/regress_rpc.c index c698ed35..e22da92c 100644 --- a/test/regress_rpc.c +++ b/test/regress_rpc.c @@ -687,8 +687,8 @@ rpc_client_timeout(void) pool = rpc_pool_with_connection(port); - /* set the timeout to 5 seconds */ - evrpc_pool_set_timeout(pool, 5); + /* set the timeout to 1 second. */ + evrpc_pool_set_timeout(pool, 1); /* set up the basic message */ msg = msg_new(); diff --git a/test/regress_thread.c b/test/regress_thread.c index da43b2e7..a6520836 100644 --- a/test/regress_thread.c +++ b/test/regress_thread.c @@ -60,6 +60,7 @@ #include "evthread-internal.h" #include "event-internal.h" #include "defer-internal.h" +#include "util-internal.h" #include "regress.h" #include "tinytest_macros.h" @@ -403,19 +404,22 @@ end: #define CB_COUNT 128 #define QUEUE_THREAD_COUNT 8 -#ifdef _WIN32 -#define SLEEP_MS(ms) Sleep(ms) -#else -#define SLEEP_MS(ms) usleep((ms) * 1000) -#endif +static void +SLEEP_MS(int ms) +{ + struct timeval tv; + tv.tv_sec = ms/1000; + tv.tv_usec = (ms%1000)*1000; + evutil_usleep(&tv); +} struct deferred_test_data { struct deferred_cb cbs[CB_COUNT]; struct deferred_cb_queue *queue; }; -static time_t timer_start = 0; -static time_t timer_end = 0; +static struct timeval timer_start = {0,0}; +static struct timeval timer_end = {0,0}; static unsigned callback_count = 0; static THREAD_T load_threads[QUEUE_THREAD_COUNT]; static struct deferred_test_data deferred_data[QUEUE_THREAD_COUNT]; @@ -445,7 +449,7 @@ load_deferred_queue(void *arg) static void timer_callback(evutil_socket_t fd, short what, void *arg) { - timer_end = time(NULL); + evutil_gettimeofday(&timer_end, NULL); } static void @@ -463,9 +467,10 @@ static void thread_deferred_cb_skew(void *arg) { struct basic_test_data *data = arg; - struct timeval tv_timer = {4, 0}; + struct timeval tv_timer = {1, 0}; struct deferred_cb_queue *queue; - time_t elapsed; + struct timeval elapsed; + int elapsed_usec; int i; queue = event_base_get_deferred_cb_queue(data->base); @@ -474,19 +479,23 @@ thread_deferred_cb_skew(void *arg) for (i = 0; i < QUEUE_THREAD_COUNT; ++i) deferred_data[i].queue = queue; - timer_start = time(NULL); + evutil_gettimeofday(&timer_start, NULL); event_base_once(data->base, -1, EV_TIMEOUT, timer_callback, NULL, &tv_timer); event_base_once(data->base, -1, EV_TIMEOUT, start_threads_callback, NULL, NULL); event_base_dispatch(data->base); - elapsed = timer_end - timer_start; + evutil_timersub(&timer_end, &timer_start, &elapsed); TT_BLATHER(("callback count, %u", callback_count)); - TT_BLATHER(("elapsed time, %u", (unsigned)elapsed)); + elapsed_usec = + (unsigned)(elapsed.tv_sec*1000000 + elapsed.tv_usec); + TT_BLATHER(("elapsed time, %u usec", elapsed_usec)); + /* XXX be more intelligent here. just make sure skew is - * within 2 seconds for now. */ - tt_assert(elapsed >= 4 && elapsed <= 6); + * within .3 seconds for now. */ + + tt_assert(elapsed_usec >= 700000 && elapsed_usec <= 1200000); end: for (i = 0; i < QUEUE_THREAD_COUNT; ++i) -- 2.40.0