Bug 2047477

Created attachment 1857223 [details]
strace of dnf and its forks

I have added also strace where I see repeated pattern of preread.

Created attachment 1857426 [details]
output of dnf update -y

This error sounded really scatchy as I haven't seen this on other computer with similar packageset. I suspected SSD have been having some issues (e.g. it has 100 Bad_Block_Count as reported by smartctl).

I was able to reproduce this with fresh new SSD though. Cleanup of that package took at least 3 minutes when I gave up and killed it.

I have collected strace and output data like this:

strace -f -o /mnt/strace_dnf_update.txt -s 1000 nice dnf upgrade -y | tee /mnt/dnf_upgrade_output.txt

I'm attaching that output.


strace is too big though - around 30GB - and I'm not sure how helpful that would be for you. Let me know if you would like to somehow get gist of it.

Couple of tests later ...

I was able to narrow the problem to upgrade of mint-y-icons:

$ dnf upgrade -y -x mint-icons

upgrades just fine. Followed by:

$ dnf upgrade -y

which upgrades mint-icons as well but cleanup makes dnf seemingly stuck. It turned out that this could take somewhere between half an hour and hour and it in the end finishes.

I've tried to use python's trace module but without luck - no visible operation:

$ python3 -m trace --trace /usr/bin/dnf upgrade --refresh -y 2>&1 | ts "%H:%M:%.S"

...
15:16:55.133176  --- modulename: util, funcname: _terminal_messenger
15:16:55.133204 util.py(389):     try:
15:16:55.133233 util.py(390):         if tp == 'write':
15:16:55.133263 util.py(392):         elif tp == 'flush':
15:16:55.133290 util.py(394):         elif tp == 'write_flush':
15:16:55.133319 util.py(395):             out.write(msg)
15:16:55.133348   Cleanup          : mint-y-icons-1.5.8-2.fc35.noarch                       2/2util.py(396):             out.flush()
16:51:54.947602 output.py(2019):                 self.lastmsg = msg
16:51:54.947665 output.py(2020):                 if ti_done == ti_total:
16:51:54.947683 output.py(2021):                     print(" ")
16:51:54.947704  
16:51:54.947727 rpmtrans.py(384):         for display in self.displays:
16:51:54.947748  --- modulename: rpmtrans, funcname: callback
16:51:54.947772 rpmtrans.py(271):         try:
16:51:54.947793 rpmtrans.py(272):             if isinstance(key, str):
16:51:54.947814 rpmtrans.py(273):                 key = ucd(key)
...


---

And similar slowness appears in undo history (again, with trace):

$ dnf history undo last

...

17:16:53.447031  --- modulename: util, funcname: _terminal_messenger
17:16:53.447068 util.py(389):     try:
17:16:53.447107 util.py(390):         if tp == 'write':
17:16:53.447142 util.py(392):         elif tp == 'flush':
17:16:53.447176 util.py(394):         elif tp == 'write_flush':
17:16:53.447215 util.py(395):             out.write(msg)
17:16:53.447247   Cleanup          : mint-y-icons-1.5.9-1.fc35.noarch                       2/2util.py(396):             out.flush()
17:41:50.771286 output.py(2019):                 self.lastmsg = msg
17:41:50.771367 output.py(2020):                 if ti_done == ti_total:
17:41:50.771414 output.py(2021):                     print(" ")
17:41:50.771445  
17:41:50.771472 rpmtrans.py(384):         for display in self.displays:
17:41:50.771497  --- modulename: rpmtrans, funcname: callback

...

(In reply to scroolik from comment #3)
> Couple of tests later ...
> 
> I was able to narrow the problem to upgrade of mint-y-icons:
> 
> $ dnf upgrade -y -x mint-icons

A typo here:

s/mint-icons/mint-y-icons/

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