From 43d036e72488b4be5f48aaec9278a55dc22cb556 Mon Sep 17 00:00:00 2001 From: Ryan Winograd Date: Wed, 21 Jun 2017 12:15:46 -0500 Subject: [PATCH] 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 --- docs/KNOWN_BUGS | 7 ---- lib/getinfo.c | 1 + lib/progress.c | 16 ++++---- lib/progress.h | 2 +- lib/transfer.c | 4 +- lib/urldata.h | 2 + tests/unit/unit1399.c | 91 +++++++++++++++++++++++++------------------ 7 files changed, 67 insertions(+), 56 deletions(-) diff --git a/docs/KNOWN_BUGS b/docs/KNOWN_BUGS index 17731945a..3ef8e895f 100644 --- a/docs/KNOWN_BUGS +++ b/docs/KNOWN_BUGS @@ -18,7 +18,6 @@ problems may have been fixed or changed somewhat since this was written! 1.4 multipart formposts file name encoding 1.5 Expect-100 meets 417 1.6 Unnecessary close when 401 received waiting for 100 - 1.8 DNS timing is wrong for HTTP redirects 1.9 HTTP/2 frames while in the connection pool kill reuse 1.10 Strips trailing dot from host name 1.11 CURLOPT_SEEKFUNCTION not called with CURLFORM_STREAM @@ -140,12 +139,6 @@ problems may have been fixed or changed somewhat since this was written! waiting for the the 100-continue response. https://curl.haxx.se/mail/lib-2008-08/0462.html -1.8 DNS timing is wrong for HTTP redirects - - When extracting timing information after HTTP redirects, only the last - transfer's results are returned and not the totals: - https://github.com/curl/curl/issues/522 - 1.9 HTTP/2 frames while in the connection pool kill reuse If the server sends HTTP/2 frames (like for example an HTTP/2 PING frame) to diff --git a/lib/getinfo.c b/lib/getinfo.c index dc3a107e9..9c6f3b731 100644 --- a/lib/getinfo.c +++ b/lib/getinfo.c @@ -54,6 +54,7 @@ CURLcode Curl_initinfo(struct Curl_easy *data) pro->t_starttransfer = 0; pro->timespent = 0; pro->t_redirect = 0; + pro->is_t_startransfer_set = false; info->httpcode = 0; info->httpproxycode = 0; diff --git a/lib/progress.c b/lib/progress.c index 740ff2887..2f80704ae 100644 --- a/lib/progress.c +++ b/lib/progress.c @@ -149,14 +149,9 @@ int Curl_pgrsDone(struct connectdata *conn) return 0; } -/* reset all times except redirect, and reset the known transfer sizes */ -void Curl_pgrsResetTimesSizes(struct Curl_easy *data) +/* reset the known transfer sizes */ +void Curl_pgrsResetTransferSizes(struct Curl_easy *data) { - data->progress.t_nslookup = 0; - data->progress.t_connect = 0; - data->progress.t_pretransfer = 0; - data->progress.t_starttransfer = 0; - Curl_pgrsSetDownloadSize(data, -1); Curl_pgrsSetUploadSize(data, -1); } @@ -181,6 +176,7 @@ void Curl_pgrsTime(struct Curl_easy *data, timerid timer) case TIMER_STARTSINGLE: /* This is set at the start of each single fetch */ data->progress.t_startsingle = now; + data->progress.is_t_startransfer_set = false; break; case TIMER_STARTACCEPT: data->progress.t_acceptdata = now; @@ -205,10 +201,11 @@ void Curl_pgrsTime(struct Curl_easy *data, timerid timer) * This prevents repeated invocations of the function from incorrectly * changing the t_starttransfer time. */ - if (*delta > data->progress.t_redirect) { + if(data->progress.is_t_startransfer_set) { return; } else { + data->progress.is_t_startransfer_set = true; break; } case TIMER_POSTRANSFER: @@ -222,7 +219,7 @@ void Curl_pgrsTime(struct Curl_easy *data, timerid timer) time_t us = Curl_tvdiff_us(now, data->progress.t_startsingle); if(!us) us++; /* make sure at least one microsecond passed */ - *delta = us; + *delta += us; } } @@ -230,6 +227,7 @@ void Curl_pgrsStartNow(struct Curl_easy *data) { data->progress.speeder_c = 0; /* reset the progress meter display */ data->progress.start = Curl_tvnow(); + data->progress.is_t_startransfer_set = false; data->progress.ul_limit_start.tv_sec = 0; data->progress.ul_limit_start.tv_usec = 0; data->progress.dl_limit_start.tv_sec = 0; diff --git a/lib/progress.h b/lib/progress.h index ed57e3368..9333ab25c 100644 --- a/lib/progress.h +++ b/lib/progress.h @@ -47,7 +47,7 @@ void Curl_pgrsSetUploadSize(struct Curl_easy *data, curl_off_t size); void Curl_pgrsSetDownloadCounter(struct Curl_easy *data, curl_off_t size); void Curl_pgrsSetUploadCounter(struct Curl_easy *data, curl_off_t size); int Curl_pgrsUpdate(struct connectdata *); -void Curl_pgrsResetTimesSizes(struct Curl_easy *data); +void Curl_pgrsResetTransferSizes(struct Curl_easy *data); void Curl_pgrsTime(struct Curl_easy *data, timerid timer); long Curl_pgrsLimitWaitTime(curl_off_t cursize, curl_off_t startsize, diff --git a/lib/transfer.c b/lib/transfer.c index 3537b58c6..e7625ef77 100644 --- a/lib/transfer.c +++ b/lib/transfer.c @@ -1345,7 +1345,7 @@ CURLcode Curl_pretransfer(struct Curl_easy *data) #endif Curl_initinfo(data); /* reset session-specific information "variables" */ - Curl_pgrsResetTimesSizes(data); + Curl_pgrsResetTransferSizes(data); Curl_pgrsStartNow(data); if(data->set.timeout) @@ -1883,7 +1883,7 @@ CURLcode Curl_follow(struct Curl_easy *data, break; } Curl_pgrsTime(data, TIMER_REDIRECT); - Curl_pgrsResetTimesSizes(data); + Curl_pgrsResetTransferSizes(data); return CURLE_OK; #endif /* CURL_DISABLE_HTTP */ diff --git a/lib/urldata.h b/lib/urldata.h index b4f18e7da..e45baff17 100644 --- a/lib/urldata.h +++ b/lib/urldata.h @@ -1259,6 +1259,8 @@ struct Progress { struct curltime t_startop; struct curltime t_acceptdata; + bool is_t_startransfer_set; + /* upload speed limit */ struct curltime ul_limit_start; curl_off_t ul_limit_size; 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; + data.progress.start.tv_sec = now.tv_sec - 2; + data.progress.start.tv_usec = now.tv_usec; + fake_t_startsingle_time(&data, now, -2); - /* - * 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; - + 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"); + expect_timer_seconds(&data, 2); - /* - * 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); - - 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