Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance Profiling Surge #556

Closed
esaruoho opened this issue Feb 10, 2019 · 10 comments
Closed

Performance Profiling Surge #556

esaruoho opened this issue Feb 10, 2019 · 10 comments

Comments

@esaruoho
Copy link
Collaborator

report from KVR: (
https://www.kvraudio.com/forum/viewtopic.php?p=7310445&sid=74fe7926c1b5f832ffcbcbb4cd8ed8af#p731044 )5


i recently try official v152 build from friend, for compare, so, my assumptions were confirmed - by some reason new version load cpu already in initial (idle) stage, just after load plugin (it's a pretty small cpu load, but strange it is). While in v152 absolutely zero cpu usage in the same idle condition. Hmm.
I dont know, maybe i miss something in settings, would be good if you check this too. Or maybe reason is known ?

@baconpaul
Copy link
Collaborator

Hmm what a good and worrying report. I wonder what it's doing. I do notice some non-zero cpu clip at idle also.

@baconpaul
Copy link
Collaborator

OK I took a peek at this using the macOS sampling profiler on the release

instruments -l 30000 -t Time\ Profiler -p 5773

where 5773 is the pid of the host. Found the time used was about half drawing and half in the processing loop

Didn't dig into the processing loop but the drawing time came a lot from something called 'background refresh' type stuff in NSView. (This was all mac).

And then I noticed something which seems to be worrying. The background image draws on every idle.

So if I place a print in CScalableBitmap::draw it gets called every idle loop.

More to investigate here, but that's definitely an issue.

@baconpaul
Copy link
Collaborator

The stack that gets us to the background draw is

0   Surge                               0x000000010aabb7c5 _ZN15CScalableBitmap4drawEPN6VSTGUI12CDrawContextERKNS0_5CRectERKNS0_6CPointEf + 261
1   Surge                               0x000000010aaf69fc _ZN6VSTGUI14CViewContainer18drawBackgroundRectEPNS_12CDrawContextERKNS_5CRectE + 780
2   Surge                               0x000000010aae6762 _ZN6VSTGUI14CViewContainer8drawRectEPNS_12CDrawContextERKNS_5CRectE + 706
3   Surge                               0x000000010aae6402 _ZN6VSTGUI6CFrame8drawRectEPNS_12CDrawContextERKNS_5CRectE + 306
4   Surge                               0x000000010aaedebd _ZThn32_N6VSTGUI6CFrame16platformDrawRectEPNS_12CDrawContextERKNS_5CRectE + 13
5   Surge                               0x000000010ab4b6d0 _ZN6VSTGUI11NSViewFrame8drawRectEP6CGRect + 256
6   Surge                               0x000000010ab48fca _ZL22VSTGUI_NSView_drawRectP11objc_objectP13objc_selector6CGRect + 74
7   AppKit                              0x00007fff44349c29 _NSViewDrawRect + 66
8   AppKit                              0x00007fff443484db -[NSView(NSInternal) _recursive:displayRectIgnoringOpacity:inContext:shouldChangeFontReferenceColor:stopAtLayerBackedViews:] + 1545
9   AppKit                              0x00007fff44347ec2 __46-[NSView(NSLayerKitGlue) drawLayer:inContext:]_block_invoke + 192
10  AppKit                              0x00007fff44347c21 -[NSView(NSLayerKitGlue) _drawViewBackingLayer:inContext:drawingHandler:] + 1769
11  QuartzCore                          0x00007fff51c94e53 CABackingStoreUpdate_ + 577
12  QuartzCore                          0x00007fff51cf5c41 ___ZN2CA5Layer8display_Ev_block_invoke + 53
13  QuartzCore                          0x00007fff51c9403c -[CALayer _display] + 1839
14  AppKit                              0x00007fff4434717a _NSBackingLayerDisplay + 531
15  AppKit                              0x00007fff4432b6e3 -[_NSViewBackingLayer display] + 811
16  QuartzCore                          0x00007fff51c93568 _ZN2CA5Layer17display_if_neededEPNS_11TransactionE + 634
17  QuartzCore                          0x00007fff51c817b7 _ZN2CA7Context18commit_transactionEPNS_11TransactionE + 319
18  QuartzCore                          0x00007fff51c81088 _ZN2CA11Transaction6commitEv + 576
19  QuartzCore                          0x00007fff51c80d94 _ZN2CA11Transaction17observer_callbackEP19__CFRunLoopObservermPv + 66
20  CoreFoundation                      0x00007fff46d2b9cd __CFRUNLOOP_IS_CALLING_OUT_TO_AN_OBSERVER_CALLBACK_FUNCTION__ + 23
21  CoreFoundation                      0x00007fff46d2b902 __CFRunLoopDoObservers + 452
22  CoreFoundation                      0x00007fff46ccd558 __CFRunLoopRun + 1469
23  CoreFoundation                      0x00007fff46cccd48 CFRunLoopRunSpecific + 463
24  HIToolbox                           0x00007fff45f63ab5 RunCurrentEventLoopInMode + 293
25  HIToolbox                           0x00007fff45f637eb ReceiveNextEventCommon + 618
26  HIToolbox                           0x00007fff45f63568 _BlockUntilNextEventMatchingListInModeWithFilter + 64
27  AppKit                              0x00007fff4421e363 _DPSNextEvent + 997
28  AppKit                              0x00007fff4421d102 -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 1362
29  AppKit                              0x00007fff44217165 -[NSApplication run] + 699
30  AppKit                              0x00007fff442068a3 NSApplicationMain + 780
31  Hosting AU                          0x0000000105acd250 Hosting AU + 4688
32  ???                                 0x0000000000000002 0x0 + 2

@baconpaul
Copy link
Collaborator

OK I checked on linux also and it is also drawing the background every idle. Here's the linux stack

Draw 904 542
./target/vst2/Release/Surge.so(_ZN15CScalableBitmap4drawEPN6VSTGUI12CDrawContextERKNS0_5CRectERKNS0_6CPointEf+0xe2) [0x7fd830fbe092]
./target/vst2/Release/Surge.so(_ZN6VSTGUI14CViewContainer18drawBackgroundRectEPNS_12CDrawContextERKNS_5CRectE+0x35b) [0x7fd83106624b]
./target/vst2/Release/Surge.so(_ZN6VSTGUI14CViewContainer8drawRectEPNS_12CDrawContextERKNS_5CRectE+0x200) [0x7fd8310b0b70]
./target/vst2/Release/Surge.so(_ZN6VSTGUI6CFrame8drawRectEPNS_12CDrawContextERKNS_5CRectE+0x176) [0x7fd8310b1616]
./target/vst2/Release/Surge.so(_ZThn32_N6VSTGUI6CFrame16platformDrawRectEPNS_12CDrawContextERKNS_5CRectE+0xd) [0x7fd8310b16cd]
./target/vst2/Release/Surge.so(_ZNSt17_Function_handlerIFvvEZN6VSTGUI3X115Frame4Impl11invalidRectENS1_5CRectEEUlvE_E9_M_invokeERKSt9_Any_data+0x10b) [0x7fd8310d027b]
./target/vst2/Release/Surge.so(_ZN6VSTGUI3X1118RedrawTimerHandler7onTimerEv+0x2e) [0x7fd8310d0cfe]
./target/vst2/Release/Surge.so(_ZN6VSTGUI12LinuxRunLoop4idleEv+0x24) [0x7fd8310446b4]
./target/vst2/Release/Surge.so(_ZN6VSTGUI18LinuxAEffGUIEditor5idle2Ev+0x29) [0x7fd831044769]
./target/vst2/Release/Surge.so(_ZN14SurgeGUIEditor4idleEv+0x2c) [0x7fd830fef54c]
./target/vst2/Release/Surge.so(_ZN11AudioEffect10dispatcherEiilPvf+0x31f) [0x7fd83102747f]
./target/vst2/Release/Surge.so(_ZN12AudioEffectX10dispatcherEiilPvf+0x6fd) [0x7fd831028d1d]
/home/paul/Carla_2.0-RC3-linux64/carla/carla-bridge-native() [0x4d739e]
/home/paul/Carla_2.0-RC3-linux64/carla/carla-bridge-native() [0x42c90d]
/home/paul/Carla_2.0-RC3-linux64/carla/carla-bridge-native() [0x42c400]
/home/paul/Carla_2.0-RC3-linux64/carla/carla-bridge-native() [0x415b72]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xe7) [0x7fd83506ab97]
/home/paul/Carla_2.0-RC3-linux64/carla/carla-bridge-native() [0x42bab1]

so this isn't an navies problem; this is a CViewFrame problem of some sort.

That's aggravating. I'm going to tag this one vstgui since it at least has a vstgui part. (There may be other things running the CPU high; like I said I didn't walk as far down the AU processing instrumentation thread)

@baconpaul
Copy link
Collaborator

note it may also be that surge is calling invalid() in too many places. Worth looking at that as a possibility too before diving head first into vstgui code.

@baconpaul
Copy link
Collaborator

Okely dokely so here's a bit more information

We invalidate the VU meter on every ::idle. That makes sense. It calls CFrame::drawRect with size 123x13 @ 763x14

but that draw rect clipping forces the entire background to redraw. All of it

That's pretty clearly not optimal. Explains why some CPU is leaking there. I think that's a VSTGUI bug - it should also minimally redraw the background image. But am not 100% sure.

baconpaul added a commit to baconpaul/surge that referenced this issue Feb 21, 2019
The VU Meter was a cause of substantial idle load. In a 30 second
timer sample, a full half second was spent drawing background
images - as much time as was spent filling up the audio buffer
with no sound. There were a couple of key reasons for this:

1. The VU Meter invalidates every idle even if value hasn't changed
2. When the VU meter invalidates even legitimately it forces a
   full repaint of the background image into a clip rect because
   that's what VSTGUI::CViewContainer does

So - somewhat unsatisfactorily in the second case - this diff
fixes those by only invalidating when value changes (which is
great for idle) and supressing the background image repaint
using knowledge of the placement of the VU meter (which is
fragile and unsatisfying but the only option we have given
the protection of VSTGUI::CFrame's final status and so on).

While at it, replace the pixel painted edges so the VU meeter
has a better boundary when zoomed.

Closes surge-synthesizer#639 - Re-Implement VU Meter
Addresses parts of surge-synthesizer#446 and surge-synthesizer#556; performance and pixely bits
baconpaul added a commit to baconpaul/surge that referenced this issue Feb 21, 2019
The VU Meter was a cause of substantial idle load. In a 30 second
timer sample, a full half second was spent drawing background
images - as much time as was spent filling up the audio buffer
with no sound. There were a couple of key reasons for this:

1. The VU Meter invalidates every idle even if value hasn't changed
2. When the VU meter invalidates even legitimately it forces a
   full repaint of the background image into a clip rect because
   that's what VSTGUI::CViewContainer does

So - somewhat unsatisfactorily in the second case - this diff
fixes those by only invalidating when value changes (which is
great for idle) and supressing the background image repaint
using knowledge of the placement of the VU meter (which is
fragile and unsatisfying but the only option we have given
the protection of VSTGUI::CFrame's final status and so on).

While at it, replace the pixel painted edges so the VU meeter
has a better boundary when zoomed.

Closes surge-synthesizer#639 - Re-Implement VU Meter
Addresses parts of surge-synthesizer#446 and surge-synthesizer#556; performance and pixely bits
@baconpaul
Copy link
Collaborator

OK with the VU meter fixed if I pop it up in hosting AU and use init sine and click latch so it just pumps sin wave out through the graph and sample for 30 seconds, the profiler only catches us in a stack about 860ms of the 30,000ms. That's pretty good. And the UI is way dropped. 50% in the audio thread, 15% in miscellaneous host threads (I'm using "Hosting AU") and 35% in the UI thread.

Drilling down the audio thread, seems half of it is overhead (move buffers around) but of the 410ms sampled here's the timing once you get down to SurgeSynthesizer::Process

screen shot 2019-02-21 at 7 39 29 pm

@baconpaul
Copy link
Collaborator

Fascinatingly our audio render time of 270ms has 41ms - which is what, like 15% - just doing SurgePatch::copy_scenedata and SurgePatch::copy_globaldata

The code mentions that the copy global data takes a great deal of CPU in debug mode.

Curious. Anyway I'm going to leave this alone until 1.6.1 I think now I have fixed the draw problem. But I think hitting the code with a profiler or two on a couple of interesting situations may show us a lot.

baconpaul added a commit that referenced this issue Feb 23, 2019
The VU Meter was a cause of substantial idle load. In a 30 second
timer sample, a full half second was spent drawing background
images - as much time as was spent filling up the audio buffer
with no sound. There were a couple of key reasons for this:

1. The VU Meter invalidates every idle even if value hasn't changed
2. When the VU meter invalidates even legitimately it forces a
   full repaint of the background image into a clip rect because
   that's what VSTGUI::CViewContainer does

So - somewhat unsatisfactorily in the second case - this diff
fixes those by only invalidating when value changes (which is
great for idle) and supressing the background image repaint
using knowledge of the placement of the VU meter (which is
fragile and unsatisfying but the only option we have given
the protection of VSTGUI::CFrame's final status and so on).

While at it, replace the pixel painted edges so the VU meeter
has a better boundary when zoomed.

Closes #639 - Re-Implement VU Meter
Addresses parts of #446 and #556; performance and pixely bits
@baconpaul baconpaul added this to the 1.6.0 milestone Feb 28, 2019
@baconpaul baconpaul modified the milestones: 1.6.0, 1.6.n Mar 12, 2019
@baconpaul
Copy link
Collaborator

OK a bit more usefully you can run this in headless mode with the stress test and you see where times going. Interestingly creating a surge and loading the data takes some time but remember we are "playing" faster than audio rate here. Purposefully putting CPU to 100%.

Hotspots when you do that include "WaveTableOscillator::convolute" "Effect:ringout" and all the "ProcessFBQuad" routines.

I'm going to change the title of this issue to "Performance Profiling Surge" since I think a lot of the 0 CPU things are fixed with the UI change I made. Will leave this here for people to pick away at if they want.

Screen Shot 2019-04-04 at 10 43 54 AM

@baconpaul baconpaul changed the title NewSurge takes way more CPU at silent + init-state than Surge1.5.2 Performance Profiling Surge Apr 14, 2019
baconpaul added a commit to baconpaul/surge that referenced this issue Jul 10, 2019
The VU Meter was a cause of substantial idle load. In a 30 second
timer sample, a full half second was spent drawing background
images - as much time as was spent filling up the audio buffer
with no sound. There were a couple of key reasons for this:

1. The VU Meter invalidates every idle even if value hasn't changed
2. When the VU meter invalidates even legitimately it forces a
   full repaint of the background image into a clip rect because
   that's what VSTGUI::CViewContainer does

So - somewhat unsatisfactorily in the second case - this diff
fixes those by only invalidating when value changes (which is
great for idle) and supressing the background image repaint
using knowledge of the placement of the VU meter (which is
fragile and unsatisfying but the only option we have given
the protection of VSTGUI::CFrame's final status and so on).

While at it, replace the pixel painted edges so the VU meeter
has a better boundary when zoomed.

Closes surge-synthesizer#639 - Re-Implement VU Meter
Addresses parts of surge-synthesizer#446 and surge-synthesizer#556; performance and pixely bits

Former-commit-id: 0e650308bda2a949e7c32265c3c534c9252835ec [formerly b51bdd2]
Former-commit-id: 075d28ec6fb51087fe96dcac3aa76def95574427
Former-commit-id: ce8d1c8ea41323ee2fce9dab210c644cbc9de14a
@baconpaul baconpaul modified the milestones: 1.6.n, Currently Unscheduled Oct 4, 2019
@baconpaul
Copy link
Collaborator

I should move this information to the doc/ folder on how to profile on a mac and then close this issue.

@baconpaul baconpaul modified the milestones: Currently Unscheduled, 1.6.5 Dec 3, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants