[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

[sc-users] profiling sclang

Hi
Any advice on how to profile sclang ? I need to understand why sometimes some fairly complex sclang code causes the process to use 100% cpu and become unresponsive. I'm using MIDI and timers sending a lot of midi messages to get some blinking lights, and guis. When the system hangs the midi part still seems to keep working but the gui freezes. 

I'm trying the linux perf tool. This is what I get.

normal view:
+   38,44%    33,77%  sclang           sclang                  [.] Interpret
+ 24,87% 0,00% sclang [unknown] [k] 0x00005556446ec900 + 24,87% 0,00% sclang [unknown] [k] 0x000055564ba4bc58 + 17,42% 17,35% sclang sclang [.] PyrGC::ScanSlots + 11,90% 11,46% sclang sclang [.] blockValue + 11,14% 11,04% sclang sclang [.] PyrGC::NewFrame + 7,80% 7,48% sclang sclang [.] doPrimitive + 7,60% 0,00% sclang [unknown] [.] 0000000000000000 + 3,87% 3,59% sclang sclang [.] returnFromBlock + 3,64% 2,42% sclang sclang [.] slotRawInt 
+    3,45%     2,55%  sclang           sclang                  [.] slotCopy
+ 2,73% 2,62% sclang sclang [.] PyrGC::ScanOneObj + 2,43% 0,00% sclang [unknown] [.] 0x000055564ee0b4e8 + 2,43% 0,00% sclang [unknown] [.] 0x000055564f15ddc8 + 2,43% 0,00% sclang [unknown] [.] 0x000055564e5a0268 + 2,43% 0,00% sclang [unknown] [.] 0x000055564e425e08 + 2,43% 0,00% sclang [unknown] [.] 0x000055564ba4c258 + 2,43% 0,00% sclang [unknown] [.] 0x0000555651badd78 + 2,19% 0,00% sclang [unknown] [.] 0x000055564f863c48 + 2,17% 0,00% sclang [unknown] [.] 0x000055564f1d57f8 + 2,17% 0,00% sclang [unknown] [.] 0x000055564f595178 + 2,17% 0,00% sclang [unknown] [.] 0x00005556523e5308 + 2,06% 0,00% sclang [unknown] [.] 0x000055564e823ed8 + 1,99% 1,97% sclang sclang [.] classOfSlot + 1,95% 0,00% sclang [unknown] [.] 0x0000555645a4a7c8 + 1,71% 0,00% sclang [unknown] [.] 0x000055564ba73c78 1,52% 1,43% sclang sclang [.] getIndexedSlot 


DSO:
+ 38,44% 33,77% sclang [.] Interpret
+ 17,42% 17,35% sclang [.] PyrGC::ScanSlots 
                                                                   ▒
+ 11,90% 11,46% sclang [.] blockValue 
                                                                   ▒
+ 11,14% 11,04% sclang [.] PyrGC::NewFrame 
                                                                   ▒
+ 7,80% 7,48% sclang [.] doPrimitive 
                                                                   ▒
+ 3,87% 3,59% sclang [.] returnFromBlock 
                                                                   ▒
+ 3,64% 2,42% sclang [.] slotRawInt 
                                                                   ▒
+ 3,45% 2,55% sclang [.] slotCopy 
                                                                   ▒
+ 2,73% 2,62% sclang [.] PyrGC::ScanOneObj 
                                                                   ▒
+ 1,99% 1,97% sclang [.] classOfSlot 
                                                                   ▒
1,52% 1,43% sclang [.] getIndexedSlot 
                                                                    ▒
+ 1,16% 0,86% sclang [.] objectIdentical 
                                                                   ▒
0,99% 0,63% sclang [.] slotRawObject 
                                                                    ▒
0,65% 0,35% sclang [.] SetTagRaw 
                                                                    ▒
+ 0,61% 0,61% sclang [.] slotRawSymbol 
                                                                   ▒
0,56% 0,49% sclang [.] PyrGC::Collect 
                                                                    ▒
     0,55%     0,29%  sclang  [.] slotRawFrame


Opening the second item:
- 24,87% 0,00% sclang [unknown] [k] 0x000055564ba4bc58 
         ▒
- 0x55564ba4bc58 
                                                                    ▒
+ 12,82% 0x5556446ec900 
                                                                    ▒
10,94% blockValue 
                                                                    ▒
        1,08% PyrGC::NewFrame
If I use gdb to stop the process at random times most of the time it is in function Interpret. Args and vars are not very informative: 

(gdb) info args
g = 0x555644199220 <gVMGlobals>
(gdb) info locals
meth = 0x555651a4fd00
ip = 0x55564d472aec <incomplete sequence \371>
op1 = 2 '\002'
numKeyArgsPushed = 1369767168
selector = 0x555650618db8
sp = 0x5556498742e8

At other times it is in:

PyrGC::Allocate

I've also caught it at:
#2 0x0000555643cb8f23 in doPrimitive (g=0x555644199220 <gVMGlobals>, meth=0x55564c211300, numArgsPushed=<optimized out>) at /home/miguel/Development/SuperCollider/supercollider/lang/LangPrimSource/PyrPrimitive.cpp:3901 3901 //post("doPrimitive %s:%s\n", slotRawSymbol(&slotRawClass(&meth->ownerclass)->name)->name, slotRawSymbol(&meth->name)->name); 
(gdb) info args
g = 0x555644199220 <gVMGlobals>
meth = 0x55564c211300
numArgsPushed = <optimized out>
(gdb) info locals
methraw = 0x55564c211328
primIndex = <optimized out>
def = <optimized out>
numArgsNeeded = 3
diff = <optimized out>
err = <optimized out>
So the info from the gdb doesn't appear to be very informative, in particular I can't seem to find what is the function or method name that was being interpreted by Interpret. 

Any hints for finding which sc code is causing most of the cpu usage ?

Coding without a debugger or profiler (for sclang) is a bit hard... :-(

thanks
--
Miguel Negrão
http://www.friendlyvirus.org/miguelnegrao



_______________________________________________
sc-users mailing list

info (subscription, etc.): http://www.birmingham.ac.uk/facilities/ea-studios/research/supercollider/mailinglist.aspx
archive: https://listarc.bham.ac.uk/marchives/sc-users/
search: https://listarc.bham.ac.uk/lists/sc-users/search/