Rofi: Rofi lags on startup, misses key presses

[oscarfv]

Version

Version: 1.2.0-163-g0554db6 (master)

Configuration

https://gist.github.com/oscarfv/5e9c447d70b3e21bb3416f4549e9f8a8

Launch Command

rofi -combi-modi window,run,drun -show combi

Steps to reproduce

• Step 1

# Clear Linux disk cache:
echo 3 | sudo tee /proc/sys/vm/drop_caches

• Step 2

./rofi -combi-modi window,run,drun -show combi

Contents of rofi-timing.log: https://gist.github.com/oscarfv/19eaa8e8a2b25cace9b3c3400339447e

What behaviour you see

I'm using rofi as a krunner replacement on Kubuntu 16.10. The CPU is a quad core 2.4 GHz Intel Q6600 with 8 GB RAM (admittedly old, but still faster than some modern machines). The disk is a 7400 rpm HDD. The machine is idle.

With krunner, I'm accustomed to start typing as soon as I press the hotkey. However, with rofi, sometimes there is a long pause until the window appears. Meanwhile, the window that has the focus when the hotkey is pressed receives the key events. Needless to say, this can create a serious mess.

• -

What behaviour you expect to see

This issue is related to https://github.com/DaveDavenport/rofi/issues/425 If running rofi in daemon mode is out of the question, I'll suggest creating the window and getting the focus as soon as possible, instead of waiting for the candidate list to be populated which, AFAIU, is what rofi does now.

BTW, apart from this issue, I'm very happy with rofi and consider it far more convenient than krunner. Thank you.

• -

[DaveDavenport]

Two things I notice from the trace:

1. )

0,284739 (0,000275): ../source/rofi.c:startup:535 Startup
1,749887 (1,465148): ../source/rofi.c:startup:549 Create Window

This should not take 1.4 seconds. Very weird. I run this on a Exynos 5250 Dual-Core @ 1.7Ghz and between startup and creating window takes ms.

2.) Can you check for me how many application files there are?

2,091146 (0,160613): ../source/dialogs/drun.c:get_apps:406 Get Desktop apps (user dir)
3,321078 (1,229932): ../source/dialogs/drun.c:get_apps:414 Get Desktop apps (system dirs)

Can you do:

find /usr/share/applications/ -name *.desktop | wc -l

Please forget about daemon mode, people keep bringing it up, but it did not keep things 'cached', so provided no real speed up.

[oscarfv]

Another data point. After clearing the disk cache, this command:

time ./rofi -combi-modi window,run,drun -show combi

gives 5.353 seconds, while rofi-timing.log last line shows

4,035817 (0,000000): Stopped

That means that if rofi created the window at time 0 of execution, there still is a 1.3 seconds interval where the key events would go to the window that had the focus when the hotkey was pressed.

[oscarfv]

Thanks for the quick response.

find /usr/share/applications/ -name *.desktop | wc -l

returns 149.

[DaveDavenport]

Weird, parsing 149 desktop files should be fast.
Only time I saw rofi being slow like this was on a machine with very very overloaded I/O.
I would prefer to load the data in a more async. fashion, but that is to much work for now.
Ill see if the grabbing of keyboard can be moved forward.

[oscarfv]

I was going to suggest grabbing the keyboard as soon as possible.

OTOH, the long time required to create the window only happens starting from an empty disk cache. The next time rofi is executed:

0,060447 (0,042246): ../source/rofi.c:startup:549 Create Window

I suspect that on creating the window some disk I/O is involved, either on loading shared libraries or resources.

This machine is totally idle, both cpu- and disk-wise.

[DaveDavenport]

Can you try: https://filebin.pw/9hIHqE/
This grabs keyboard early on.
( I get one weird mis-draw if I add an artificial sleep in there. will look at that.)

[oscarfv]

This is better, but the > 1 sec. delay from command execution until rofi starts running is still there.

I guess that there must be a method on Linux for having an executable and its library dependencies loaded at all times. I'll google a bit.

[DaveDavenport]

Well I don't assume you are going to clear the disk cache all the time....

[DaveDavenport]

Can you pastebin the timing log with patch? I cannot help with initial startup time (loading rofi), it does sounds like something is not right with the system to take 1 second to load just rofi and deps.

For me with flushing all caches it still starts in < 200 ms.

[oscarfv]

Not all the time, but sometimes... Let me explain:

I use rofi (or krunner) only a few times a day. Meanwhile I work with large files (virtual machines, mutimedia, databases). On this scenario it is common that rofi and its dependencies get dropped from the disk cache quite quickly, so when I need it the effect is as if the cache was cleared, as fas as rofi is concerned.

Krunner always pops up its window instantly, although it can take a while before displaying the candidates. The way krunner works avoids the possibility of sending the key events to wrong window. Mind you, krunner uses 80 MB of RAM (no kidding!) and depends on a bazillion shared libraries.

[oscarfv]

Here it goes, after clearing the cache. Do you use an SSD or an HDD? Also, it is quite possible that my disk is fragmented after several years installing updates.

0.000000 (0.000000): Started
0.000037 (0.000037): ../source/rofi.c:main:667 
0.000077 (0.000040): ../source/rofi.c:main:690 
0.000079 (0.000002): ../source/rofi.c:main:694 
0,042115 (0,042036): ../source/rofi.c:main:709 Open Display
0,178442 (0,136327): ../source/rofi.c:main:809 Setup mainloop
0,178532 (0,000090): ../source/rofi.c:main:824 Startup Notification
0,178554 (0,000022): ../source/rofi.c:main:827 Setup abe
0,217776 (0,039222): ../source/rofi.c:main:864 X11 Setup 
0,217781 (0,000005): ../source/view.c:rofi_view_workers_initialize:1555 Setup Threadpool, start
0,217785 (0,000004): ../source/view.c:rofi_view_workers_initialize:1578 Setup Threadpool, done
0,218055 (0,000270): ../source/rofi.c:startup:535 Startup
0,218996 (0,000941): ../source/rofi.c:startup:559 Grab keyboard
1,655687 (1,436691): ../source/rofi.c:startup:561 Create Window
1,655894 (0,000207): ../source/rofi.c:startup:567 Parse ABE
1,655969 (0,000075): ../source/rofi.c:startup:572 Config sanity check
1,659411 (0,003442): ../source/dialogs/run.c:get_apps:245 start
1,793666 (0,134255): ../source/dialogs/run.c:get_apps:363 stop
1,830512 (0,036846): ../source/dialogs/drun.c:get_apps:398 Get Desktop apps (start)
1,991108 (0,160596): ../source/dialogs/drun.c:get_apps:406 Get Desktop apps (user dir)
3,162810 (1,171702): ../source/dialogs/drun.c:get_apps:414 Get Desktop apps (system dirs)
3,162823 (0,000013): ../source/view.c:rofi_view_create:1332 
3,162828 (0,000005): ../source/view.c:rofi_view_create:1350 Startup notification
3,162830 (0,000002): ../source/view.c:rofi_view_create:1353 Get active monitor
3,167152 (0,004322): ../source/view.c:rofi_view_refilter:828 Filter start
3,167224 (0,000072): ../source/view.c:rofi_view_refilter:917 Filter done
3,167227 (0,000003): ../source/view.c:rofi_view_update:696 
3,168007 (0,000780): ../source/view.c:rofi_view_update:721 Background
3,210249 (0,042242): ../source/view.c:rofi_view_update:754 
3,210419 (0,000170): ../source/view.c:rofi_view_update:696 
3,211404 (0,000985): ../source/view.c:rofi_view_update:721 Background
3,213289 (0,001885): ../source/view.c:rofi_view_update:754 
3,213304 (0,000015): ../source/view.c:rofi_view_update:696 
3,214202 (0,000898): ../source/view.c:rofi_view_update:721 Background
3,216530 (0,002328): ../source/view.c:rofi_view_update:754 
3,216588 (0,000058): ../source/view.c:rofi_view_refilter:828 Filter start
3,219762 (0,003174): ../source/view.c:rofi_view_refilter:917 Filter done
3,219777 (0,000015): ../source/view.c:rofi_view_update:696 
3,220733 (0,000956): ../source/view.c:rofi_view_update:721 Background
3,240437 (0,019704): ../source/view.c:rofi_view_update:754 
3,240478 (0,000041): ../source/view.c:rofi_view_update:696 
3,241978 (0,001500): ../source/view.c:rofi_view_update:721 Background
3,244310 (0,002332): ../source/view.c:rofi_view_update:754 
3,244326 (0,000016): ../source/view.c:rofi_view_update:696 
3,245520 (0,001194): ../source/view.c:rofi_view_update:721 Background
3,247777 (0,002257): ../source/view.c:rofi_view_update:754 
3,247832 (0,000055): ../source/view.c:rofi_view_refilter:828 Filter start
3,249979 (0,002147): ../source/view.c:rofi_view_refilter:917 Filter done
3,249989 (0,000010): ../source/view.c:rofi_view_update:696 
3,250451 (0,000462): ../source/view.c:rofi_view_update:721 Background
3,253600 (0,003149): ../source/view.c:rofi_view_update:754 
3,253640 (0,000040): ../source/view.c:rofi_view_update:696 
3,255007 (0,001367): ../source/view.c:rofi_view_update:721 Background
3,257383 (0,002376): ../source/view.c:rofi_view_update:754 
3,257399 (0,000016): ../source/view.c:rofi_view_update:696 
3,258599 (0,001200): ../source/view.c:rofi_view_update:721 Background
3,260973 (0,002374): ../source/view.c:rofi_view_update:754 
3,261008 (0,000035): ../source/view.c:rofi_view_update:696 
3,262226 (0,001218): ../source/view.c:rofi_view_update:721 Background
3,264648 (0,002422): ../source/view.c:rofi_view_update:754 
3,264681 (0,000033): ../source/view.c:rofi_view_update:696 
3,265863 (0,001182): ../source/view.c:rofi_view_update:721 Background
3,268190 (0,002327): ../source/view.c:rofi_view_update:754 
6,201417 (2,933227): ../source/view.c:rofi_view_update:696 
6,201960 (0,000543): ../source/view.c:rofi_view_update:721 Background
6,203450 (0,001490): ../source/view.c:rofi_view_update:754 
6,203501 (0,000051): ../source/view.c:rofi_view_update:696 
6,204932 (0,001431): ../source/view.c:rofi_view_update:721 Background
6,207411 (0,002479): ../source/view.c:rofi_view_update:754 
6,208462 (0,000000): Stopped

[DaveDavenport]

I have an SSD in my system, but also on system with old hdd or even an SD card as storage it is faster then that..

I wonder why krunner is quick? probably because QT is still in memory (other apps using it?).
(from above log it should now take input from 0.2 seconds after launching.)

[oscarfv]

krunner is quick because it is running in the background :-)

[DaveDavenport]

Guess this patch is the best we can currently do.

[oscarfv]

Even with a 0.2s lag there are chances for misdirected keypresses. IMHO it is important for this type of application to act instantly as far as the user's perception can discern.

I googled for a bit and didn't found a method for keeping a GUI application running on the background, when the application closes after losing focus as rofi does.

Anyway thank you for your efforts. I'll keep using rofi instead of krunner and try to wait for a while after pressing the hotkey :-)

[DaveDavenport]

In theory we can keep rofi and even a window running in the background.
A good patch is welcome.

[oscarfv]

Noted.

[github-actions[bot]]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.