From 6ac8e775bb3cba49c276c90e288554635d38b466 Mon Sep 17 00:00:00 2001 From: Azat Khuzhin Date: Sun, 21 Oct 2018 18:31:01 +0300 Subject: [PATCH] Simplify bufferevent timeout tests to reduce CPU usage in between start/compare Between start (setting "started_at") and comparing the time when timeouts triggered with the start (test_timeval_diff_eq), there is too much various things that can introduce extra delays and eventually could fail the test on machine with shortage of CPU. And this is exactly what happend on: - travis-ci - #262 Here is a simple reproducer that I came up with for this issue: docker run --cpus=0.01 -e LD_LIBRARY_PATH=$PWD/lib -e PATH=/usr/bin:/bin:$PWD/bin -v $PWD:$PWD --rm -it debian:testing regress --no-fork --verbose bufferevent/bufferevent_timeout Under limited CPU (see reproducer) the test almost always has problems with that "write_timeout_at" exceed default timeval diff tolerance (test_timeval_diff_eq() has 50 tolerance), i.e.: FAIL ../test/regress_bufferevent.c:1040: assert(labs(timeval_msec_diff(((&started_at)), ((&res1.write_timeout_at))) - (100)) <= 50): 101 vs 50 But under some setup write timeout can even not triggered, and the reason for this is that we write to the bufferevent 1024*1024 bytes, and hence if evbuffer_write_iovec() will has some delay after writev() and not send more then one vector at a time [1], it is pretty simple to trigger, i.e.: FAIL ../test/regress_bufferevent.c:1040: assert(labs(timeval_msec_diff(((&started_at)), ((&res1.write_timeout_at))) - (100)) <= 50): 1540155888478 vs 50 [1]: https://gist.github.com/azat/b72773dfe7549fed865d439e03de05c1 So this patch just send static small payload for all cases (plus a few more asserts added). The outcome of this patch is that all regression tests passed on travis-ci for linux box [2]. While before it fails almost always [3]. Also reproducer with CPU limiting via docker also survive some iterations (and strictly speaking it should has less CPU then travis-ci workers I guess). [2]: https://travis-ci.org/azat/libevent/builds/444391481 [3]: https://travis-ci.org/libevent/libevent/builds/444336505 --- test/regress_bufferevent.c | 51 +++++++++++++++++++------------------- 1 file changed, 25 insertions(+), 26 deletions(-) diff --git a/test/regress_bufferevent.c b/test/regress_bufferevent.c index 6d69655f..faf87a7f 100644 --- a/test/regress_bufferevent.c +++ b/test/regress_bufferevent.c @@ -908,18 +908,24 @@ struct timeout_cb_result { struct timeval read_timeout_at; struct timeval write_timeout_at; struct timeval last_wrote_at; + struct timeval last_read_at; int n_read_timeouts; int n_write_timeouts; int total_calls; }; +static void +bev_timeout_read_cb(struct bufferevent *bev, void *arg) +{ + struct timeout_cb_result *res = arg; + evutil_gettimeofday(&res->last_read_at, NULL); +} static void bev_timeout_write_cb(struct bufferevent *bev, void *arg) { struct timeout_cb_result *res = arg; evutil_gettimeofday(&res->last_wrote_at, NULL); } - static void bev_timeout_event_cb(struct bufferevent *bev, short what, void *arg) { @@ -947,7 +953,6 @@ test_bufferevent_timeouts(void *arg) int use_pair = 0, use_filter = 0; struct timeval tv_w, tv_r, started_at; struct timeout_cb_result res1, res2; - char buf[1024]; memset(&res1, 0, sizeof(res1)); memset(&res2, 0, sizeof(res2)); @@ -966,7 +971,6 @@ test_bufferevent_timeouts(void *arg) bev1 = bufferevent_socket_new(data->base, data->pair[0], 0); bev2 = bufferevent_socket_new(data->base, data->pair[1], 0); } - tt_assert(bev1); tt_assert(bev2); @@ -990,30 +994,14 @@ test_bufferevent_timeouts(void *arg) tv_w.tv_sec = tv_r.tv_sec = 0; tv_w.tv_usec = 100*1000; tv_r.tv_usec = 150*1000; - bufferevent_setcb(bev1, NULL, bev_timeout_write_cb, + bufferevent_setcb(bev1, bev_timeout_read_cb, bev_timeout_write_cb, bev_timeout_event_cb, &res1); - bufferevent_setwatermark(bev1, EV_WRITE, 1024*1024+10, 0); bufferevent_set_timeouts(bev1, &tv_r, &tv_w); - if (use_pair) { - /* For a pair, the fact that the other side isn't reading - * makes the writer stall */ - bufferevent_write(bev1, "ABCDEFG", 7); - } else { - /* For a real socket, the kernel's TCP buffers can eat a - * fair number of bytes; make sure that at some point we - * have some bytes that will stall. */ - struct evbuffer *output = bufferevent_get_output(bev1); - int i; - memset(buf, 0xbb, sizeof(buf)); - for (i=0;i<1024;++i) { - evbuffer_add_reference(output, buf, sizeof(buf), - NULL, NULL); - } - } + bufferevent_write(bev1, "ABCDEFG", 7); bufferevent_enable(bev1, EV_READ|EV_WRITE); /* bev2 has nothing to say, and isn't listening. */ - bufferevent_setcb(bev2, NULL, bev_timeout_write_cb, + bufferevent_setcb(bev2, bev_timeout_read_cb, bev_timeout_write_cb, bev_timeout_event_cb, &res2); tv_w.tv_sec = tv_r.tv_sec = 0; tv_w.tv_usec = 200*1000; @@ -1030,15 +1018,26 @@ test_bufferevent_timeouts(void *arg) /* XXXX Test that actually reading or writing a little resets the * timeouts. */ - /* Each buf1 timeout happens, and happens only once. */ - tt_want(res1.n_read_timeouts); - tt_want(res1.n_write_timeouts); + tt_want(res1.total_calls == 2); tt_want(res1.n_read_timeouts == 1); tt_want(res1.n_write_timeouts == 1); + tt_want(res2.total_calls == !(use_pair && !use_filter)); + tt_want(res2.n_write_timeouts == !(use_pair && !use_filter)); + tt_want(!res2.n_read_timeouts); test_timeval_diff_eq(&started_at, &res1.read_timeout_at, 150); test_timeval_diff_eq(&started_at, &res1.write_timeout_at, 100); +#define tt_assert_timeval_empty(tv) do { \ + tt_int_op((tv).tv_sec, ==, 0); \ + tt_int_op((tv).tv_usec, ==, 0); \ +} while(0) + tt_assert_timeval_empty(res1.last_read_at); + tt_assert_timeval_empty(res2.last_read_at); + tt_assert_timeval_empty(res2.last_wrote_at); + tt_assert_timeval_empty(res2.last_wrote_at); +#undef tt_assert_timeval_empty + end: if (bev1) bufferevent_free(bev1); @@ -1363,7 +1362,7 @@ struct testcase_t bufferevent_testcases[] = { { "bufferevent_connect_fail", test_bufferevent_connect_fail, TT_FORK|TT_NEED_BASE, &basic_setup, NULL }, { "bufferevent_timeout", test_bufferevent_timeouts, - TT_FORK|TT_NEED_BASE|TT_NEED_SOCKETPAIR, &basic_setup, (void*)"" }, + TT_FORK|TT_NEED_BASE, &basic_setup, (void*)"" }, { "bufferevent_timeout_pair", test_bufferevent_timeouts, TT_FORK|TT_NEED_BASE, &basic_setup, (void*)"pair" }, { "bufferevent_timeout_filter", test_bufferevent_timeouts,