Bug 2315665

Summary: "dnf history" is very slow
Product: [Fedora] Fedora Reporter: Jonathan Billings <jbilling>
Component: dnf5Assignee: amatej
Status: CLOSED ERRATA QA Contact:
Severity: medium Docs Contact:
Priority: unspecified    
Version: 41CC: amatej, jkolarik, kparal, moschlegbz, nsella, pkratoch, ppisar, rpm-software-management
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: dnf5-5.2.7.0-1.fc41 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2025-03-10 15:43:44 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 2184978    

Description Jonathan Billings 2024-09-30 13:01:37 UTC 
Hello,

In Fedora 41, dnf5 history list operations are extremely slow. This is on a system where I've been using dnf5 since Fedora 38, but the problems only seemed to start in Fedora 41. 

Running /usr/bin/time -v dnf history list results in:

	Command being timed: "sudo dnf5 history list"
	User time (seconds): 0.00
	System time (seconds): 0.02
	Percent of CPU this job got: 0%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:35.65
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 9732
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 954
	Voluntary context switches: 344
	Involuntary context switches: 10
	Swaps: 0
	File system inputs: 0
	File system outputs: 0
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0

I looked into the list, and I see that every time the Fedora Linux CSB Ansible playbook runs, there are 20 new history entries that look like this:

$ sudo dnf history info 871
Transaction ID : 871
Begin time     : 2024-09-30 12:06:41
Begin rpmdb    : 28906e8593751d6d24a74989ce0fdf8c501cd594dfcf525acd16b71baf93dfe2
End time       : 2024-09-30 12:06:42
End rpmdb      : 28906e8593751d6d24a74989ce0fdf8c501cd594dfcf525acd16b71baf93dfe2
User           : 0 Super User <root>
Status         : Ok
Releasever     : 41
Description    : ansible dnf5 module
Comment        : 

It looks like an entry like that corresponds to every time an ansible.builtin.dnf module runs, regardless of whether anything changes.  The rpmdb hash is the same for beginning and end.  This is probably a bug in the ansible.builtin.dnf module, and I can file a separate bug against that, but the dnf history issue remains.

For what it's worth, I immediately get readable results by running:

echo 'select id,dt_end,user_id,description from trans order by id desc;' | sqlite3 -tabs /usr/lib/sysimage/libdnf5/transaction_history.sqlite

So, I expect dnf history is doing an incredibly inefficient query.

Reproducible: Always

Steps to Reproduce:
1. Install Fedora Linux 41
2. Have an ansible playbook run dnf tasks periodically over several days
3. Build up 800 transactions in dnf history
Actual Results:  
Running 'dnf history list' takes ~30 seconds to complete

Expected Results:  
'dnf history list' should take only a second or less to run.
Comment 1 Petr Pisar 2024-10-02 10:10:00 UTC 
Yes, "dnf history" is slow and it's not caused by ansible.builtin.dnf module. I also experience the slowness and I don't use that module. At least I'm not aware I would use it.
Comment 2 M. Schlegel 2024-10-07 02:44:08 UTC 
I've seen this too and it's not related to ansible playbook in my case.  I have no ansible being used and dnf history list is very slow for me too on more than one laptop (SSD m.2 drives in use so no spinning disk is hosting the DNF dbs and files).
Comment 3 M. Schlegel 2024-10-07 03:42:51 UTC 
I've noticed that when I run dnf history list as root and it's doing this slow thing, "iotop -a"  (iotop in accumulate mode) shows the dnf process is writing tons of bytes (GBs) to my disk.  When I snoop around 
and used "lsof -p $(pgrep dnf)" that led me to this file constantly changing size due to writes from dnf5:

/usr/lib/sysimage/libdnf/transaction_history.sqlite-shm

it gets bigger then at some point gets small again, then gets big again.

Finally I tried running "strace -p $(pgrep dnf)" which showed a constant flood of these pread64 calls:

pread64(5, "\0\0\0\227\0\0\0\0tG\302\374\31\255|\\\323h\211b\0\v\222k\n\0\0\0\223\18\0"..., 4120, 38311912) = 4120
pread64(5, "\0\0\1Y\0\0\0\0tG\302\374\31\255|\\\205\31\356\263.E\234z\n\5\210\1j\3x\0"..., 4120, 38316032) = 4120
pread64(5, "\0\0\1v\0\0\0\0tG\302\374\31\255|\\\371\335!\353s\222\274\25\r\0\0\0\f\7:\0"..., 4120, 38320152) = 4120
pread64(5, "\0\0\1w\0\0\0\0tG\302\374\31\255|\\\263\275\306_\353\224\312\330\n\0\0\1]\5\30\0"..., 4120, 38324272) = 4120
pread64(5, "\0\0\1x\0\0\0\0tG\302\374\31\255|\\;N\333%\363\234\252o\n\0\0\1x\4@\0"..., 4120, 38328392) = 4120
pread64(5, "\0\0\1y\0\0\0\0tG\302\374\31\255|\\\215\37\r\210\361\266\267\34\r\0\0\0\212\rN\0"..., 4120, 38332512) = 4120
pread64(5, "\0\0\1z\0\0\0\0tG\302\374\31\255|\\ \276V\351\326\345Da\r\0\0\0g\5,\0"..., 4120, 38336632) = 4120
pread64(5, "\0\0\1{\0\0\0\0tG\302\374\31\255|\\\272\330\253\224\212\361\313\277\r\0\0\0\322\1\342\0"..., 4120, 38340752) = 4120
pread64(5, "\0\0\1}\0\0\1~tG\302\374\31\255|\\2K\350\210\261\351\276\257\n\0\0\1F\5\320\0"..., 4120, 38344872) = 4120
pread64(5, "\0\0\1v\0\0\1~tG\302\374\31\255|\\\250\236\357H\205\351\222^\r\0\0\0\f\6\364\0"..., 4120, 38348992) = 4120
pread64(5, "\0\0\0\1\0\0\0\0tG\302\374\31\255|\\jn\343\326\301B\27\rSQLite f"..., 4120, 38353112) = 4120
pread64(5, "\0\0\0\4\0\0\0\0tG\302\374\31\255|\\eS\270yvB\343-\r\0\0\0\2\17\343\0"..., 4120, 38357232) = 4120
^Cpread64(5, strace: Process 5423 detached

I have no idea how to interpret that.
Comment 4 amatej 2024-10-21 05:49:29 UTC 
I made a PR that should improve the situation: https://github.com/rpm-software-management/dnf5/pull/1778
Comment 5 Colin J Thomson 2024-10-26 11:00:10 UTC 
Running the nightly builds here, a huge improvement with your fix (fedora 41):

Command being timed: "dnf5 history list"
        User time (seconds): 0.23
        System time (seconds): 0.05
        Percent of CPU this job got: 98%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.29
Comment 6 M. Schlegel 2024-12-12 19:52:53 UTC 
I have dnf version 5.2.8.1 and "dnf history list" is now very fast.

time dnf history list
real    0m0.344s
user    0m0.256s
sys     0m0.049s

So this can taken out of "ASSIGNED"