[BUG] Rofi is slow to appear when cold

[yuki-tsubaki]

Rofi version (rofi -v or git commit in case of build issue)

2.0.0

Configuration

https://gist.github.com/yuki-tsubaki/af0d69e5dcf013a7053bee6e42fd2ba3

Theme

https://gist.github.com/yuki-tsubaki/78d7018967d1786f6ea70706f9530442

Timing report

https://gist.github.com/yuki-tsubaki/17118b8a96705b05804c218a99dc1b4f

Launch command

rofi -dmenu

Step to reproduce

• Launch rofi (really any command, I did with -dmenu to exclude desktop caching issues)

Expected behavior

Rofi launches in at least under a second even when cold for at least simple things like dmenu.

Actual behavior

Dmenu takes almost 2 seconds to show when run cold:

The following shows a cleaned up version of the data with the offending portions in bold (all the times are accurate; I didn't use any LLM to format it, just Emacs):

Accumulated time	Partial time	Code	Task
0.000001	0.000000	Started
0.001267	0.001267	../rofi-2.0.0/source/rofi.c:main:1012
0.001965	0.000698	../rofi-2.0.0/source/rofi.c:main:1062
0.002577	0.000612	../rofi-2.0.0/source/rofi.c:main:1092	Setup Locale
0.002700	0.000123	../rofi-2.0.0/source/rofi.c:main:1094	Collect MODES
0.002737	0.000037	../rofi-2.0.0/source/rofi.c:main:1096	Setup MODES
0.002784	0.000047	../rofi-2.0.0/source/rofi.c:main:1100	Setup mainloop
0.002945	0.000161	../rofi-2.0.0/source/rofi.c:main:1103	NK Bindings
0.003083	0.000138	../rofi-2.0.0/source/rofi.c:main:1107	Setup abe
0.003966	0.000883	../rofi-2.0.0/source/rofi.c:main:1178	Load cmd config
0.004421	0.000455	../rofi-2.0.0/source/xcb/display.c:xcb_display_setup:1676	Open Display
0.004928	0.000507	../rofi-2.0.0/source/xcb/display.c:xcb_display_setup:1692	Setup XCB
0.007109	0.002181	../rofi-2.0.0/source/rofi.c:main:1261	Setup Display
0.007123	0.000014	../rofi-2.0.0/source/view.c:rofi_view_workers_initialize:1993	Setup Threadpool, start
0.007200	0.000077	../rofi-2.0.0/source/view.c:rofi_view_workers_initialize:2019	Setup Threadpool, done
0.007210	0.000010	../rofi-2.0.0/source/rofi.c:main:1298	Workers initialize
0.014590	0.007380	../rofi-2.0.0/source/rofi.c:main:1300	Icon fetcher initialize
0.014627	0.000037	../rofi-2.0.0/source/rofi.c:main:1308	Pid file created
0.014634	0.000007	../rofi-2.0.0/source/rofi.c:main:1314	Text box setup
0.015701	0.001067	../rofi-2.0.0/source/rofi.c:main:1321	Setup late Display
0.015817	0.000116	../rofi-2.0.0/source/rofi.c:main:1326	Theme setup
0.015923	0.000106	../rofi-2.0.0/source/rofi.c:startup:819	Startup
0.015938	0.000015	../rofi-2.0.0/source/rofi.c:startup:831	Grab keyboard
0.016028	0.000090	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:646	xcb create window
0.016049	0.000021	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:650	xcb create gc
0.016441	0.000392	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:660	create cairo surface
0.016538	0.000097	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:669	pango cairo font setup
0.016560	0.000022	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:713	configure font
0.668243	0.651683	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:721	textbox setup
0.668286	0.000043	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:735	setup window attributes
0.668296	0.000010	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:750	setup window fullscreen
0.668303	0.000007	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:757	setup window name and class
0.668310	0.000007	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:766	setup startup notification
0.668316	0.000006	../rofi-2.0.0/source/xcb/view.c:xcb___create_window:768	done
0.668334	0.000018	../rofi-2.0.0/source/rofi.c:startup:833	Create Window
0.668340	0.000006	../rofi-2.0.0/source/rofi.c:startup:835	Parse ABE
0.668348	0.000008	../rofi-2.0.0/source/rofi.c:startup:838	Config sanity check
0.668442	0.000094	../rofi-2.0.0/source/view.c:rofi_view_create:1798
0.668451	0.000009	../rofi-2.0.0/source/view.c:rofi_view_create:1833	Startup notification
0.668456	0.000005	../rofi-2.0.0/source/view.c:rofi_view_create:1836	Get active monitor
0.668749	0.000293	../rofi-2.0.0/source/view.c:rofi_view_refilter_real:764	Filter start
0.668759	0.000010	../rofi-2.0.0/source/view.c:rofi_view_refilter_real:769	Filter reload rows
0.668764	0.000005	../rofi-2.0.0/source/view.c:rofi_view_refilter_real:774	Filter tokenize
0.668769	0.000005	../rofi-2.0.0/source/view.c:rofi_view_refilter_real:860	Filter matching done
0.668775	0.000006	../rofi-2.0.0/source/widgets/listview.c:listview_set_num_elements:626	listview_set_num_elements
0.668781	0.000006	../rofi-2.0.0/source/widgets/listview.c:listview_set_num_elements:632	Set selected
0.668793	0.000012	../rofi-2.0.0/source/widgets/listview.c:listview_set_num_elements:634	recompute elements
0.668801	0.000008	../rofi-2.0.0/source/widgets/listview.c:listview_set_num_elements:636	queue redraw
0.668840	0.000039	../rofi-2.0.0/source/view.c:rofi_view_refilter_real:873	Update filter lines
0.668855	0.000015	../rofi-2.0.0/source/view.c:rofi_view_refilter_real:891	Filter resize window based on window
0.668861	0.000006	../rofi-2.0.0/source/view.c:rofi_view_refilter_real:893	Filter done
0.668866	0.000005	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:223
0.668888	0.000022	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:243	Background
0.669058	0.000170	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:256	widgets
0.670074	0.001016	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:199	Update start
0.670085	0.000011	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:223
0.670092	0.000007	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:243	Background
0.670120	0.000028	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:256	widgets
0.670126	0.000006	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:202	Expose
0.670135	0.000009	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:206	flush
0.670269	0.000134	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:199	Update start
0.670278	0.000009	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:202	Expose
0.670288	0.000010	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:206	flush
1.870271	1.199983	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:199	Update start
1.870397	0.000126	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:223
1.870443	0.000046	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:243	Background
1.870643	0.000200	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:256	widgets
1.870666	0.000023	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:202	Expose
1.870708	0.000042	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:206	flush
3.070830	1.200122	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:199	Update start
3.070885	0.000055	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:223
3.070913	0.000028	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:243	Background
3.071053	0.000140	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_update:256	widgets
3.071064	0.000011	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:202	Expose
3.071083	0.000019	../rofi-2.0.0/source/xcb/view.c:xcb_rofi_view_repaint:206	flush
3.453550	0.000000	Stopped

Additional information

I have a Sandisk WD Black SN850X NVMe SSD and the system was not under load during the time when tested. I also tested locking all the libraries and the binary in memory and got these results still: ldd $(which rofi) | rg -e '=> (.*?) \(0x.*\)' -r '$1' -o | xargs vmtouch -fl. I will also point out that the issue happens exactly the same when I run it like this rofi -dmenu -theme /dev/null so I know it isn't my theme that is causing the issue.

I've checked if the issue exists in the latest stable release

• Yes, I have checked the problem exists in the latest stable version

[DaveDavenport]

From this it looks like initializing pango font rendering is slow. (0.6s)
This is often a problem (not limited to rofi) on systems that have tons of fonts installed.

The 2nd 'bold' is the redraw that is most likely caused by the blinking of the cursor. Rofi has been ready already by this time (for 1.2s) and should have been visible.

[yuki-tsubaki]

I ran an strace yesterday but didn't have time to post the results. Anyway, I and did find a difference between the fast and slow in the number of reads of my main ttc fonts (Sarasa variants).

On the first load, there are 987 entries of mainly openat syscalls (again just for this font family). On subsequent loads, it just has 7 syscalls, 3 access and 4 openat. Even then, when I sum up the times reported by strace for each of these syscalls it is only 0.012 seconds which doesn't account for the time it takes to become visible.

I still don't know why the difference between the first and subsequent loads happens though.

I used vmtouch and found that even if I evict the offending fonts from memory, it still remains fast on subsequent runs.

I also manually timed (so of course take with a mound of salt because maybe I just have terrible reflexes), and it seems to take 1.12 seconds to be visible (though I feel like it sometimes takes longer when I run the full drun combi mode).

[DaveDavenport]

From the above trace it 'should' be shown after the first xcb_rofi_view_repaint. It will then only redraw again if the content changes (cursor in this case I suspect). I am not sure why for you it only shows after the first redraw, this is not intended behaviour (also not what I observe locally).

What happens if you disable cursor blinking?

./rofi -show drun -no-config -theme-str 'entry { blink: false; }'

I would like to find a good solution for pango being slow, but not sure what I can do without having to bypass it (and I don't want to implement font rendering myself)..

[DaveDavenport]

This is what it is for me:

(process:1434160): Timings-DEBUG: 17:20:57.176: 0.070740 (0.000010): ../source/xcb/view.c:xcb_rofi_view_repaint:206 flush

and I can confirm with obs recording of my screen that from the moment I press 'Enter' to window visible is around that time difference. ~0.08s.

[yuki-tsubaki]

Ok (sorry I forgot to send this earlier), I videoed it this time and it does indeed take approximately 1 second (0.96-1.00) from the moment I run the command to when it appears when running cold with the following command:

G_MESSAGES_DEBUG=Timings rofi -dmenu -no-config -theme-str 'entry { blink: false; }'

Do you perhaps know why the Pango initialization slowdown only occurs on the first run? The massive difference in number of syscalls related to loading my main font family between the first run and subsequent runs seems very suspicious.

[yuki-tsubaki]

This is what it is for me:

(process:1434160): Timings-DEBUG: 17:20:57.176: 0.070740 (0.000010): ../source/xcb/view.c:xcb_rofi_view_repaint:206 flush

and I can confirm with obs recording of my screen that from the moment I press 'Enter' to window visible is around that time difference. ~0.08s.

I'll also mention that when mine is warm (which again I still haven't figured out what specific thing is being cached or not that makes the difference), mine is visible in 0.03 seconds (based on the graphics debug thing) and feels instantaneous.

[DaveDavenport]

I am not sure how pango handles caching internally.It would be interesting to know.