Go Back   Cockos Incorporated Forums > REAPER Forums > REAPER for Linux

Reply
 
Thread Tools Display Modes
Old 03-13-2019, 11:52 AM   #1
HadrienG
Human being with feelings
 
Join Date: Mar 2019
Posts: 7
Default Good first impression ! But suspicious desktop resource usage.

As a big fan of REAPER back when I was using Windows as my daily driver, I was very happy to learn about its native Linux port recently. Found out that my old license was still valid, installed it, started playing around, and so far I'm pretty happy about the port.

Everything mostly Just Works. I've only managed to crash it once in a few weeks of experimentation (which, per Murphy's law, was obviously that time where I had been working on something for an hour without saving), and the only obviously broken behavior I observed so far was that time I tried to run it on a high-DPI laptop at native resolution. For software that's flagged as experimental and not ready for official support yet, count me impressed!

That being said, there is one thing which I'm hesitant to call a bug, but find pretty suspicious: my desktop's basic GUI processes (cinnamon & X) will see their CPU usage jump up enormously (from 1~3% to 20~30% of one core, split as 2/3 cinnamon 1/3 X) when REAPER is running, even when doing ~nothing. Hiding the REAPER window leads their CPU usage to drop significantly, but not back to normal levels (~10%). A bit of system-wide profiling with perf reveals that most of that CPU time is spent processing glib events.

Now, cinnamon is certainly not the lightest-weight Linux DE out there, but the fact that this only happens with REAPER makes me suspect that REAPER or the underlying Swell abstraction layer might doing something evil and unnecessary here, such as spamming UI refreshes faster than the screen's refresh rate. Since libSwell is open-source, I'll try to rebuild it with debug symbols and see if more interesting stuff shows up in my perf profiles...

Last edited by HadrienG; 03-13-2019 at 12:46 PM.
HadrienG is offline   Reply With Quote
Old 03-13-2019, 01:14 PM   #2
JamesPeters
Human being with feelings
 
Join Date: Aug 2011
Location: Near a big lake
Posts: 3,943
Default

That doesn't happen with me (but I'm using XFCE since it's the DE in MX Linux).

What driver are you using for your video device? If it's an nVidia or Intel device and you're using a "free" video driver (and included in the distro), I'd recommend installing the non-free Intel or nVidia driver instead. There's probably a utility in the Mint menu to do this. And if your video device is nVidia, you're probably going to want to enable the "full composition pipeline" option in the nVidia X Server application to avoid screen tear with some applications.

I was going to ask what compositor you're using but I see Cinnamon has a compositor enabled by default. (MX Linux doesn't do that by default and I was getting some screen tear issues.)
JamesPeters is offline   Reply With Quote
Old 03-13-2019, 01:26 PM   #3
HadrienG
Human being with feelings
 
Join Date: Mar 2019
Posts: 7
Default Profiling results

So, I rebuilt libSwell with debug info (and threw an -O3 -march=native into the mix while I was at it, just in case there's vectorizable stuff in there :P), and installed a few more debug info packages, then ran another 20s perf profile with "perf record -a --call-graph=dwarf,64000 -F 300 -o /dev/shm/perf.data -- sleep 20".

First of all, we see reaper, spending a lot of time sleeping for reasons that only cockos devs with access to its debugging symbols could tell. My guess is that it's doing this because in real-time processing, it's too risky to fall asleep when there is no work to do...

Code:
-   25,38%     0,00%  reaper/mediaafx  libc-2.29.so                        [.] __GI___clone (inlined)
     __GI___clone (inlined)
     start_thread
   - __threadproc
      - 24,54% 0x64d778
         - 24,52% usleep
              __GI___nanosleep (inlined)
Then we have cinnamon, who as I pointed out earlier spends a curious lot of time iterating over glib events:

Code:
-   20,54%     0,00%  cinnamon         cinnamon                            [.] _start
     _start
     __libc_start_main
     main
     meta_run
     g_main_loop_run
   - g_main_context_iterate (inlined)
      - 8,43% g_main_context_dispatch
         - g_main_dispatch (inlined)
            - 7,54% clutter_clock_dispatch
               - master_clock_update_stages (inlined)
                  - 7,25% _clutter_stage_do_update
                     + 7,14% clutter_stage_do_redraw (inlined)
            - 0,74% 0x7fb843d30071
                 gdk_display_get_event
      - 5,41% g_main_context_prepare
           4,63% g_source_iter_next
      - 4,95% g_main_context_check
           4,26% g_source_iter_next
      - 1,72% g_main_context_poll (inlined)
           1,71% __GI___poll (inlined)
With the extra debug symbols that I just installed, I can also look into the details of clutter's draw call. And all I can say without going above the char limit for this post is... wow.

Last edited by HadrienG; 03-13-2019 at 02:03 PM.
HadrienG is offline   Reply With Quote
Old 03-13-2019, 01:48 PM   #4
HadrienG
Human being with feelings
 
Join Date: Mar 2019
Posts: 7
Default

This is on an AMD Radeon RX 560 card with the free AMDGPU driver. Which is pretty competitive with the binary driver according to Phoronix, and the only one of the two that'll work on a recent kernel / Mesa pair according to my experimenting

Anyway, here's what I see if I have fun expanding the clutter renderer stuff down to 1%:

Code:
-    8,43%     0,00%  cinnamon         libglib-2.0.so.0.5800.3             [.] g_main_context_dispatch
     8,43% g_main_context_dispatch
      - g_main_dispatch (inlined)
         - 7,54% clutter_clock_dispatch
            - master_clock_update_stages (inlined)
               - 7,25% _clutter_stage_do_update
                  - 7,14% clutter_stage_do_redraw (inlined)
                     - clutter_stage_cogl_redraw
                        - 4,79% _clutter_stage_do_paint
                           - 4,62% clutter_actor_paint
                              - clutter_actor_paint
                                 - 4,56% clutter_actor_continue_paint
                                    - 4,39% g_signal_emit
                                       - g_signal_emit_valist
                                          - 4,39% signal_emit_unlocked_R
                                             - g_closure_invoke
                                                - 4,38% clutter_stage_paint
                                                   - 4,37% clutter_actor_paint
                                                      - 4,36% clutter_actor_paint
                                                         - 3,66% clutter_actor_continue_paint
                                                            - 3,63% g_signal_emit
                                                               - g_signal_emit_valist
                                                                  - 3,62% signal_emit_unlocked_R
                                                                       g_closure_invoke
                                                                       clutter_actor_real_paint
                                                                       clutter_actor_paint
                                                                     - clutter_actor_paint
                                                                        - 3,37% clutter_actor_continue_paint
                                                                           - 3,37% g_signal_emit
                                                                                g_signal_emit_valist
                                                                              - signal_emit_unlocked_R
                                                                                 - 3,35% g_closure_invoke
                                                                                    - cinnamon_generic_container_paint
                                                                                       - 3,33% clutter_actor_paint
                                                                                          - clutter_actor_paint
                                                                                             - 2,96% clutter_actor_continue_paint
                                                                                                - 2,95% g_signal_emit
                                                                                                     g_signal_emit_valist
                                                                                                     signal_emit_unlocked_R
                                                                                                   - g_closure_invoke
                                                                                                      - 2,01% cinnamon_generic_container_paint
                                                                                                         - 1,97% clutter_actor_paint
                                                                                                            - clutter_actor_paint
                                                                                                               - 1,80% clutter_actor_continue_paint
                                                                                                                  - 1,78% g_signal_emit
                                                                                                                       g_signal_emit_valist
                                                                                                                     - signal_emit_unlocked_R
                                                                                                                        - 1,77% g_closure_invoke
                                                                                                                           - st_box_layout_paint
                                                                                                                              - 1,76% clutter_actor_paint
                                                                                                                                 - clutter_actor_paint
                                                                                                                                    - 1,60% clutter_actor_continue_paint
                                                                                                                                       - g_signal_emit
                                                                                                                                          - g_signal_emit_valist
                                                                                                                                             - 1,59% signal_emit_unlocked_R
                                                                                                                                                - g_closure_invoke
                                                                                                                                                   - 1,57% st_box_layout_paint
                                                                                                                                                      - 1,55% clutter_actor_paint
                                                                                                                                                         - clutter_actor_paint
                                                                                                                                                            - 1,29% clutter_actor_continue_paint
                                                                                                                                                               - 1,27% g_signal_emit
                                                                                                                                                                  - g_signal_emit_valist
                                                                                                                                                                     - 1,26% signal_emit_unlocked_R
                                                                                                                                                                        - g_closure_invoke
                                                                                                                                                                           + 0,99% clutter_actor_real_paint
                                                                                                      + 0,81% meta_window_group_paint
                                                         + 0,69% _clutter_actor_update_last_paint_volume (inlined)
                        - 2,33% cogl_onscreen_swap_buffers_with_damage
                           - 1,39% cogl_flush
                                _cogl_journal_flush
                              - _cogl_journal_flush
                                 - 1,21% batch_and_call (inlined)
                                    - 1,01% batch_and_call (inlined)
                                       + 0,98% _cogl_journal_flush_vbo_offsets_and_entries
                           + 0,93% _cogl_winsys_onscreen_swap_buffers_with_damage
         + 0,74% gdk_event_source_dispatch
As you can see, most of that time is spent in GDK's clutter OpenGL renderer, recursing down to absurd depths while rendering... something. So I don't think we're talking about video driver overhead here. As far as I can tell, it's the CPU side of Clutter that is dying trying to render something here. If you look for the driver (radeonsi_dri.so), it's wayyy down at 1.3% overhead in the profile, which is nothing compared to the above clutter and glib event loop monstrosities. That being said, there is also some 9% of X11 overhead which the profiler doesn't manage to drill down into, driver stuff might also be hiding there!

The question is, what is this absurdly complex scene that clutter is trying to render here? But as far as I can tell, only [strike]REAPER[/strike] cinnamon knows the answer to this question. I could use some help from someone who knows more about GTK in order to profile this further.

One good news, though, is that there has been a lot of work on GNOME 3 performance optimization recently, which should percolate to cinnamon eventually. So maybe the problem will resolve itself just by virtue of the GTK & cinnamon world getting better at rendering complex scenes

In the meantime, though, I guess my point still stands: it would be nice of reaper to be a bit more gentle with them.

Last edited by HadrienG; 03-13-2019 at 02:35 PM.
HadrienG is offline   Reply With Quote
Old 03-13-2019, 02:33 PM   #5
HadrienG
Human being with feelings
 
Join Date: Mar 2019
Posts: 7
Default

Thinking a bit more about it, I'd like to retract the earlier statement that REAPER might be to blame for the complexity of the rendering task above. As far as I know, all a compositing window manager does is to blit bitmaps coming from various applications, so all REAPER should be giving to cinnamon is a bitmap to display on the screen. Anything more (e.g. GTK widgets to be rendered) would be a security hole.

What REAPER could infuence, however, is how often cinnamon refreshes its UI and triggers this messy rendering task.
HadrienG is offline   Reply With Quote
Old 03-13-2019, 03:41 PM   #6
JamesPeters
Human being with feelings
 
Join Date: Aug 2011
Location: Near a big lake
Posts: 3,943
Default

Quote:
Originally Posted by HadrienG View Post
As you can see, most of that time is spent in GDK's clutter OpenGL renderer, recursing down to absurd depths while rendering... something.
Yes, I can clearly see that. I was going to say the same exact thing.

...I have no idea what any of this means. I did read it all, though. So maybe I'll learn something through osmosis, eventually.
JamesPeters is offline   Reply With Quote
Old 03-13-2019, 11:28 PM   #7
HadrienG
Human being with feelings
 
Join Date: Mar 2019
Posts: 7
Default

Ha ha, sorry, got carried away into a rabbit hole there. Software performance analysis is something I'm supposed to be doing at work every day (and kinda tired of not doing as more boring stuff takes priority).

The stuff I've shown above is a drill-down of where CPU time is spent, across all running programs on the system, down to granularity of individual functions in their code. You should not pay too much attention to absolute percentage values because getting them right requires some precious files called debugging symbols that I don't have for REAPER, but since I have them for cinnamon and GTK stuff the relative drilldown should be pretty accurate there.

The limited analysis above is then based on the few things I know or could find in the docs regarding how GTK and Linux GUI in general work.

In any case, thanks for giving me the Xfce workaround. These days, I'm not using this desktop as often as I did in the past because it doesn't like my laptop's high-resolution screen. But since REAPER & yoshimi have the same problem anyway, forcing me into ugly non-native screen resolutions for audio work, it might be good to switch to Xfce for this purpose.

Last edited by HadrienG; 03-13-2019 at 11:37 PM.
HadrienG is offline   Reply With Quote
Old 03-14-2019, 02:12 AM   #8
HadrienG
Human being with feelings
 
Join Date: Mar 2019
Posts: 7
Default

Here's a nicer profile that was acquired on a cleaner system (nothing but a maximized REAPER window around, aimlessly looping through a few MIDI tracks), and with the few extra debug symbols, which when put together allowed me to also get perf to show me kernel-side overhead

But maybe let's start by showing the breakdown by process, which is the only one that will not be affected by REAPER's lack of debugging symbols and can be 100% trusted:

Code:
  Overhead      Pid:Command
    49,17%        0:swapper
    26,60%     2392:cinnamon
     4,96%     3271:reaper/libjack
     4,48%      347:irq/26-xhci_hcd
     2,65%     3258:reaper
     2,59%     1682:X
     1,82%     3272:reaper/cs_midio
     1,43%      162:kworker/u8:6+ev
     1,07%     3243:jackd
     0,79%     1353:ntpd
     0,75%        9:ksoftirqd/0
     0,61%     3274:reaper/mediaafx
     0,59%     3308:perf
     0,53%     1280:kworker/1:5-eve
     0,45%     1689::1689
     0,23%     3273:reaper/mediaafx
     0,20%     3276:reaper/mediaafx
     0,18%     3275:reaper/mediaafx
     0,18%     2419:cinnamon:cs0
     0,15%      368:irq/27-amdgpu
     0,12%      369:gfx
The toplevel "swapper" thing that we can see now is the kernel idle task. It's spinning the CPU while waiting for work, processing CPU clock ticks, and scheduling the running programs. Nothing unusual here:

Code:
-   49,17%    49,17%        0:swapper
   - 48,72% secondary_startup_64
      - 40,57% start_secondary
         - cpu_startup_entry
            - do_idle
               - 39,49% cpuidle_enter_state
                    34,18% intel_idle
                  + 2,98% apic_timer_interrupt
                  + 2,10% ret_from_intr
      - 8,16% start_kernel
         - cpu_startup_entry
            - do_idle
               - 6,80% cpuidle_enter_state
                    6,62% intel_idle
               - 1,24% schedule_idle
                  - __sched_text_start
There is a little bit of cinnamon overhead which I missed before, because it does not have debugging symbols (or perf failed to get to them). Hard to say if it's linked to the issue at hand:

Code:
-   26,60%    26,60%     2392:cinnamon
   +→22,57% _start cinnamon
   - 1,34% 0xffffffffffffffff unknown
      +→0,76% glibtop_get_cpu_s libgtop-2.0.so.11.0.0
   - 0,97% 0x7fb789b6b9af libclutter-1.0.so.0.2600.2
       →_clutter_context_get_show_fps libclutter-1.0.so.0.2600.2
   - 0,79% 0x563cf932ceaf [heap]
       →0,79% _cogl_get_texture_unit libcogl.so.20.4.2
If you take the kernel-side overhead into account, you can see that the CPU overhead split is a bit less even that it was before. We see more drawing overhead now that we account for the kernel side of things, because a lot of drawing work is done there. We can also get a more nuanced view of the event processing stuff:

Code:
-   22,57%     0,00%  cinnamon         libglib-2.0.so.0.5800.3             [.] g_main_context_iterate.isra.26
   - 22,57% g_main_context_iterate.isra.26
      - 14,00% g_main_context_dispatch
         - 13,68% clutter_clock_dispatch
            - 13,61% _clutter_stage_do_update
               + 13,57% clutter_stage_cogl_redraw
      - 6,10% g_main_context_prepare
           2,99% g_source_iter_next
         - 1,09% gdk_event_source_prepare
            + 1,08% XPending
         - 0,79% message_queue_prepare
            + dbus_connection_get_dispatch_status
      - 2,38% g_main_context_check
         - 1,25% gdk_event_source_check
            + 1,24% XPending
           1,04% g_source_iter_next
And we can see more detail of the draw stuff too if we feel so inclined, all the way down to the user-side driver library and underlying kernel facilities.

All that extra precision does not change my general diagnosis though: this thing is crunching so much CPU because it is doing a suspicious lot of suspiciously complex graphic refreshes.
HadrienG is offline   Reply With Quote
Old 03-14-2019, 05:02 AM   #9
Jack Winter
Human being with feelings
 
Jack Winter's Avatar
 
Join Date: Aug 2007
Location: Luxembourg/Spain
Posts: 1,922
Default

You could try to reduce Prefs->Track Control Panels->Meter update frequency (Hz). Maybe it helps.
__________________
Reaper for Linux Documentation (WIP). Software: Archlinux/KDE, Fabfilter FX, Komplete 8, Nebula, Schwa/Stillwell, T-racks Max/Amplitube/SVX, etc. Gear: i7-2600k/4700HQ/16GB, RME Multiface/Babyface, Behringer X32, Genelec 8040, etc. :)
Jack Winter is offline   Reply With Quote
Old 03-14-2019, 08:27 AM   #10
HadrienG
Human being with feelings
 
Join Date: Mar 2019
Posts: 7
Default

Quote:
Originally Posted by Jack Winter View Post
You could try to reduce Prefs->Track Control Panels->Meter update frequency (Hz). Maybe it helps.
Thanks for the tip! I'd been looking for a setting of this sort in the preferences, but did not think about checking the Track Control Panel subsection.

Indeed, the VU meter updates have an influence on this. Tuning down the VU meter refresh rate can reduce the graphic stack's CPU consumption all the way down to nothing when REAPER is idle (no playback, no recording).

Tuning it up above 60hz will lead the CPU consumption to plateau, showing that someone somewhere (REAPER? cinnamon? X?) is honoring the VSync sanity limit. So there is no excessive amount of refresh events from REAPER as I was suspecting earlier.

When there is playback/recording going on, the graphics stack will start crunching CPU again, to similar levels as with an idle 60hz VU meter refresh rate, showing that this is purely bound to UI refreshes (there are obviously lots of refreshes during playback/record, be it only due to the moving time position line). The overall CPU consumption remains less than with high VU meter refresh rates, though, so damage regions seem to be working correctly.

So overall, I'm now convinced that REAPER is probably doing the right thing here, and cinnamon is the culprit for making UI refreshes so expensive. The reason why I've not observed that with other apps is likely that these tend not to refresh their window while idle, as REAPER is doing with its VU meters.

I'll wait for the GNOME 3.32 performance fixes to be ported to Cinnamon, and if it doesn't bring cinnamon's CPU usage to a saner level, I'll try to build a simpler reproducer (maybe an OpenGL app that does nothing but spam screen clears with random colors) and file them a bug report with that

Thanks again for the Linux port, and sorry for my misguided finger pointing!

Last edited by HadrienG; 03-14-2019 at 08:41 AM.
HadrienG is offline   Reply With Quote
Old 03-14-2019, 09:05 AM   #11
s wave
Human being with feelings
 
Join Date: Sep 2018
Location: Colorado
Posts: 429
Default

With Cinnamon (r u running 18.04 kernel?) I get rid of Hibernate and Sleep as its set up. What is that swapper doing?...32 49%

'The reason is historical and programatic. The idle task is the task running, if no other task is runnable, like like it was said. It has the lowest possible priority, so that's why it's running of no other task is runnable

Programatic reason: This simplifies process scheduling a lot, because you don't have to care about the special case: "What happens if no task is runnable?", because there always is at least one task runnable, the idle task. Also you can count the amount of cpu time used per task. Without the idle task, which task gets the cpu-time accounted no one needs?

Historical reason: Before we had cpus which are able to step-down or go into power saving modes, it HAD to run on full speed at any time. It ran a series of NOP-instructions, if no tasks were runnable. Today the scheduling of the idle task usually steps down the cpu by using HLT-instructions (halt), so power is saved. So there is a functionality somehow in the idle task in our days'

'The swapper process is part of the kernel. It should have PID 0 and is in charge of scheduling processes'

COMMAND:$ ps -eaf [more in depth to track the pid: ps -ef | grep <PID>]
or something similar...

Maybe that sheds some light. I would also dial in your swap memory - don't over allocate or under allocate - there appears to be a sweet spot.
Here is the swap command to quick check 'SWAP' usage:

~ $ vmstat
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
1 0 0 5329948 185436 1082220 0 0 79 28 387 622 4 2 92 2

(sudo apt get) '# glances' program will give more detailed info on swap too.

You probably know all this but its good to brainstorm sometimes. Also I have heard of a rare problem in the 1st swapper sched can split the secondary scheduling wrong (not OS or program specific) gl
s wave is offline   Reply With Quote
Old 03-14-2019, 09:08 AM   #12
s wave
Human being with feelings
 
Join Date: Sep 2018
Location: Colorado
Posts: 429
Default

Forgot - what GUI enabled? Generic or Normal (BOTH LOL) how is Cinn using it...
s wave is offline   Reply With Quote
Old 03-14-2019, 11:33 AM   #13
Jack Winter
Human being with feelings
 
Jack Winter's Avatar
 
Join Date: Aug 2007
Location: Luxembourg/Spain
Posts: 1,922
Default

My guess is that this is some bug in the gtk/compositor/driver stack.
__________________
Reaper for Linux Documentation (WIP). Software: Archlinux/KDE, Fabfilter FX, Komplete 8, Nebula, Schwa/Stillwell, T-racks Max/Amplitube/SVX, etc. Gear: i7-2600k/4700HQ/16GB, RME Multiface/Babyface, Behringer X32, Genelec 8040, etc. :)
Jack Winter is offline   Reply With Quote
Old 03-15-2019, 11:27 PM   #14
s wave
Human being with feelings
 
Join Date: Sep 2018
Location: Colorado
Posts: 429
Default

One idea also... I run mint on one machine... all the sudden the video editor hit a maybe 100ms lag for no apparent reason... so in 'software sources' I 'purged residual configuration' then 'fix Mergelist problems' then updated cache -- and it was back to its normal speed. [I think it might of been from installing and un-installing a program (leftover artifacts?)
s wave is offline   Reply With Quote
Reply

Thread Tools
Display Modes

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

BB code is On
Smilies are On
[IMG] code is On
HTML code is Off

Forum Jump


All times are GMT -7. The time now is 02:39 AM.


Powered by vBulletin® Version 3.8.11
Copyright ©2000 - 2024, vBulletin Solutions Inc.