From 211b0d4e1346451c7dddbb79d7d4804507d81bab Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Wed, 24 Jul 2024 20:10:41 +0200 Subject: [PATCH 1/4] Log download durations (cherry picked from commit caf4e98f0c0a0a7178538ee8ef7b199d2a655aac) --- src/libstore/filetransfer.cc | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/libstore/filetransfer.cc b/src/libstore/filetransfer.cc index bab21bf51..d20fb2b17 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -67,7 +67,10 @@ struct curlFileTransfer : public FileTransfer curl_off_t writtenToSink = 0; + std::chrono::steady_clock::time_point startTime = std::chrono::steady_clock::now(); + inline static const std::set successfulStatuses {200, 201, 204, 206, 304, 0 /* other protocol */}; + /* Get the HTTP status code, or 0 for other protocols. */ long getHTTPStatus() { @@ -369,10 +372,14 @@ struct curlFileTransfer : public FileTransfer void finish(CURLcode code) { + auto finishTime = std::chrono::steady_clock::now(); + auto httpStatus = getHTTPStatus(); - debug("finished %s of '%s'; curl status = %d, HTTP status = %d, body = %d bytes", - request.verb(), request.uri, code, httpStatus, result.bodySize); + debug("finished %s of '%s'; curl status = %d, HTTP status = %d, body = %d bytes, duration = %.2f s", + request.verb(), request.uri, code, httpStatus, result.bodySize, + std::chrono::duration_cast(finishTime - startTime).count() / 1000.0f + ); appendCurrentUrl(); From 56140d974eac977683686028a071eaeedae08799 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Wed, 24 Jul 2024 20:10:45 +0200 Subject: [PATCH 2/4] Add 'download-buffer-size' setting We are piping curl downloads into `unpackTarfileToSink()`, but the latter is typically slower than the former if you're on a fast connection. So the download could appear unnecessarily slow. (There is even a risk that if the Git import is *really* slow for whatever reason, the TCP connection could time out.) So let's make the download buffer bigger by default - 64 MiB is big enough for the Nixpkgs tarball. Perhaps in the future, we could have an unlimited buffer that spills data to disk beyond a certain threshold, but that's probably overkill. (cherry picked from commit 8ffea0a018874e60584eabeb620ec3495873c30d) --- src/libstore/filetransfer.cc | 2 +- src/libstore/filetransfer.hh | 6 ++++++ 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/src/libstore/filetransfer.cc b/src/libstore/filetransfer.cc index d20fb2b17..02ac9e067 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -835,7 +835,7 @@ void FileTransfer::download( buffer). We don't wait forever to prevent stalling the download thread. (Hopefully sleeping will throttle the sender.) */ - if (state->data.size() > 1024 * 1024) { + if (state->data.size() > fileTransferSettings.downloadBufferSize) { debug("download buffer is full; going to sleep"); state.wait_for(state->request, std::chrono::seconds(10)); } diff --git a/src/libstore/filetransfer.hh b/src/libstore/filetransfer.hh index 1c271cbec..221a2b0ea 100644 --- a/src/libstore/filetransfer.hh +++ b/src/libstore/filetransfer.hh @@ -45,6 +45,12 @@ struct FileTransferSettings : Config Setting tries{this, 5, "download-attempts", "How often Nix will attempt to download a file before giving up."}; + + Setting downloadBufferSize{this, 64 * 1024 * 1024, "download-buffer-size", + R"( + The size of Nix's internal download buffer during `curl` transfers. If data is + not processed quickly enough to exceed the size of this buffer, downloads may stall. + )"}; }; extern FileTransferSettings fileTransferSettings; From 682f60b4f78f1e939e638898eef4d61e0f4a5e95 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Wed, 24 Jul 2024 20:14:31 +0200 Subject: [PATCH 3/4] Warn if the download buffer is full (cherry picked from commit f6a9a71b38b25d6c9fb0b9a7fbf0eccf99fa5520) --- src/libstore/filetransfer.cc | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/libstore/filetransfer.cc b/src/libstore/filetransfer.cc index 02ac9e067..6f4ca653c 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -837,6 +837,8 @@ void FileTransfer::download( sender.) */ if (state->data.size() > fileTransferSettings.downloadBufferSize) { debug("download buffer is full; going to sleep"); + static bool haveWarned = false; + warnOnce(haveWarned, "download buffer is full; consider increasing the 'download-buffer-size' setting"); state.wait_for(state->request, std::chrono::seconds(10)); } From ea37d81a0ff6064917eeaa92493139ba9feda5f1 Mon Sep 17 00:00:00 2001 From: Eelco Dolstra Date: Wed, 24 Jul 2024 20:22:26 +0200 Subject: [PATCH 4/4] Show when we're unpacking an archive into the Git cache This happens in parallel with the download (which starts later), so you only see this message when the download has finished but the import hasn't. (cherry picked from commit 01839b525c5e80d7f67f2808f7f7fb478ddf1ba0) --- src/libfetchers/github.cc | 5 +++++ src/libfetchers/tarball.cc | 5 +++++ 2 files changed, 10 insertions(+) diff --git a/src/libfetchers/github.cc b/src/libfetchers/github.cc index 60e323464..793e8346c 100644 --- a/src/libfetchers/github.cc +++ b/src/libfetchers/github.cc @@ -248,10 +248,15 @@ struct GitArchiveInputScheme : InputScheme getFileTransfer()->download(std::move(req), sink); }); + auto act = std::make_unique(*logger, lvlInfo, actUnknown, + fmt("unpacking '%s' into the Git cache", input.to_string())); + TarArchive archive { *source }; auto parseSink = getTarballCache()->getFileSystemObjectSink(); auto lastModified = unpackTarfileToSink(archive, *parseSink); + act.reset(); + TarballInfo tarballInfo { .treeHash = parseSink->sync(), .lastModified = lastModified diff --git a/src/libfetchers/tarball.cc b/src/libfetchers/tarball.cc index e58eddb65..2e5e78235 100644 --- a/src/libfetchers/tarball.cc +++ b/src/libfetchers/tarball.cc @@ -156,6 +156,9 @@ DownloadTarballResult downloadTarball( // TODO: fall back to cached value if download fails. + auto act = std::make_unique(*logger, lvlInfo, actUnknown, + fmt("unpacking '%s' into the Git cache", url)); + AutoDelete cleanupTemp; /* Note: if the download is cached, `importTarball()` will receive @@ -180,6 +183,8 @@ DownloadTarballResult downloadTarball( auto parseSink = getTarballCache()->getFileSystemObjectSink(); auto lastModified = unpackTarfileToSink(archive, *parseSink); + act.reset(); + auto res(_res->lock()); Attrs infoAttrs;