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.
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.
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).
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.
I made a PR that should improve the situation: https://github.com/rpm-software-management/dnf5/pull/1778
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
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"