Bug 1236046 - long delay before downloading the first package
Summary: long delay before downloading the first package
Keywords:
Status: CLOSED DUPLICATE of bug 1194222
Alias: None
Product: Fedora
Classification: Fedora
Component: dnf
Version: 22
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Packaging Maintenance Team
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-06-26 12:20 UTC by Kamil Páral
Modified: 2015-08-10 11:24 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2015-07-29 12:02:25 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
dnf.librepo.log excerpt when a long delay was experienced (87.62 KB, text/plain)
2015-06-26 12:21 UTC, Kamil Páral
no flags Details

Description Kamil Páral 2015-06-26 12:20:08 UTC
Description of problem:
I'm on a 1Gb/s network with private Fedora mirrors. All the packages are usually downloaded in a matter of seconds. Yet, with dnf, the first package to download suffers a "random" delay of 2-60? seconds, before the downloading really starts. This is different to yum, which started downloading immediately after confirming the transaction.

With dnf, I see "Downloading packages:" line and then a blinking cursor with no other feedback for some time. After the random wait, all packages are downloaded immediately.

My theory is that dnf is trying to contact some mirrors before the download operation starts, and some mirrors are slow from time to time. However, this seems to happen always, even when all metalinks are up-to-date (for example when I had performed other dnf operations in the last few minutes). dnf seems to try to contact the mirrors always, not just when needed, and waits until it is done, which slows down every operation. But that's just my theory.

mluscon on #yum asked me to try to identify the long operation in /var/log/dnf.librepo.log, so I attach a part of that log with a few comments inside roughly where the wait occurred. However, this is really hard to reproduce reliably (the 30+ sec timeout occurs just sometimes, usually it is just a few seconds), so it's very approximate. I can try harder if needed.

Maybe there is a reason why dnf is waiting for something to happen, before the downloading starts. But if that operation takes more than 5-10 seconds, it should give users some feedback. (Even when I run it with -v, there is *no* feedback what it is waiting for). Otherwise it just seems like stuck and it contributes to a poor user experience and perceived slowness.


Version-Release number of selected component (if applicable):
dnf-1.0.1-2.fc22.noarch
hawkey-0.5.7-1.fc22.x86_64
librepo-1.7.16-1.fc22.x86_64
libsolv-0.6.10-1.fc22.x86_64

How reproducible:
random

Steps to Reproduce:
1. run something like dnf makecache or dnf install foo to make sure all your repo metadata is up to date
2. run dnf install bar and confirm Y to run the operation
3. see that after "Downloading packages:" is printed out, you stare at a blinking cursor for a random delay (sometimes very long), before the packages start to be really downloaded. See no feedback during that time that would explain why nothing is happening.

Comment 1 Kamil Páral 2015-06-26 12:21:20 UTC
Created attachment 1043492 [details]
dnf.librepo.log excerpt when a long delay was experienced

Comment 2 Radek Holy 2015-07-29 12:02:25 UTC

*** This bug has been marked as a duplicate of bug 1194222 ***

Comment 3 Kamil Páral 2015-08-04 09:06:44 UTC
Radek, are you sure this is a duplicate? Bug 1194222 seems to be referring to slow operations before "depsolving starts", and seems to be caused by slow yumdb access. This bug occurs after depsolving is complete (I assume, because the installation summary is already printed out) and it seems to be caused by network. That seems to be also suggested by the variable delay. If it was CPU-bound, the delay would be always the same. Also, I see no CPU spike during this delay.

Comment 4 Radek Holy 2015-08-10 10:00:03 UTC
Well, it is a duplicate of the bug 1234907 which has been closed as a duplicate of the bug 1194222.

Comment 5 Kamil Páral 2015-08-10 11:24:08 UTC
OK, this really seems to be a duplicate of bug 1234907. Thanks for info.


Note You need to log in before you can comment on or make changes to this bug.