From fbcf10ab84d75e76029e50d0b22793a218181166 Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Tue, 2 Jun 2026 11:10:10 +0200 Subject: [PATCH] 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 --- lib/multi.c | 114 ++++++++++++++++++++----------------- lib/progress.c | 43 ++++++++++++-- lib/progress.h | 2 + lib/request.c | 3 +- lib/sendf.c | 3 +- tests/http/testenv/curl.py | 19 +------ tests/libtest/lib500.c | 5 +- tests/unit/unit1399.c | 79 +++++++++++++++---------- 8 files changed, 159 insertions(+), 109 deletions(-) diff --git a/lib/multi.c b/lib/multi.c index 1948bbda77..fe9bcfaeaf 100644 --- a/lib/multi.c +++ b/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 diff --git a/lib/progress.c b/lib/progress.c index 919c151e75..d34b155e32 100644 --- a/lib/progress.c +++ b/lib/progress.c @@ -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); +} diff --git a/lib/progress.h b/lib/progress.h index 7d419ecb8a..1f2a4e71c3 100644 --- a/lib/progress.h +++ b/lib/progress.h @@ -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 */ diff --git a/lib/request.c b/lib/request.c index 4ecb462951..de07c6aa13 100644 --- a/lib/request.c +++ b/lib/request.c @@ -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) { diff --git a/lib/sendf.c b/lib/sendf.c index c5936514a1..38abb04955 100644 --- a/lib/sendf.c +++ b/lib/sendf.c @@ -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; } diff --git a/tests/http/testenv/curl.py b/tests/http/testenv/curl.py index 8fb17349ab..64c1cacd46 100644 --- a/tests/http/testenv/curl.py +++ b/tests/http/testenv/curl.py @@ -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'] diff --git a/tests/libtest/lib500.c b/tests/libtest/lib500.c index 71b1eaed8f..6e64704ee0 100644 --- a/tests/libtest/lib500.c +++ b/tests/libtest/lib500.c @@ -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", diff --git a/tests/unit/unit1399.c b/tests/unit/unit1399.c index e1e472a536..909b13e8b2 100644 --- a/tests/unit/unit1399.c +++ b/tests/unit/unit1399.c @@ -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)) }