From caf4e98f0c0a0a7178538ee8ef7b199d2a655aac 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 --- 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 cbbb0fe7a34..e7dae333be2 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -71,7 +71,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() { @@ -373,10 +376,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 8ffea0a018874e60584eabeb620ec3495873c30d 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. --- 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 e7dae333be2..f48c2e22d7b 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -858,7 +858,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 1f5b4ab934c..d836ab2c4a7 100644 --- a/src/libstore/filetransfer.hh +++ b/src/libstore/filetransfer.hh @@ -47,6 +47,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 f6a9a71b38b25d6c9fb0b9a7fbf0eccf99fa5520 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 --- src/libstore/filetransfer.cc | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/libstore/filetransfer.cc b/src/libstore/filetransfer.cc index f48c2e22d7b..5ea8b6f962c 100644 --- a/src/libstore/filetransfer.cc +++ b/src/libstore/filetransfer.cc @@ -860,6 +860,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 01839b525c5e80d7f67f2808f7f7fb478ddf1ba0 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. --- 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 2968d2df2a4..5710b94d523 100644 --- a/src/libfetchers/github.cc +++ b/src/libfetchers/github.cc @@ -254,10 +254,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 55db3eafbc1..5837cf8a49c 100644 --- a/src/libfetchers/tarball.cc +++ b/src/libfetchers/tarball.cc @@ -143,6 +143,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 @@ -167,6 +170,8 @@ DownloadTarballResult downloadTarball( auto parseSink = getTarballCache()->getFileSystemObjectSink(); auto lastModified = unpackTarfileToSink(archive, *parseSink); + act.reset(); + auto res(_res->lock()); Attrs infoAttrs;