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)) }