Hi, just a question, whether it can be faster than 4 sec ? $ time /usr/bin/qlop -r 2019-09-19T19:41:14 >>> www-client/firefox... (1 of 1) ETA: 24′41″ real 0m4.019s user 0m3.947s sys 0m0.048s $ wc /var/log/emerge.log 255266 1776462 22257698 /var/log/emerge.log ;-)
Unfortunately, Portage's log-format is very ill-defined (if defined at all). This is an issue when parallel merges happen. 4 seconds is kind of slow, I don't think your emerge.log file is very large either (21MiB?). I'll give it some thoughts if we can walk backwards in the file to identify running merge processes, that should speedup in terms of CPU (which I don't expect to be your problem), as well as IO (which I suspect is your problem). Just for my info, what kind of system is this? (rough hardware specs)
(In reply to Fabian Groffen from comment #1) > Unfortunately, Portage's log-format is very ill-defined (if defined at all). yep, it is a nightmare to be parsed > Just for my info, what kind of system is this? (rough hardware specs) $ uname -a Linux t44 5.2.16 #8 SMP Thu Sep 19 19:25:14 CEST 2019 x86_64 Intel(R) Core(TM) i5-4300U CPU @ 1.90GHz GenuineIntel GNU/Linux BTW now where FF was emerged it speeds up to 2 sec: $ time /usr/bin/qlop --merge --unmerge --verbose --time --human -r real 0m2.077s user 0m2.047s sys 0m0.030s
I'll see if I can profile this, it seems 2-4 seconds to parse 21MiB*2 on timestamps is a bit much. It's much faster when -r isn't being used, (for a 26MiB file, ~4s for -r, <1s without -r) which triggers -a to compute the average. -r is actually as slow as -a, I think because it's averaging all packages, which probably also takes quite some memory.
(In reply to Fabian Groffen from comment #3) > I'll see if I can profile this, it seems 2-4 seconds to parse 21MiB*2 on > timestamps is a bit much. > > It's much faster when -r isn't being used, (for a 26MiB file, ~4s for -r, > <1s without -r) which triggers -a to compute the average. -r is actually as > slow as -a, I think because it's averaging all packages, which probably also > takes quite some memory. But if -r is used together with a package then it is fast again: $ time /usr/bin/qlop --merge --unmerge --verbose --time --human -r 2019-09-20T16:42:28 >>> media-libs/mesa-19.1.7: 12 minutes, 45 seconds... (14 of 16) ETA: 5 minutes, 8 seconds (average run) real 0m4.012s user 0m3.902s sys 0m0.047s $ time /usr/bin/qlop --merge --unmerge --verbose --time --human -r mesa 2019-09-20T16:42:28 >>> media-libs/mesa-19.1.7: 12 minutes, 49 seconds... (14 of 16) ETA: 5 minutes, 4 seconds (average run) real 0m0.163s user 0m0.146s sys 0m0.008s
(In reply to Toralf Förster from comment #4) > But if -r is used together with a package then it is fast again: > > $ time /usr/bin/qlop --merge --unmerge --verbose --time --human -r > 2019-09-20T16:42:28 >>> media-libs/mesa-19.1.7: 12 minutes, 45 seconds... > (14 of 16) ETA: 5 minutes, 8 seconds (average run) > > real 0m4.012s > user 0m3.902s > sys 0m0.047s > > $ time /usr/bin/qlop --merge --unmerge --verbose --time --human -r mesa > 2019-09-20T16:42:28 >>> media-libs/mesa-19.1.7: 12 minutes, 49 seconds... > (14 of 16) ETA: 5 minutes, 4 seconds (average run) > > real 0m0.163s > user 0m0.146s > sys 0m0.008s Yes, this is an artifact of calculating the averages, qlop is simply computing average times for *all* packages, and then it looks which one never had a closing logline, assuming that those are the ones currently running. The smarts would be to first determine which packages are currently still running, and then compute the averages in order to show the estimates. Still I suspect the average computation (or the storage/matching thereof) is not as snappy as it should be, what does qlop -a | wc -l return for you? something in the 5000 range?
(In reply to Fabian Groffen from comment #5) > not as snappy as it should be, what does qlop -a | wc -l return for you? > something in the 5000 range? yep: $ head -n 1 /var/log/emerge.log 1417968809: Started emerge on: Dec 07, 2014 16:13:29 $ qlop -a | wc -l 3529
The bug has been referenced in the following commit(s): https://gitweb.gentoo.org/proj/portage-utils.git/commit/?id=18ceb0276719b34a769aa4bc8ef8556776967090 commit 18ceb0276719b34a769aa4bc8ef8556776967090 Author: Fabian Groffen <grobian@gentoo.org> AuthorDate: 2019-09-21 19:50:06 +0000 Commit: Fabian Groffen <grobian@gentoo.org> CommitDate: 2019-09-21 19:50:06 +0000 qlop: improve performance for -a (and thus -r), bug #694972 Bring down runtime for -a or -f (without atoms) from ~4s to ~0.6s. Bug: https://bugs.gentoo.org/694972 Signed-off-by: Fabian Groffen <grobian@gentoo.org> TODO.md | 1 + qlop.c | 191 ++++++++++++++++++++++++++++++++-------------------------------- 2 files changed, 97 insertions(+), 95 deletions(-)
I'll see if I can make -r select the packages that are "unfinished" in the first scan qlop does, but I'm not sure this is as simple as it sounds.
(In reply to Fabian Groffen from comment #8) > I'll see if I can make -r select the packages that are "unfinished" in the > first scan qlop does, but I'm not sure this is as simple as it sounds. Could it just search backwards through the log for timestamps newer than what /proc/uptime indicates? I've got a ~15MB emerge.log, and assuming a few weeks uptime, doing that would allow to skip 99% of it.
The problem is that it still has to search for the start of an emerge sequence, plus that you want the average based on the full log-file (= best approximation). Code in 0.80 does a naive search for every package it finds, this is where it spends most of its time. I've reduced this cost quite some. Any improvements here can indeed be made by reducing the amount of packages the average has to be computed for. (Compare e.g. qlop -r foo.) This, however, requires a 3rd scan and quite some code overhaul. I'm hoping the performance in git is acceptable to most.
The speed problems here are not limited to the -r option. E.g. a simple listing of merged packages (-l vs -m) went up by a factor of 20 after upgrading to version 0.80. Even genlop is much faster now (about a factor of tree), which is written in perl. I have a ~50MiB emerge.log file. For the -r switch it might be beneficial to allow disabling ETA calculation at all. Furthermore, it would be beneficial to just skip the scanning of the log file if portage is not running. Example use case: I used qlop before for conky to display the current emerged package. But with the current implementation this is not feasible anymore, because that would consume a complete CPU core, when refreshing every 5 seconds.
Would it be possible for you to share your emerge.log and the exact invocations you're using? Also, have you tried using portage-utils-9999?
(In reply to Fabian Groffen from comment #12) > Would it be possible for you to share your emerge.log and the exact > invocations you're using? Also, have you tried using portage-utils-9999? FWIW here is my file: https://www.zwiebeltoralf.de/pub/emerge.log.xz
Whilst we are discussing here performance, what's about the ETA calculation? : Maybe the algorithm should not take too old results into account? here's an example where old values aren't helpful: $ /usr/bin/qlop --merge --unmerge --verbose --time --human digikam 2014-12-08T15:08:53 >>> media-gfx/digikam-3.5.0: 20 minutes, 2 seconds 2014-12-10T22:51:34 >>> media-gfx/digikam-4.4.0-r1: 22 minutes, 2 seconds 2014-12-14T23:48:51 >>> media-gfx/digikam-4.4.0-r1: 20 minutes, 55 seconds 2015-08-13T18:53:10 >>> media-gfx/digikam-4.4.0-r1: 17 minutes, 42 seconds 2016-03-05T18:10:14 >>> media-gfx/digikam-4.4.0-r1: 12 minutes, 43 seconds 2016-05-02T02:21:26 >>> media-gfx/digikam-4.4.0-r1: 10 minutes, 43 seconds 2016-05-10T17:21:08 >>> media-gfx/digikam-4.4.0-r1: 9 minutes, 26 seconds 2016-05-23T18:38:42 >>> media-gfx/digikam-4.4.0-r1: 9 minutes, 30 seconds 2016-06-22T20:21:08 >>> media-gfx/digikam-4.4.0-r1: 9 minutes, 10 seconds 2016-07-03T23:37:23 >>> media-gfx/digikam-4.4.0-r1: 9 minutes, 16 seconds 2016-07-06T10:38:21 >>> media-gfx/digikam-4.14.0-r1: 9 minutes, 31 seconds 2016-07-10T17:34:27 >>> media-gfx/digikam-5.0.0: 27 minutes, 40 seconds 2016-07-10T18:02:08 <<< media-gfx/digikam-4.14.0-r1: 14 seconds 2016-08-10T21:59:14 >>> media-gfx/digikam-5.1.0: 28 minutes, 35 seconds 2016-08-18T10:09:47 >>> media-gfx/digikam-5.1.0-r1: 27 minutes, 40 seconds 2016-10-19T15:44:21 >>> media-gfx/digikam-5.1.0-r1: 27 minutes, 35 seconds 2016-10-31T21:37:33 >>> media-gfx/digikam-5.2.0: 27 minutes, 5 seconds 2016-11-08T00:07:03 >>> media-gfx/digikam-5.3.0: 28 minutes, 7 seconds 2016-11-12T09:43:55 >>> media-gfx/digikam-5.3.0: 26 minutes, 31 seconds 2016-12-17T11:13:24 >>> media-gfx/digikam-5.3.0: 33 minutes, 52 seconds 2017-01-10T21:41:57 >>> media-gfx/digikam-5.3.0-r1: 26 minutes, 37 seconds 2017-03-26T11:19:28 >>> media-gfx/digikam-5.5.0: 26 minutes, 55 seconds 2017-04-18T14:08:08 >>> media-gfx/digikam-5.5.0: 24 minutes, 20 seconds 2017-10-17T21:32:41 >>> media-gfx/digikam-5.5.0: 24 minutes, 46 seconds 2017-11-06T19:18:50 >>> media-gfx/digikam-5.5.0: 25 minutes, 57 seconds 2017-11-20T06:57:53 >>> media-gfx/digikam-5.5.0: 26 minutes, 22 seconds 2017-12-16T19:31:14 >>> media-gfx/digikam-5.7.0-r1: 30 minutes, 13 seconds 2018-03-30T09:35:31 >>> media-gfx/digikam-5.7.0-r3: 28 minutes, 21 seconds 2018-05-02T19:15:48 >>> media-gfx/digikam-5.9.0: 29 minutes, 56 seconds 2018-05-23T02:48:16 >>> media-gfx/digikam-5.9.0: 29 minutes, 51 seconds 2018-05-27T11:45:34 >>> media-gfx/digikam-5.9.0: 30 minutes, 21 seconds 2018-08-25T16:10:06 >>> media-gfx/digikam-5.9.0: 29 minutes, 44 seconds 2018-10-12T00:50:18 >>> media-gfx/digikam-5.9.0: 29 minutes, 32 seconds 2018-12-14T03:32:12 >>> media-gfx/digikam-5.9.0: 32 minutes, 32 seconds 2019-02-07T18:41:48 >>> media-gfx/digikam-5.9.0: 34 minutes, 53 seconds 2019-02-20T19:21:23 >>> media-gfx/digikam-6.0.0: 54 minutes, 28 seconds 2019-09-08T21:03:11 >>> media-gfx/digikam-6.2.0: 58 minutes, 18 seconds $ /usr/bin/qlop --merge --unmerge --verbose --time --human digikam -r 2019-10-06T11:20:05 >>> media-gfx/digikam-6.2.0: 24 minutes, 7 seconds... (3 of 3) ETA: 1 minute, 28 seconds (average run)
Do you have an idea for a heuristic which would match this? I've thought about this previously, but I couldn't find anything which made sense for the generic case.
(In reply to Fabian Groffen from comment #15) > Do you have an idea for a heuristic which would match this? I've thought > about this previously, but I couldn't find anything which made sense for the > generic case. Yep, generic versus heuristic ... I'd just take into account the last 3 versions/releases as a starting point - can't be much more worse than taking all into account, isn't it?
The bug has been closed via the following commit(s): https://gitweb.gentoo.org/repo/gentoo.git/commit/?id=0b04f542749e2fb95c627364bf58b075c164c4f6 commit 0b04f542749e2fb95c627364bf58b075c164c4f6 Author: Fabian Groffen <grobian@gentoo.org> AuthorDate: 2019-10-20 10:25:14 +0000 Commit: Fabian Groffen <grobian@gentoo.org> CommitDate: 2019-10-20 10:25:38 +0000 app-portage/portage-utils: version bump to v0.81 - 697094: qfile incorrectly matching /usr/lib - 697068: qlop -r not showing ongoing merges from parallel merges - 696078: qgrep not matching revisioned ebuilds - 695586: qpkg double frees and incorrect unpacking - 694972: qlop -r/-a speedups - 692224: qlop support for alternate ROOT - 677982: qfile report matches from prune lib registry Closes: https://bugs.gentoo.org/697094 Closes: https://bugs.gentoo.org/697068 Closes: https://bugs.gentoo.org/696078 Closes: https://bugs.gentoo.org/695586 Closes: https://bugs.gentoo.org/694972 Closes: https://bugs.gentoo.org/692224 Closes: https://bugs.gentoo.org/677982 Package-Manager: Portage-2.3.76, Repoman-2.3.16 Signed-off-by: Fabian Groffen <grobian@gentoo.org> app-portage/portage-utils/Manifest | 1 + .../portage-utils/portage-utils-0.81.ebuild | 87 ++++++++++++++++++++++ 2 files changed, 88 insertions(+)
