Menu shows with noticeable delay

vestingz commented 2 years ago

Since one of the recent updates, the menu lost its snappiness. After calling it, it shows with a noticeable delay of sth around .5 seconds, whereas before it would show instantly. Could this in any way be connected to your recent updates?

MarkHedleyJones commented 2 years ago

Interesting, thanks for the report. Yes it probably is. What version are you using? I changed the way the cache is opened v1.1.4 which may have impacted performance. Also, possibly the culprit could be the changes in v1.0.0...

For me the menu loads instantly, but if your cache is sufficiently large there may be a noticeable delay. I'll try and run some tests to see if I can pinpoint where the performance dropped.

vestingz commented 2 years ago

Thanks a lot! :)

I am using a build from the latest git revision 7ad25c0. FWIW, my cache is close to 18.000 entries (I am using your tool to access my library of scientific articles). Before, the menu opened instantly, too. Filtering is still as fast as ever.

MarkHedleyJones commented 2 years ago

Hi @vestingz Thanks for the information, I love hearing about the different ways people are using tools. 7ad25c0 is the main branch v1.1.4 which I've ran some comparisons against. For future reference I'm just going to dump the data below.

In summary, I'm not yet sure if I've been able to replicate the slow-down you've been experiencing. Initially I suspected the degradation may be due to codecs and the size of your cache. But the results seem to show that those changes didn't make much / if any difference to time taken to open the menu. What I did notice though is that the menu takes about twice as long to open, regardless of the size of the cache, since changing the installer (from about 0.22 seconds to about 0.5 seconds). This is probably related to the launcher scripts that are used to execute the menu (where are now handled by the installer).

So I would like to ask, would that change in launch-time from 0.22 seconds to 0.5 seconds explain the loss of snappiness you're experiencing?

Main Branch (v1.1.4)

Run 1

Time to open menu (empty cache)

Real time: 0.492s
User time: 0.476s
System time: 0.016s

Time to load cache of 1000 entries ...

Real time: 0.501s (0.009s longer than empty cache)
User time: 0.466s (-0.01s longer than empty cache)
System time: 0.035s (0.019s longer than empty cache)

Time to load cache of 20000 entries ...

Real time: 0.874s (0.382s longer than empty cache)
User time: 0.687s (0.211s longer than empty cache)
System time: 0.366s (0.35s longer than empty cache)

Time to load cache of 100000 entries ...

Real time: 2.627s (2.135s longer than empty cache)
User time: 1.672s (1.196s longer than empty cache)
System time: 2.018s (2.002s longer than empty cache)

Run 2

Time to open menu (empty cache)

Real time: 0.493s
User time: 0.465s
System time: 0.028s

Time to load cache of 1000 entries ...

Real time: 0.514s (0.021s longer than empty cache)
User time: 0.465s (0.0s longer than empty cache)
System time: 0.049s (0.021s longer than empty cache)

Time to load cache of 20000 entries ...

Real time: 0.863s (0.37s longer than empty cache)
User time: 0.726s (0.261s longer than empty cache)
System time: 0.297s (0.269s longer than empty cache)

Time to load cache of 100000 entries ...

Real time: 2.688s (2.195s longer than empty cache)
User time: 1.625s (1.16s longer than empty cache)
System time: 2.152s (2.124s longer than empty cache)

Reverting removal of `codecs.open` (v1.1.3)

Run 1

Time to open menu (empty cache)

Real time: 0.533s
User time: 0.497s
System time: 0.037s

Time to load cache of 1000 entries ...

Real time: 0.602s (0.069s longer than empty cache)
User time: 0.566s (0.069s longer than empty cache)
System time: 0.036s (-0.001s longer than empty cache)

Time to load cache of 20000 entries ...

Real time: 0.971s (0.438s longer than empty cache)
User time: 0.797s (0.3s longer than empty cache)
System time: 0.361s (0.324s longer than empty cache)

Time to load cache of 100000 entries ...

Real time: 2.850s (2.317s longer than empty cache)
User time: 1.929s (1.432s longer than empty cache)
System time: 2.014s (1.977s longer than empty cache)

Run 2

Time to open menu (empty cache)

Real time: 0.507s
User time: 0.488s
System time: 0.020s

Time to load cache of 1000 entries ...

Real time: 0.526s (0.019s longer than empty cache)
User time: 0.491s (0.003s longer than empty cache)
System time: 0.035s (0.015s longer than empty cache)

Time to load cache of 20000 entries ...

Real time: 0.944s (0.437s longer than empty cache)
User time: 0.786s (0.298s longer than empty cache)
System time: 0.344s (0.324s longer than empty cache)

Time to load cache of 100000 entries ...

Real time: 2.892s (2.385s longer than empty cache)
User time: 1.794s (1.306s longer than empty cache)
System time: 2.288s (2.268s longer than empty cache)

Before dropping Python2 support (v0.2.0)

Run 1

Time to open menu (empty cache)

Real time: 0.514s
User time: 0.495s
System time: 0.020s

Time to load cache of 1000 entries ...

Real time: 0.507s (-0.007s longer than empty cache)
User time: 0.466s (-0.029s longer than empty cache)
System time: 0.041s (0.021s longer than empty cache)

Time to load cache of 20000 entries ...

Real time: 0.933s (0.419s longer than empty cache)
User time: 0.739s (0.244s longer than empty cache)
System time: 0.382s (0.362s longer than empty cache)

Time to load cache of 100000 entries ...

Real time: 2.710s (2.196s longer than empty cache)
User time: 1.517s (1.022s longer than empty cache)
System time: 2.312s (2.292s longer than empty cache)

Run 2

Time to open menu (empty cache)

Real time: 0.492s
User time: 0.432s
System time: 0.061s

Time to load cache of 1000 entries ...

Real time: 0.529s (0.037s longer than empty cache)
User time: 0.489s (0.057s longer than empty cache)
System time: 0.041s (-0.02s longer than empty cache)

Time to load cache of 20000 entries ...

Real time: 0.976s (0.484s longer than empty cache)
User time: 0.792s (0.36s longer than empty cache)
System time: 0.377s (0.316s longer than empty cache)

Time to load cache of 100000 entries ...

Real time: 2.741s (2.249s longer than empty cache)
User time: 1.629s (1.197s longer than empty cache)
System time: 2.265s (2.204s longer than empty cache)

Before updating installer (v0.1.0)

Run 1

Time to open menu (empty cache)

Real time: 0.223s
User time: 0.219s
System time: 0.005s

Time to load cache of 1000 entries ...

Real time: 0.238s (0.015s longer than empty cache)
User time: 0.225s (0.006s longer than empty cache)
System time: 0.013s (0.008s longer than empty cache)

Time to load cache of 20000 entries ...

Real time: 0.694s (0.471s longer than empty cache)
User time: 0.505s (0.286s longer than empty cache)
System time: 0.366s (0.361s longer than empty cache)

Time to load cache of 100000 entries ...

Real time: 2.555s (2.332s longer than empty cache)
User time: 1.495s (1.276s longer than empty cache)
System time: 2.221s (2.216s longer than empty cache)

Run 2

Time to open menu (empty cache)

Real time: 0.226s
User time: 0.218s
System time: 0.008s

Time to load cache of 1000 entries ...

Real time: 0.244s (0.018s longer than empty cache)
User time: 0.232s (0.014s longer than empty cache)
System time: 0.012s (0.004s longer than empty cache)

Time to load cache of 20000 entries ...

Real time: 0.619s (0.393s longer than empty cache)
User time: 0.444s (0.226s longer than empty cache)
System time: 0.350s (0.342s longer than empty cache)

Time to load cache of 100000 entries ...

Real time: 2.371s (2.145s longer than empty cache)
User time: 1.296s (1.078s longer than empty cache)
System time: 2.153s (2.145s longer than empty cache)

vestingz commented 2 years ago

@MarkHedleyJones

Thank you so much for your analysis! And yes, it has been a real pleasure to work with for someone who keeps their filenames tidy and predictable :)

It could indeed very well be the difference that the new installer created. It is hard to assess the difference subjectively, though. Could you maybe link the last commit before the new installer? I'll try to install from there and get back to you with my results.

FWIW, since I stated in my last comment that filtering is still as fast as ever: that also has gone now. There is a lag of about 0.3 - 0.5 seconds until the closest result shows, while before that was nearly instant. Maybe it is connected to some newly updated python library? These are the python packages that have been updated since recently:

[2022-07-15T13:47:39+0200] [ALPM] upgraded python-cryptography (37.0.2-1 -> 37.0.4-1)
[2022-07-15T13:47:39+0200] [ALPM] upgraded python-lxml (4.9.0-1 -> 4.9.1-1)
[2022-07-15T13:47:40+0200] [ALPM] upgraded python-astroid (2.11.6-1 -> 2.12.2-1)
[2022-07-15T13:47:40+0200] [ALPM] upgraded python-filelock (3.5.1-1 -> 3.6.0-1)
[2022-07-15T13:47:40+0200] [ALPM] upgraded python-stevedore (3.5.0-3 -> 4.0.0-1)
[2022-07-15T13:47:40+0200] [ALPM] upgraded python-zipp (3.8.0-2 -> 3.8.1-1)
[2022-07-15T13:47:41+0200] [ALPM] installed python-xvfbwrapper (0.2.9-8)
[2022-07-15T13:48:49+0200] [ALPM] upgraded python-mpv (0.5.2-3 -> 1.0.1-1)
[2022-07-29T12:26:54+0200] [ALPM] upgraded python-gobject (3.42.1-1 -> 3.42.2-1)
[2022-07-29T12:26:54+0200] [ALPM] upgraded python-numpy (1.23.0-1 -> 1.23.1-1)
[2022-07-29T12:26:54+0200] [ALPM] upgraded python-distlib (0.3.4-1 -> 0.3.5-1)
[2022-07-29T12:26:54+0200] [ALPM] upgraded python-jaraco.functools (3.5.0-2 -> 3.5.1-1)
[2022-07-29T12:26:54+0200] [ALPM] upgraded python-jaraco.text (3.8.0-2 -> 3.8.1-1)
[2022-07-29T12:26:54+0200] [ALPM] upgraded python-trove-classifiers (2022.6.26-1 -> 2022.7.22-1)
[2022-07-29T12:26:55+0200] [ALPM] upgraded python-pip (22.1.2-1 -> 22.2-1)
[2022-07-29T12:27:03+0200] [ALPM] upgraded python-soupsieve (2.3.1-1 -> 2.3.2.post1-1)
[2022-07-29T12:27:03+0200] [ALPM] upgraded python-beautifulsoup4 (4.10.0-1 -> 4.11.1-1)
[2022-07-29T12:27:03+0200] [ALPM] upgraded python-bleach (5.0.0-1 -> 5.0.1-2)
[2022-07-29T12:27:03+0200] [ALPM] upgraded python-deepdiff (5.7.0-1 -> 5.8.0-1)
[2022-07-29T12:27:03+0200] [ALPM] upgraded python-dogpile.cache (1.1.6-1 -> 1.1.7-1)
[2022-07-29T12:27:03+0200] [ALPM] upgraded python-markdown (3.3.7-1 -> 3.4.1-1)
[2022-07-29T12:27:03+0200] [ALPM] upgraded python-pylint (2.14.4-1 -> 2.14.5-1)
[2022-07-29T12:27:03+0200] [ALPM] upgraded python-simplebayes (1.5.7-9 -> 1.5.8-1)
[2022-07-29T12:27:04+0200] [ALPM] upgraded python-sphinx (5.0.2-3 -> 5.1.1-1)
[2022-08-05T14:48:43+0200] [ALPM] installed python-llfuse (1.4.1-2)
[2022-08-05T14:56:12+0200] [ALPM] upgraded python (3.10.5-1 -> 3.10.5-2)
[2022-08-05T14:56:15+0200] [ALPM] upgraded python-chardet (4.0.0-5 -> 5.0.0-1)
[2022-08-05T14:56:15+0200] [ALPM] upgraded python-platformdirs (2.5.1-1 -> 2.5.2-1)
[2022-08-05T14:56:15+0200] [ALPM] upgraded python-requests (2.27.1-1 -> 2.28.1-1)
[2022-08-05T14:56:16+0200] [ALPM] upgraded python-pip (22.2-1 -> 22.2.2-1)
[2022-08-05T14:56:21+0200] [ALPM] installed python-jarowinkler (1.2.0-2)
[2022-08-05T14:56:21+0200] [ALPM] installed python-rapidfuzz (2.4.2-2)
[2022-08-05T14:56:21+0200] [ALPM] upgraded python-levenshtein (0.12.2-3 -> 0.20.1-2)
[2022-08-05T14:56:21+0200] [ALPM] upgraded python-scipy (1.8.1-1 -> 1.9.0-2)
[2022-08-05T14:56:22+0200] [ALPM] upgraded python-apipkg (2.1.1-1 -> 3.0.1-1)
[2022-08-05T14:56:22+0200] [ALPM] upgraded python-peewee (3.14.10-1 -> 3.15.1-1)
[2022-08-05T14:56:22+0200] [ALPM] upgraded python-reportlab (3.6.10-1 -> 3.6.11-1)
[2022-08-05T14:56:22+0200] [ALPM] upgraded python-sh (1.14.2-3 -> 1.14.3-1)
[2022-08-16T19:14:21+0200] [ALPM] upgraded python (3.10.5-2 -> 3.10.6-1)
[2022-08-16T19:14:28+0200] [ALPM] installed python-autocommand (2.2.1-1)
[2022-08-16T19:14:28+0200] [ALPM] upgraded python-typing_extensions (4.2.0-1 -> 4.3.0-1)
[2022-08-16T19:14:29+0200] [ALPM] installed python-pydantic (1.9.2-1)
[2022-08-16T19:14:29+0200] [ALPM] installed python-inflect (6.0.0-1)
[2022-08-16T19:14:29+0200] [ALPM] upgraded python-jaraco.text (3.8.1-1 -> 3.9.0-1)
[2022-08-16T19:14:29+0200] [ALPM] upgraded python-trove-classifiers (2022.7.22-1 -> 2022.8.7-1)
[2022-08-16T19:14:29+0200] [ALPM] upgraded python-setuptools (1:61.3.1-1 -> 1:62.1.0-1)
[2022-08-16T19:14:29+0200] [ALPM] upgraded python-urllib3 (1.26.9-1 -> 1.26.11-1)
[2022-08-16T19:14:32+0200] [ALPM] upgraded python-dogpile.cache (1.1.7-1 -> 1.1.8-1)
[2022-08-16T19:14:32+0200] [ALPM] upgraded python-pbr (5.9.0-1 -> 5.10.0-1)
[2022-08-16T19:14:32+0200] [ALPM] upgraded python-setproctitle (1.2.3-1 -> 1.3.1-1)
[2022-08-16T19:14:32+0200] [ALPM] upgraded python-setuptools-scm (7.0.4-1 -> 7.0.5-1)
[2022-08-16T19:14:32+0200] [ALPM] upgraded python-shellingham (1.4.0-4 -> 1.5.0-1)
[2022-08-16T19:14:32+0200] [ALPM] upgraded python-tomlkit (0.11.1-1 -> 0.11.4-1)
[2022-08-16T19:26:36+0200] [ALPM] installed python-configobj (5.0.6.r110.g3e2f4cc-3)
[2022-08-16T19:26:36+0200] [ALPM] installed python-fastbencode (0.0.9-1)
[2022-08-16T19:26:36+0200] [ALPM] installed python-patiencediff (0.2.2-3)
[2022-08-19T19:08:08+0200] [ALPM] upgraded python-pyelftools (0.28-1 -> 0.29-1)
[2022-08-19T19:08:08+0200] [ALPM] upgraded python-importlib_resources (5.8.0-1 -> 5.9.0-1)
[2022-08-19T19:08:08+0200] [ALPM] upgraded python-jaraco.text (3.9.0-1 -> 3.9.1-1)
[2022-08-19T19:08:09+0200] [ALPM] upgraded python-pygments (2.12.0-1 -> 2.13.0-1)

MarkHedleyJones / dmenu-extended