aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorRyan Winograd <ryan@thewinograds.com>2017-06-21 12:15:46 -0500
committerDaniel Stenberg <daniel@haxx.se>2017-08-15 18:58:31 +0200
commit43d036e72488b4be5f48aaec9278a55dc22cb556 (patch)
tree32de6e2fd9ac79fac4fc5cc9ba75f4d2c614bd84
parent0969901eb9a2efb9f204a48c2538925d27944444 (diff)
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
-rw-r--r--docs/KNOWN_BUGS7
-rw-r--r--lib/getinfo.c1
-rw-r--r--lib/progress.c16
-rw-r--r--lib/progress.h2
-rw-r--r--lib/transfer.c4
-rw-r--r--lib/urldata.h2
-rw-r--r--tests/unit/unit1399.c95
7 files changed, 69 insertions, 58 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;
-
- /*
- * 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