HTTPDownloader: Log time for each request

src/util/http_downloader.cpp

@@ -40,7 +40,6 @@ void HTTPDownloader::CreateRequest(std::string url, Request::Callback callback,
   req->url = std::move(url);
   req->callback = std::move(callback);
   req->progress = progress;
-  req->start_time = Timer::GetCurrentValue();
 
   // set progress state to indeterminate until we know the size
   if (req->progress)
@@ -69,7 +68,6 @@ void HTTPDownloader::CreatePostRequest(std::string url, std::string post_data, R
   req->post_data = std::move(post_data);
   req->callback = std::move(callback);
   req->progress = progress;
-  req->start_time = Timer::GetCurrentValue();
 
   std::unique_lock lock(m_pending_http_request_lock);
   if (LockedGetActiveRequestCount() < m_max_active_requests)
@@ -102,7 +100,8 @@ void HTTPDownloader::LockedPollRequests(std::unique_lock<std::mutex>& lock)
     }
 
     if ((req_state == Request::State::Started || req_state == Request::State::Receiving) &&
-        current_time >= req->start_time && Timer::ConvertValueToSeconds(current_time - req->start_time) >= m_timeout)
+        current_time >= req->last_update_time &&
+        Timer::ConvertValueToSeconds(current_time - req->last_update_time) >= m_timeout)
     {
       // request timed out
       ERROR_LOG("Request for '{}' timed out", req->url);
@@ -157,8 +156,8 @@ void HTTPDownloader::LockedPollRequests(std::unique_lock<std::mutex>& lock)
     }
 
     // request complete
-    VERBOSE_LOG("Request for '{}' complete, returned status code {} and {} bytes", req->url, req->status_code,
-                req->data.size());
+    VERBOSE_LOG("Request for '{}' complete, returned status code {} and {} bytes, took {:.0f} ms", req->url,
+                req->status_code, req->data.size(), Timer::ConvertValueToMilliseconds(current_time - req->start_time));
     m_pending_http_requests.erase(m_pending_http_requests.begin() + index);
 
     // run callback with lock unheld

src/util/http_downloader.h

@@ -56,7 +56,8 @@ public:
     std::string content_type;
     Data data;
     Error error;
-    u64 start_time;
+    u64 start_time = 0;
+    u64 last_update_time = 0;
     s32 status_code = 0;
     u32 content_length = 0;
     u32 last_progress_update = 0;

src/util/http_downloader_curl.cpp

@@ -145,7 +145,7 @@ size_t HTTPDownloaderCurl::WriteCallback(char* ptr, size_t size, size_t nmemb, v
   const size_t transfer_size = size * nmemb;
   const size_t new_size = current_size + transfer_size;
   req->data.resize(new_size);
-  req->start_time = Timer::GetCurrentValue();
+  req->last_update_time = Timer::GetCurrentValue();
   std::memcpy(&req->data[current_size], ptr, transfer_size);
 
   if (req->content_length == 0)
@@ -301,6 +301,7 @@ bool HTTPDownloaderCurl::StartRequest(HTTPDownloader::Request* request)
   DEV_LOG("Started HTTP request for '{}'", req->url);
   req->state.store(Request::State::Started, std::memory_order_release);
   req->start_time = Timer::GetCurrentValue();
+  req->last_update_time = req->start_time;
 
   // Add to action queue for worker thread to process
   const std::unique_lock lock(m_worker_queue_mutex);

src/util/http_downloader_winhttp.cpp

@@ -236,7 +236,7 @@ void CALLBACK HTTPDownloaderWinHttp::HTTPStatusCallback(HINTERNET hRequest, DWOR
       const u32 new_size = req->io_position + dwStatusInformationLength;
       Assert(new_size <= req->data.size());
       req->data.resize(new_size);
-      req->start_time = Timer::GetCurrentValue();
+      req->last_update_time = Timer::GetCurrentValue();
 
       if (!WinHttpQueryDataAvailable(hRequest, nullptr) && GetLastError() != ERROR_IO_PENDING)
       {
@@ -340,6 +340,7 @@ bool HTTPDownloaderWinHttp::StartRequest(HTTPDownloader::Request* request)
   DEV_LOG("Started HTTP request for '{}'", req->url);
   req->state = Request::State::Started;
   req->start_time = Timer::GetCurrentValue();
+  req->last_update_time = req->start_time;
   return true;
 }