From 43d036e72488b4be5f48aaec9278a55dc22cb556 Mon Sep 17 00:00:00 2001 From: Ryan Winograd Date: Wed, 21 Jun 2017 12:15:46 -0500 Subject: progress: Track total times following redirects Update the progress timers `t_nslookup`, `t_connect`, `t_appconnect`, `t_pretransfer`, and `t_starttransfer` to track the total times for these activities when a redirect is followed. Previously, only the times for the most recent request would be tracked. Related changes: - Rename `Curl_pgrsResetTimesSizes` to `Curl_pgrsResetTransferSizes` now that the function only resets transfer sizes and no longer modifies any of the progress timers. - Add a bool to the `Progress` struct that is used to prevent double-counting `t_starttransfer` times. Added test case 1399. Fixes #522 and Known Bug 1.8 Closes #1602 Reported-by: joshhe on github --- tests/unit/unit1399.c | 95 ++++++++++++++++++++++++++++++--------------------- 1 file changed, 56 insertions(+), 39 deletions(-) (limited to 'tests/unit/unit1399.c') diff --git a/tests/unit/unit1399.c b/tests/unit/unit1399.c index 82e0dc27e..91fd3dae1 100644 --- a/tests/unit/unit1399.c +++ b/tests/unit/unit1399.c @@ -36,6 +36,20 @@ static void unit_stop(void) } +/* + * Invoke Curl_pgrsTime for TIMER_STARTSINGLE to trigger the behavior that + * manages is_t_startransfer_set, but fake the t_startsingle time for purposes + * of the test. + */ +static void fake_t_startsingle_time(struct Curl_easy *data, + struct curltime fake_now, + int seconds_offset) +{ + Curl_pgrsTime(data, TIMER_STARTSINGLE); + data->progress.t_startsingle.tv_sec = fake_now.tv_sec + seconds_offset; + data->progress.t_startsingle.tv_usec = fake_now.tv_usec; +} + static bool usec_matches_seconds(time_t time_usec, int expected_seconds) { int time_sec = (int)(time_usec / usec_magnitude); @@ -46,55 +60,58 @@ static bool usec_matches_seconds(time_t time_usec, int expected_seconds) return same; } +static void expect_timer_seconds(struct Curl_easy *data, int seconds) +{ + char msg[64]; + snprintf(msg, sizeof(msg), "about %d seconds should have passed", seconds); + fail_unless(usec_matches_seconds(data->progress.t_nslookup, seconds), msg); + fail_unless(usec_matches_seconds(data->progress.t_connect, seconds), msg); + fail_unless(usec_matches_seconds(data->progress.t_appconnect, seconds), msg); + fail_unless(usec_matches_seconds(data->progress.t_pretransfer, seconds), + msg); + fail_unless(usec_matches_seconds(data->progress.t_starttransfer, seconds), + msg); +} + +/* Scenario: simulate a redirect. When a redirect occurs, t_nslookup, + * t_connect, t_appconnect, t_pretransfer, and t_starttransfer are addative. + * E.g., if t_starttransfer took 2 seconds initially and took another 1 + * second for the redirect request, then the resulting t_starttransfer should + * be 3 seconds. */ UNITTEST_START struct Curl_easy data; struct curltime now = Curl_tvnow(); + data.progress.t_nslookup = 0; + data.progress.t_connect = 0; + data.progress.t_appconnect = 0; + data.progress.t_pretransfer = 0; data.progress.t_starttransfer = 0; data.progress.t_redirect = 0; - - /* - * Set the startsingle time to a second ago. This time is used by - * Curl_pgrsTime to calculate how much time the events takes. - * t_starttransfer should be updated to reflect the difference from this time - * when `Curl_pgrsTime is invoked. - */ - data.progress.t_startsingle.tv_sec = now.tv_sec - 1; - data.progress.t_startsingle.tv_usec = now.tv_usec; - + data.progress.start.tv_sec = now.tv_sec - 2; + data.progress.start.tv_usec = now.tv_usec; + fake_t_startsingle_time(&data, now, -2); + + Curl_pgrsTime(&data, TIMER_NAMELOOKUP); + Curl_pgrsTime(&data, TIMER_CONNECT); + Curl_pgrsTime(&data, TIMER_APPCONNECT); + Curl_pgrsTime(&data, TIMER_PRETRANSFER); Curl_pgrsTime(&data, TIMER_STARTTRANSFER); - fail_unless(usec_matches_seconds(data.progress.t_starttransfer, 1), - "about 1 second should have passed"); - - /* - * Update the startsingle time to a second ago to simulate another second has - * passed. - * Now t_starttransfer should not be changed, as t_starttransfer has already - * occurred and another invocation of `Curl_pgrsTime` for TIMER_STARTTRANSFER - * is superfluous. - */ - data.progress.t_startsingle.tv_sec = now.tv_sec - 2; - data.progress.t_startsingle.tv_usec = now.tv_usec; - - Curl_pgrsTime(&data, TIMER_STARTTRANSFER); + expect_timer_seconds(&data, 2); - fail_unless(usec_matches_seconds(data.progress.t_starttransfer, 1), - "about 1 second should have passed"); - - /* - * Simulate what happens after a redirect has occurred. - * - * Since the value of t_starttransfer is set to the value from the first - * request, it should be updated when a transfer occurs such that - * t_starttransfer is the starttransfer time of the redirect request. - */ - data.progress.t_startsingle.tv_sec = now.tv_sec - 3; - data.progress.t_startsingle.tv_usec = now.tv_usec; + /* now simulate the redirect */ data.progress.t_redirect = data.progress.t_starttransfer + 1; - + fake_t_startsingle_time(&data, now, -1); + + Curl_pgrsTime(&data, TIMER_NAMELOOKUP); + Curl_pgrsTime(&data, TIMER_CONNECT); + Curl_pgrsTime(&data, TIMER_APPCONNECT); + Curl_pgrsTime(&data, TIMER_PRETRANSFER); + /* ensure t_starttransfer is only set on the first invocation by attempting + * to set it twice */ + Curl_pgrsTime(&data, TIMER_STARTTRANSFER); Curl_pgrsTime(&data, TIMER_STARTTRANSFER); - fail_unless(usec_matches_seconds(data.progress.t_starttransfer, 3), - "about 3 second should have passed"); + expect_timer_seconds(&data, 3); UNITTEST_STOP -- cgit v1.2.3