mirror of
https://github.com/curl/curl.git
synced 2026-07-28 14:23:07 +03:00
progress: fx CURLINFO time reporting
Whack the times reported for a transfer (see https://curl.se/libcurl/c/curl_easy_getinfo.html#TIMES) into order for all variations of up-/download, http/ftp etc. Make sure they are reported in the documented order. There is still the *possibility* of PRETRANSFER being longer then POSTTRANSFER, if a server sends a response before an upload is done. POST is the time the first response byte is received, and PRE is the time the last byte was sent by curl. This may happen with more likelihood on HTTP/2 and 3 for a server rejected upload. But for successful uploads, the answer will almost over come afterwards. Undo the previous twists in lib500.c tests, adjust pytest timeline checks. Fixes #21828 Reported-by: BazaarAcc32 on github Closes #21843
This commit is contained in:
Stefan Eissing
Daniel Stenberg
parent
317bf7e8a8
commit
fbcf10ab84
8 changed files with 159 additions and 109 deletions
114
lib/multi.c
114
lib/multi.c
|
|
@ -106,20 +106,56 @@ static const struct curltime *multi_now(struct Curl_multi *multi)
|
|||
return &multi->now;
|
||||
}
|
||||
|
||||
/* function pointer called once when switching TO a state */
|
||||
typedef void (*init_multistate_func)(struct Curl_easy *data);
|
||||
/* function pointer called once when entering a state */
|
||||
typedef void (*mstate_enter_func)(struct Curl_easy *data,
|
||||
CURLMstate from_state);
|
||||
|
||||
/* called in DID state, before PERFORMING state */
|
||||
static void before_perform(struct Curl_easy *data)
|
||||
static void mstate_enter_connect(struct Curl_easy *data,
|
||||
CURLMstate from_state)
|
||||
{
|
||||
data->req.chunk = FALSE;
|
||||
Curl_pgrsTime(data, TIMER_PRETRANSFER);
|
||||
(void)from_state;
|
||||
Curl_init_CONNECT(data);
|
||||
}
|
||||
|
||||
static void init_completed(struct Curl_easy *data)
|
||||
static void mstate_enter_did(struct Curl_easy *data,
|
||||
CURLMstate from_state)
|
||||
{
|
||||
/* this is a completed transfer */
|
||||
(void)from_state;
|
||||
data->req.chunk = FALSE;
|
||||
Curl_pgrsTime(data, TIMER_PRETRANSFER);
|
||||
if(!CURL_REQ_WANT_SEND(data))
|
||||
Curl_pgrsTime(data, TIMER_POSTRANSFER);
|
||||
}
|
||||
|
||||
static void mstate_enter_done(struct Curl_easy *data,
|
||||
CURLMstate from_state)
|
||||
{
|
||||
(void)from_state;
|
||||
CURLM_NTFY(data, CURLMNOTIFY_EASY_DONE);
|
||||
}
|
||||
|
||||
static void mstate_enter_completed(struct Curl_easy *data,
|
||||
CURLMstate from_state)
|
||||
{
|
||||
/* we sometimes directly jump to COMPLETED, trigger things
|
||||
* we then missed. */
|
||||
if(from_state < MSTATE_DID) {
|
||||
Curl_pgrsTime(data, TIMER_PRETRANSFER);
|
||||
Curl_pgrsTime(data, TIMER_POSTRANSFER);
|
||||
Curl_pgrsTime(data, TIMER_STARTTRANSFER);
|
||||
}
|
||||
Curl_pgrsCompleted(data);
|
||||
if(from_state < MSTATE_DONE)
|
||||
CURLM_NTFY(data, CURLMNOTIFY_EASY_DONE);
|
||||
/* changing to COMPLETED means it is in process and needs to go */
|
||||
DEBUGASSERT(Curl_uint32_bset_contains(&data->multi->process, data->mid));
|
||||
Curl_uint32_bset_remove(&data->multi->process, data->mid);
|
||||
Curl_uint32_bset_remove(&data->multi->pending, data->mid); /* to be sure */
|
||||
|
||||
if(Curl_uint32_bset_empty(&data->multi->process)) {
|
||||
/* free the transfer buffer when we have no more active transfers */
|
||||
multi_xfer_bufs_free(data->multi);
|
||||
}
|
||||
/* Important: reset the conn pointer so that we do not point to memory
|
||||
that could be freed anytime */
|
||||
Curl_detach_connection(data);
|
||||
|
|
@ -134,23 +170,23 @@ static void mstate(struct Curl_easy *data, CURLMstate state
|
|||
)
|
||||
{
|
||||
CURLMstate oldstate = data->mstate;
|
||||
static const init_multistate_func finit[MSTATE_LAST] = {
|
||||
NULL, /* INIT */
|
||||
NULL, /* PENDING */
|
||||
NULL, /* SETUP */
|
||||
Curl_init_CONNECT, /* CONNECT */
|
||||
NULL, /* CONNECTING */
|
||||
NULL, /* PROTOCONNECT */
|
||||
NULL, /* PROTOCONNECTING */
|
||||
NULL, /* DO */
|
||||
NULL, /* DOING */
|
||||
NULL, /* DOING_MORE */
|
||||
before_perform, /* DID */
|
||||
NULL, /* PERFORMING */
|
||||
NULL, /* RATELIMITING */
|
||||
NULL, /* DONE */
|
||||
init_completed, /* COMPLETED */
|
||||
NULL /* MSGSENT */
|
||||
static const mstate_enter_func state_enter[MSTATE_LAST] = {
|
||||
NULL, /* INIT */
|
||||
NULL, /* PENDING */
|
||||
NULL, /* SETUP */
|
||||
mstate_enter_connect, /* CONNECT */
|
||||
NULL, /* CONNECTING */
|
||||
NULL, /* PROTOCONNECT */
|
||||
NULL, /* PROTOCONNECTING */
|
||||
NULL, /* DO */
|
||||
NULL, /* DOING */
|
||||
NULL, /* DOING_MORE */
|
||||
mstate_enter_did, /* DID */
|
||||
NULL, /* PERFORMING */
|
||||
NULL, /* RATELIMITING */
|
||||
mstate_enter_done, /* DONE */
|
||||
mstate_enter_completed, /* COMPLETED */
|
||||
NULL /* MSGSENT */
|
||||
};
|
||||
|
||||
if(oldstate == state)
|
||||
|
|
@ -166,32 +202,8 @@ static void mstate(struct Curl_easy *data, CURLMstate state
|
|||
|
||||
/* really switching state */
|
||||
data->mstate = state;
|
||||
switch(state) {
|
||||
case MSTATE_DONE:
|
||||
CURLM_NTFY(data, CURLMNOTIFY_EASY_DONE);
|
||||
break;
|
||||
case MSTATE_COMPLETED:
|
||||
/* we sometimes directly jump to COMPLETED, trigger also a notification
|
||||
* in that case. */
|
||||
if(oldstate < MSTATE_DONE)
|
||||
CURLM_NTFY(data, CURLMNOTIFY_EASY_DONE);
|
||||
/* changing to COMPLETED means it is in process and needs to go */
|
||||
DEBUGASSERT(Curl_uint32_bset_contains(&data->multi->process, data->mid));
|
||||
Curl_uint32_bset_remove(&data->multi->process, data->mid);
|
||||
Curl_uint32_bset_remove(&data->multi->pending, data->mid); /* to be sure */
|
||||
|
||||
if(Curl_uint32_bset_empty(&data->multi->process)) {
|
||||
/* free the transfer buffer when we have no more active transfers */
|
||||
multi_xfer_bufs_free(data->multi);
|
||||
}
|
||||
break;
|
||||
default:
|
||||
break;
|
||||
}
|
||||
|
||||
/* if this state has an init-function, run it */
|
||||
if(finit[state])
|
||||
finit[state](data);
|
||||
if(state_enter[state])
|
||||
state_enter[state](data, oldstate);
|
||||
}
|
||||
|
||||
#ifndef DEBUGBUILD
|
||||
|
|
|
|||
|
|
@ -240,6 +240,30 @@ void Curl_pgrsSendPause(struct Curl_easy *data, bool enable)
|
|||
}
|
||||
}
|
||||
|
||||
#ifdef CURLVERBOSE
|
||||
static const char * const pgrs_timer_names[] = {
|
||||
"PGRS-NONE",
|
||||
"PGRS-STARTOP",
|
||||
"PGRS-STARTSINGLE",
|
||||
"PGRS-POSTQUEUE",
|
||||
"PGRS-NAMELOOKUP",
|
||||
"PGRS-CONNECT",
|
||||
"PGRS-APPCONNECT",
|
||||
"PGRS-PRETRANSFER",
|
||||
"PGRS-STARTTRANSFER",
|
||||
"PGRS-POSTRANSFER",
|
||||
"PGRS-STARTACCEPT",
|
||||
"PGRS-REDIRECT",
|
||||
};
|
||||
|
||||
static const char *pgrs_timer_name(timerid timer)
|
||||
{
|
||||
if((size_t)timer < CURL_ARRAYSIZE(pgrs_timer_names))
|
||||
return pgrs_timer_names[(size_t)timer];
|
||||
return "?";
|
||||
}
|
||||
|
||||
#endif /* CURLVERBOSE */
|
||||
/*
|
||||
* Curl_pgrsTimeWas(). Store the timestamp time at the given label.
|
||||
*/
|
||||
|
|
@ -285,7 +309,6 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer,
|
|||
delta = &data->progress.t_pretransfer;
|
||||
break;
|
||||
case TIMER_STARTTRANSFER:
|
||||
delta = &data->progress.t_starttransfer;
|
||||
/* prevent updating t_starttransfer unless:
|
||||
* 1. this is the first time we are setting t_starttransfer
|
||||
* 2. a redirect has occurred since the last time t_starttransfer was set
|
||||
|
|
@ -293,12 +316,12 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer,
|
|||
* changing the t_starttransfer time.
|
||||
*/
|
||||
if(data->progress.is_t_startransfer_set) {
|
||||
CURL_TRC_M(data, "[%s] ignored", pgrs_timer_name(timer));
|
||||
return;
|
||||
}
|
||||
else {
|
||||
data->progress.is_t_startransfer_set = TRUE;
|
||||
break;
|
||||
}
|
||||
data->progress.is_t_startransfer_set = TRUE;
|
||||
delta = &data->progress.t_starttransfer;
|
||||
break;
|
||||
case TIMER_POSTRANSFER:
|
||||
delta = &data->progress.t_posttransfer;
|
||||
break;
|
||||
|
|
@ -314,7 +337,11 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer,
|
|||
if(us < 1)
|
||||
us = 1; /* make sure at least one microsecond passed */
|
||||
*delta += us;
|
||||
CURL_TRC_M(data, "[%s] added %" FMT_TIMEDIFF_T "ns",
|
||||
pgrs_timer_name(timer), us);
|
||||
}
|
||||
else
|
||||
CURL_TRC_M(data, "[%s] set", pgrs_timer_name(timer));
|
||||
}
|
||||
|
||||
/*
|
||||
|
|
@ -703,3 +730,9 @@ void Curl_pgrsUpdate_nometer(struct Curl_easy *data)
|
|||
{
|
||||
(void)progress_calc(data, Curl_pgrs_now(data));
|
||||
}
|
||||
|
||||
void Curl_pgrsCompleted(struct Curl_easy *data)
|
||||
{
|
||||
struct Progress * const p = &data->progress;
|
||||
p->timespent = curlx_ptimediff_us(Curl_pgrs_now(data), &p->start);
|
||||
}
|
||||
|
|
|
|||
|
|
@ -83,4 +83,6 @@ void Curl_pgrsTimeWas(struct Curl_easy *data, timerid timer,
|
|||
|
||||
void Curl_pgrsEarlyData(struct Curl_easy *data, curl_off_t sent);
|
||||
|
||||
void Curl_pgrsCompleted(struct Curl_easy *data);
|
||||
|
||||
#endif /* HEADER_CURL_PROGRESS_H */
|
||||
|
|
|
|||
|
|
@ -271,7 +271,8 @@ static CURLcode req_set_upload_done(struct Curl_easy *data)
|
|||
data->req.upload_done = TRUE;
|
||||
CURL_REQ_CLEAR_SEND(data);
|
||||
|
||||
Curl_pgrsTime(data, TIMER_POSTRANSFER);
|
||||
if(data->mstate >= MSTATE_DID)
|
||||
Curl_pgrsTime(data, TIMER_POSTRANSFER);
|
||||
Curl_creader_done(data, data->req.upload_aborted);
|
||||
|
||||
if(data->req.upload_aborted) {
|
||||
|
|
|
|||
|
|
@ -183,7 +183,8 @@ static CURLcode cw_download_write(struct Curl_easy *data,
|
|||
bool is_connect = !!(type & CLIENTWRITE_CONNECT);
|
||||
|
||||
if(!ctx->started_response &&
|
||||
!(type & (CLIENTWRITE_INFO | CLIENTWRITE_CONNECT))) {
|
||||
!(type & CLIENTWRITE_CONNECT) &&
|
||||
(!(type & CLIENTWRITE_INFO) || data->req.upload_done)) {
|
||||
Curl_pgrsTime(data, TIMER_STARTTRANSFER);
|
||||
ctx->started_response = TRUE;
|
||||
}
|
||||
|
|
|
|||
|
|
@ -540,23 +540,8 @@ class ExecResult:
|
|||
ref_tl += ['time_namelookup', 'time_connect']
|
||||
if url.startswith('https:'):
|
||||
ref_tl += ['time_appconnect']
|
||||
# what kind of transfer was it?
|
||||
if s['size_upload'] == 0 and s['size_download'] > 0:
|
||||
# this is a download
|
||||
dl_tl = ['time_pretransfer']
|
||||
if s['size_request'] > 0:
|
||||
dl_tl = ['time_posttransfer'] + dl_tl
|
||||
ref_tl += dl_tl
|
||||
# the first byte of the response may arrive before we
|
||||
# track the other times when the client is slow (CI).
|
||||
somewhere_keys.extend(['time_starttransfer'])
|
||||
elif s['size_upload'] > 0 and s['size_download'] == 0:
|
||||
# this is an upload
|
||||
ul_tl = ['time_pretransfer', 'time_posttransfer']
|
||||
ref_tl += ul_tl
|
||||
else:
|
||||
# could be a 0-length upload or 0-length download, not sure
|
||||
exact_match = False
|
||||
ref_tl += ['time_pretransfer', 'time_posttransfer']
|
||||
somewhere_keys.extend(['time_starttransfer'])
|
||||
# always there at the end
|
||||
ref_tl += ['time_total']
|
||||
|
||||
|
|
|
|||
|
|
@ -127,10 +127,7 @@ static CURLcode test_lib500(const char *URL)
|
|||
(time_pretransfer / 1000000),
|
||||
(long)(time_pretransfer % 1000000));
|
||||
}
|
||||
if(time_posttransfer > time_pretransfer) {
|
||||
/* counter-intuitive: on a GET request, all bytes are sent *before*
|
||||
* PRETRANSFER happens. Thus POSTTRANSFER has to be smaller.
|
||||
* The reverse would be true for a POST/PUT. */
|
||||
if(time_pretransfer > time_posttransfer) {
|
||||
curl_mfprintf(moo, "pretransfer vs posttransfer: %"
|
||||
CURL_FORMAT_CURL_OFF_T
|
||||
".%06ld %" CURL_FORMAT_CURL_OFF_T ".%06ld\n",
|
||||
|
|
|
|||
|
|
@ -25,6 +25,25 @@
|
|||
#include "urldata.h"
|
||||
#include "progress.h"
|
||||
|
||||
static CURLcode t1399_setup(struct Curl_easy **easy)
|
||||
{
|
||||
CURLcode result = CURLE_OK;
|
||||
|
||||
global_init(CURL_GLOBAL_ALL);
|
||||
*easy = curl_easy_init();
|
||||
if(!*easy) {
|
||||
curl_global_cleanup();
|
||||
return CURLE_OUT_OF_MEMORY;
|
||||
}
|
||||
return result;
|
||||
}
|
||||
|
||||
static void t1399_stop(struct Curl_easy *easy)
|
||||
{
|
||||
curl_easy_cleanup(easy);
|
||||
curl_global_cleanup();
|
||||
}
|
||||
|
||||
/*
|
||||
* Invoke Curl_pgrsTime for TIMER_STARTSINGLE to trigger the behavior that
|
||||
* manages is_t_startransfer_set, but fake the t_startsingle time for purposes
|
||||
|
|
@ -72,45 +91,45 @@ static void expect_timer_seconds(struct Curl_easy *data, int seconds)
|
|||
* be 3 seconds. */
|
||||
static CURLcode test_unit1399(const char *arg)
|
||||
{
|
||||
UNITTEST_BEGIN_SIMPLE
|
||||
|
||||
struct Curl_easy data;
|
||||
struct Curl_easy *data;
|
||||
struct curltime now = curlx_now();
|
||||
|
||||
data.multi = NULL;
|
||||
data.progress.now = now;
|
||||
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);
|
||||
UNITTEST_BEGIN(t1399_setup(&data))
|
||||
|
||||
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);
|
||||
data->multi = NULL;
|
||||
data->progress.now = now;
|
||||
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);
|
||||
|
||||
expect_timer_seconds(&data, 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);
|
||||
|
||||
expect_timer_seconds(data, 2);
|
||||
|
||||
/* now simulate the redirect */
|
||||
data.progress.t_redirect = data.progress.t_starttransfer + 1;
|
||||
fake_t_startsingle_time(&data, now, -1);
|
||||
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);
|
||||
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);
|
||||
Curl_pgrsTime(data, TIMER_STARTTRANSFER);
|
||||
Curl_pgrsTime(data, TIMER_STARTTRANSFER);
|
||||
|
||||
expect_timer_seconds(&data, 3);
|
||||
expect_timer_seconds(data, 3);
|
||||
|
||||
UNITTEST_END_SIMPLE
|
||||
UNITTEST_END(t1399_stop(data))
|
||||
}
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue