10:23 a.m.
> > > PS: a couple of updates about specific points (Michal,
Nir)
> > > - still no luck with yappi on RHEL7, managed to do the above bench
> > > with 10 VMs and collected a profile.
> >
> > Can you share the profile with us?
>
> please find attached.
Ok, here are profile report - from the profile I see that you run the new
scalable sampling branch.
It will be interesting to compare this with profile of master
code.
Looking at the profiles we can see that there is no much to
optimize. A profile with 100 or 200 vms would be more
interesting when yappi is fixed to cope with this concurrency
level.
Thu Jul 31 17:33:34 2014 rhel7_enhanced_vdsmd.prof
27631973 function calls (32490375 primitive calls) in 38.141 seconds
Ordered by: internal time
List reduced from 2646 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
46 6.058 0.242 3.636 0.079
/usr/lib64/python2.7/threading.py:753(Thread.run)
4688193 3.898 0.000 3.898 0.000 __builtin__:0(poll)
9492888 2.133 0.000 2.133 0.000 time:0(time)
4684972 1.811 0.000 1.811 0.000 __builtin__:0(max)
11157 0.786 0.000 1.081 0.000
/usr/lib/python2.7/site-packages/mom/Policy/spark.py:211(Parser.buildState)
15612 0.767 0.000 0.809 0.000 libvirtmod:0(virEventRunDefaultImpl)
23419 0.607 0.000 0.690 0.000
/usr/lib/python2.7/site-packages/pthread.py:133(Cond.timedwait)
105699 0.509 0.000 0.509 0.000
/usr/lib/python2.7/site-packages/pthread.py:95(Lock.lock)
105769 0.483 0.000 0.524 0.000
/usr/lib/python2.7/site-packages/pthread.py:98(Lock.unlock)
21628 0.468 0.000 0.468 0.000 __builtin__:0(<method 'read' of
'file' objects>)
46 0.467 0.011 1.984 0.043
/usr/lib/python2.7/site-packages/mom/GuestMonitor.py:51(GuestMonitor.run)
257 0.417 0.002 0.417 0.002 posix:0(fork)
29299 0.384 0.000 1.307 0.000
/usr/lib/python2.7/site-packages/pthreading.py:115(Condition.wait)
323 0.383 0.001 0.383 0.001 cpopen.cpopen:0(createProcess)
4151 0.378 0.000 1.571 0.000
/usr/share/vdsm/virt/vm.py:2470(Vm._getRunningVmStats)
3047 0.303 0.000 0.303 0.000 libvirtmod:0(virDomainGetBlockInfo)
105807 0.302 0.000 0.841 0.000
/usr/lib/python2.7/site-packages/pthreading.py:66(Lock.acquire)
105769 0.297 0.000 0.820 0.000
/usr/lib/python2.7/site-packages/pthreading.py:77(Lock.release)
17767 0.272 0.000 0.674 0.000
/usr/lib64/python2.7/site-packages/vdsm/schedule.py:150(Scheduler._pop_expired_calls)
267579 0.255 0.000 0.350 0.000 /usr/lib64/python2.7/string.py:511(replace)
Ordered by: internal time
List reduced from 2646 to 20 due to restriction <20>
Function was
called by...
ncalls tottime cumtime
/usr/lib64/python2.7/threading.py:753(Thread.run)
<- 1/0 5.623 5.623
/usr/lib64/python2.7/logging/__init__.py:598(Logger.filter)
1/0 0.018 0.018
/usr/lib64/python2.7/logging/__init__.py:693(WatchedFileHandler.acquire)
2/0 0.043 0.043
/usr/lib64/python2.7/logging/__init__.py:828(WatchedFileHandler.flush)
1/0 0.186 0.186
/usr/lib64/python2.7/logging/__init__.py:1215(Logger.findCaller)
1/0 0.188 0.188 /usr/lib64/python2.7/posixpath.py:51(normcase)
__builtin__:0(poll)
<- 1798 0.010 0.010
/usr/lib/python2.7/site-packages/ioprocess/__init__.py:51(NoIntrPoll)
1335/1334 0.030 0.030 /usr/lib64/python2.7/asyncore.py:170(poll2)
4683270/4683269 3.845 3.845
/usr/lib64/python2.7/site-packages/M2Crypto/__init__.py:17(<module>)
1790 0.014 0.014
/usr/lib64/python2.7/subprocess.py:1406(CPopen._communicate_with_poll)
time:0(time)
<- 23419 0.006 0.006
/usr/lib/python2.7/site-packages/pthreading.py:115(Condition.wait)
14297 0.007 0.007 /usr/lib64/python2.7/Queue.py:150(Queue.get)
3 0.000 0.000 /usr/lib64/python2.7/ftplib.py:883(Netrc)
7557 0.003 0.003
/usr/lib64/python2.7/logging/__init__.py:242(LogRecord.__init__)
19 0.000 0.000
/usr/lib64/python2.7/multiprocessing/connection.py:77(_init_timeout)
9366537 2.082 2.082
/usr/lib64/python2.7/site-packages/M2Crypto/__init__.py:17(<module>)
9004 0.004 0.004
/usr/lib64/python2.7/site-packages/vdsm/schedule.py:101(Scheduler.schedule)
17766 0.006 0.006
/usr/lib64/python2.7/site-packages/vdsm/schedule.py:145(Scheduler._time_until_deadline)
17767 0.011 0.011
/usr/lib64/python2.7/site-packages/vdsm/schedule.py:150(Scheduler._pop_expired_calls)
1 0.000 0.000
/usr/lib64/python2.7/site-packages/vdsm/sslutils.py:218(VerifyingHTTPS)
670 0.000 0.000
/usr/lib64/python2.7/site-packages/vdsm/utils.py:294(NoIntrPoll)
6 0.000 0.000
/usr/lib64/python2.7/site-packages/vdsm/utils.py:516(AsyncProc.wait)
4 0.000 0.000 /usr/lib64/python2.7/site-packages/vdsm/utils.py:858(retry)
589 0.000 0.000 /usr/lib64/python2.7/xmlrpclib.py:482(Binary)
1 0.000 0.000 /usr/lib64/python2.7/xmlrpclib.py:543(ExpatParser)
44 0.000 0.000 /usr/share/vdsm/API.py:1247(Global.getStats)
2 0.000 0.000 /usr/share/vdsm/clientIF.py:539(clientIF._recoverVm)
2 0.000 0.000
/usr/share/vdsm/protocoldetector.py:198(MultiProtocolAcceptor._handle_connection_read)
134 0.000 0.000
/usr/share/vdsm/storage/blockSD.py:821(BlockStorageDomain.selftest)
534 0.000 0.000
/usr/share/vdsm/storage/domainMonitor.py:44(DomainMonitorStatus.clear)
3 0.000 0.000
/usr/share/vdsm/storage/domainMonitor.py:136(DomainMonitorThread.__init__)
407 0.000 0.000
/usr/share/vdsm/storage/domainMonitor.py:189(DomainMonitorThread._monitorDomain)
109 0.000 0.000 /usr/share/vdsm/storage/hsm.py:3570(HSM._getRepoStats)
1 0.000 0.000 /usr/share/vdsm/storage/sdc.py:93(StorageDomainCache.produce)
8294 0.002 0.002 /usr/share/vdsm/virt/guestagent.py:324(GuestAgent.isResponsive)
333 0.000 0.000 /usr/share/vdsm/virt/sampling.py:233(HostSample.__init__)
5747 0.003 0.003
/usr/share/vdsm/virt/sampling.py:366(AdvancedStatsFunction.__call__)
5747 0.002 0.002 /usr/share/vdsm/virt/sampling.py:457(Sampler.__call__)
2 0.000 0.000 /usr/share/vdsm/virt/sampling.py:543(HostStatsThread.__init__)
44 0.000 0.000 /usr/share/vdsm/virt/sampling.py:600(HostStatsThread.get)
44 0.000 0.000
/usr/share/vdsm/virt/sampling.py:663(HostStatsThread._getInterfacesStats)
667 0.000 0.000 /usr/share/vdsm/virt/vm.py:134(DRIVE_SHARED_TYPE)
4150 0.001 0.001 /usr/share/vdsm/virt/vm.py:586(VmStats.get)
677 0.000 0.000 /usr/share/vdsm/virt/vm.py:625(TimeoutError)
12 0.000 0.000 /usr/share/vdsm/virt/vm.py:1466(Vm.__init__)
4151 0.000 0.002 /usr/share/vdsm/virt/vm.py:2470(Vm._getRunningVmStats)
4144 0.002 0.002 /usr/share/vdsm/virt/vm.py:2526(_getVmStatusFromGuest)
__builtin__:0(max)
<- 1 0.000 0.000
/usr/lib/python2.7/site-packages/yajsonrpc/stompReactor.py:324(StompDetector)
4683270 1.810 1.810
/usr/lib64/python2.7/site-packages/M2Crypto/__init__.py:17(<module>)
1 0.000 0.000
/usr/lib64/python2.7/site-packages/vdsm/sslutils.py:218(VerifyingHTTPS)
589 0.000 0.000 /usr/lib64/python2.7/socket.py:292(_fileobject.flush)
589 0.000 0.000 /usr/lib64/python2.7/socket.py:336(_fileobject.read)
105 0.000 0.000 /usr/lib64/python2.7/sre_parse.py:141(SubPattern.getwidth)
1 0.000 0.000 /usr/share/vdsm/virt/sampling.py:543(HostStatsThread.__init__)
44 0.000 0.000 /usr/share/vdsm/virt/sampling.py:600(HostStatsThread.get)
352 0.000 0.000
/usr/share/vdsm/virt/sampling.py:633(HostStatsThread._getCpuCoresStats)
20 0.000 0.000 /usr/share/vdsm/virt/vm.py:2812(Vm._domDependentInit)
/usr/lib/python2.7/site-packages/mom/Policy/spark.py:211(Parser.buildState)
<- 11157 0.786 1.081
/usr/lib/python2.7/site-packages/mom/Policy/spark.py:187(Parser.parse)
libvirtmod:0(virEventRunDefaultImpl)
<- 15612/15611 0.767 0.809
/usr/lib64/python2.7/site-packages/libvirt.py:288(virEventRunDefaultImpl)
/usr/lib/python2.7/site-packages/pthread.py:133(Cond.timedwait)
<- 23419/23392 0.607 0.690
/usr/lib/python2.7/site-packages/pthreading.py:115(Condition.wait)
/usr/lib/python2.7/site-packages/pthread.py:95(Lock.lock)
<- 105698 0.509 0.509
/usr/lib/python2.7/site-packages/pthreading.py:66(Lock.acquire)
1 0.000 0.000 /usr/share/vdsm/storage/threadPool.py:211(WorkerThread.run)
/usr/lib/python2.7/site-packages/pthread.py:98(Lock.unlock)
<- 105769 0.483 0.524
/usr/lib/python2.7/site-packages/pthreading.py:77(Lock.release)
__builtin__:0(<method 'read' of 'file' objects>)
<- 1200 0.027 0.027
/usr/lib/python2.7/site-packages/mom/Collectors/GuestQemuProc.py:43(GuestQemuProc.collect)
5 0.000 0.000
/usr/lib/python2.7/site-packages/mom/GuestManager.py:24(GuestManager)
1 0.000 0.000 /usr/lib64/python2.7/platform.py:1000(_syscmd_uname)
849 0.000 0.000 /usr/lib64/python2.7/shlex.py:120(shlex.read_token)
1224 0.005 0.005
/usr/lib64/python2.7/site-packages/vdsm/netinfo.py:174(bondOpts)
35 0.000 0.000
/usr/lib64/python2.7/site-packages/vdsm/netinfo.py:199(bridgeOpts)
668 0.003 0.003
/usr/lib64/python2.7/site-packages/vdsm/netinfo.py:258(operstate)
334 0.002 0.002
/usr/lib64/python2.7/site-packages/vdsm/netinfo.py:288(nicSpeed)
257 0.010 0.010 /usr/lib64/python2.7/subprocess.py:475(_eintr_retry_call)
133 0.013 0.013 /usr/lib64/python2.7/xml/dom/expatbuilder.py:561(Skipper)
399 0.003 0.003 /usr/share/vdsm/API.py:1573(Global._memAvailable)
1 0.000 0.000 /usr/share/vdsm/caps.py:367(_getAllCpuModels)
1 0.000 0.000 /usr/share/vdsm/caps.py:464(_getKdumpStatus)
1 0.000 0.000 /usr/share/vdsm/caps.py:534(_getSELinuxEnforceMode)
16 0.000 0.000 /usr/share/vdsm/storage/multipath.py:190(getDeviceBlockSizes)
55 0.000 0.000 /usr/share/vdsm/storage/multipath.py:385(getMPDevsIter)
11988 0.102 0.102
/usr/share/vdsm/virt/sampling.py:81(InterfaceSample.readIfaceStat)
333 0.011 0.011 /usr/share/vdsm/virt/sampling.py:227(PidCpuSample.__init__)
666 0.005 0.005 /usr/share/vdsm/virt/sampling.py:278(HostSample.__init__)
1998 0.227 0.227 /usr/share/vdsm/virt/sampling.py:749(_getDuplex)
1064 0.003 0.003 /usr/share/vdsm/virt/vm.py:23(<module>)
266 0.051 0.051 /usr/share/vdsm/virt/vm.py:756(NetworkInterfaceDevice)
134 0.004 0.004 /usr/share/vdsm/virt/vm.py:1375(RngDevice)
/usr/lib/python2.7/site-packages/mom/GuestMonitor.py:51(GuestMonitor.run)
<- 1 0.011 0.011
/usr/lib/python2.7/site-packages/mom/HostMonitor.py:25(HostMonitor)
1 0.176 0.176
/usr/lib/python2.7/site-packages/pthreading.py:63(Lock.__exit__)
1 0.165 0.165
/usr/lib/python2.7/site-packages/pthreading.py:109(Condition.__enter__)
1 0.025 0.026 /usr/lib64/python2.7/glob.py:18(glob)
1/0 0.016 0.016 /usr/lib64/python2.7/glob.py:66(glob1)
1 0.055 0.055 /usr/lib64/python2.7/threading.py:442(_Semaphore.acquire)
1/0 0.004 0.004 /usr/lib64/python2.7/threading.py:570(_Event.isSet)
1 0.005 0.006 /usr/share/vdsm/virt/vm.py:2525(Vm._getVmStatus)
posix:0(fork)
<- 257 0.417 0.417
/usr/lib64/python2.7/subprocess.py:1173(Popen._execute_child)
/usr/lib/python2.7/site-packages/pthreading.py:115(Condition.wait)
<- 4782/4759 0.059 0.223 /usr/lib64/python2.7/Queue.py:150(Queue.get)
5752/5747 0.036 0.260
/usr/lib64/python2.7/site-packages/vdsm/executor.py:110(Executor._next_task)
17746/17745 0.273 0.770
/usr/lib64/python2.7/site-packages/vdsm/schedule.py:131(Scheduler._loop)
1017/1012 0.016 0.053 /usr/lib64/python2.7/threading.py:603(_Event.wait)
1 0.000 0.000 /usr/share/vdsm/storage/misc.py:871(OperationMutex.acquire)
1 0.000 0.000
/usr/share/vdsm/storage/sdc.py:101(StorageDomainCache._realProduce)
cpopen.cpopen:0(createProcess)
<- 323 0.383 0.383
/usr/lib64/python2.7/site-packages/cpopen/__init__.py:67(CPopen._execute_child_v275)
/usr/share/vdsm/virt/vm.py:2470(Vm._getRunningVmStats)
<- 4151 0.378 1.571 /usr/share/vdsm/virt/vm.py:2425(Vm.getStats)
libvirtmod:0(virDomainGetBlockInfo)
<- 3047 0.303 0.303
/usr/lib64/python2.7/site-packages/libvirt.py:1953(virDomain.blockInfo)
/usr/lib/python2.7/site-packages/pthreading.py:66(Lock.acquire)
<- 71436 0.266 0.644
/usr/lib/python2.7/site-packages/pthreading.py:59(Lock.__enter__)
297 0.000 0.001 /usr/lib64/python2.7/Queue.py:45(Queue.task_done)
297 0.000 0.001 /usr/lib64/python2.7/Queue.py:93(Queue.empty)
1062 0.002 0.005 /usr/lib64/python2.7/Queue.py:107(Queue.put)
6132 0.016 0.053 /usr/lib64/python2.7/Queue.py:150(Queue.get)
741 0.003 0.008 /usr/lib64/python2.7/logging/__init__.py:210(_acquireLock)
21666 0.006 0.109
/usr/lib64/python2.7/logging/__init__.py:693(WatchedFileHandler.acquire)
1 0.000 0.000
/usr/lib64/python2.7/multiprocessing/managers.py:699(AutoProxy[instance].__init__)
2 0.000 0.000
/usr/lib64/python2.7/site-packages/vdsm/utils.py:450(AsyncProc._processStreams)
46 0.000 0.000 /usr/lib64/python2.7/tempfile.py:135(_RandomNameSequence.next)
740 0.001 0.003 /usr/lib64/python2.7/threading.py:576(_Event.set)
2 0.000 0.000 /usr/lib64/python2.7/threading.py:590(_Event.clear)
1412 0.003 0.009 /usr/lib64/python2.7/threading.py:603(_Event.wait)
1 0.000 0.000 /usr/lib64/python2.7/threading.py:753(Thread.run)
74 0.000 0.001 /usr/lib64/python2.7/threading.py:867(Thread.__stop)
12 0.000 0.000 /usr/share/vdsm/API.py:328(VM.destroy)
106 0.000 0.001 /usr/share/vdsm/storage/misc.py:871(OperationMutex.acquire)
88 0.000 0.000 /usr/share/vdsm/storage/resourceManager.py:789(Owner.acquire)
332 0.000 0.001
/usr/share/vdsm/storage/resourceManager.py:938(Owner.releaseAll)
88 0.000 0.000 /usr/share/vdsm/storage/resourceManager.py:950(Owner.release)
333 0.000 0.001 /usr/share/vdsm/storage/resourceManager.py:976(Owner.cancelAll)
88 0.000 0.000 /usr/share/vdsm/storage/task.py:820(Task.resourceAcquired)
2 0.000 0.000 /usr/share/vdsm/storage/task.py:927(Task._doAbort)
422 0.001 0.002 /usr/share/vdsm/storage/task.py:975(Task._incref)
422 0.001 0.001 /usr/share/vdsm/storage/task.py:987(Task._decref)
2 0.000 0.000
/usr/share/vdsm/storage/threadPool.py:46(ThreadPool.setRunningTask)
3 0.000 0.000
/usr/share/vdsm/storage/threadPool.py:64(ThreadPool.setThreadCount)
/usr/lib/python2.7/site-packages/pthreading.py:77(Lock.release)
<- 1 0.000 0.000
/usr/lib/python2.7/site-packages/mom/GuestMonitor.py:51(GuestMonitor.run)
71429 0.242 0.654
/usr/lib/python2.7/site-packages/pthreading.py:63(Lock.__exit__)
297 0.000 0.001 /usr/lib64/python2.7/Queue.py:45(Queue.task_done)
297 0.000 0.001 /usr/lib64/python2.7/Queue.py:93(Queue.empty)
1062 0.001 0.003 /usr/lib64/python2.7/Queue.py:107(Queue.put)
6109 0.015 0.053 /usr/lib64/python2.7/Queue.py:150(Queue.get)
741 0.002 0.007 /usr/lib64/python2.7/logging/__init__.py:219(_releaseLock)
21666 0.027 0.078
/usr/lib64/python2.7/logging/__init__.py:700(WatchedFileHandler.release)
1 0.000 0.000
/usr/lib64/python2.7/multiprocessing/managers.py:699(AutoProxy[instance].__init__)
2 0.000 0.000
/usr/lib64/python2.7/site-packages/vdsm/utils.py:450(AsyncProc._processStreams)
46 0.000 0.000 /usr/lib64/python2.7/tempfile.py:135(_RandomNameSequence.next)
740 0.001 0.003 /usr/lib64/python2.7/threading.py:576(_Event.set)
2 0.000 0.000 /usr/lib64/python2.7/threading.py:590(_Event.clear)
1407 0.004 0.014 /usr/lib64/python2.7/threading.py:603(_Event.wait)
74 0.000 0.001 /usr/lib64/python2.7/threading.py:867(Thread.__stop)
12 0.000 0.000 /usr/share/vdsm/API.py:328(VM.destroy)
103 0.000 0.001 /usr/share/vdsm/storage/misc.py:892(OperationMutex.release)
88 0.000 0.000 /usr/share/vdsm/storage/resourceManager.py:789(Owner.acquire)
332 0.000 0.001
/usr/share/vdsm/storage/resourceManager.py:938(Owner.releaseAll)
88 0.000 0.000 /usr/share/vdsm/storage/resourceManager.py:950(Owner.release)
333 0.000 0.001 /usr/share/vdsm/storage/resourceManager.py:976(Owner.cancelAll)
88 0.000 0.000 /usr/share/vdsm/storage/task.py:820(Task.resourceAcquired)
2 0.000 0.000 /usr/share/vdsm/storage/task.py:927(Task._doAbort)
422 0.001 0.001 /usr/share/vdsm/storage/task.py:975(Task._incref)
422 0.000 0.001 /usr/share/vdsm/storage/task.py:987(Task._decref)
2 0.000 0.000
/usr/share/vdsm/storage/threadPool.py:46(ThreadPool.setRunningTask)
3 0.000 0.000
/usr/share/vdsm/storage/threadPool.py:64(ThreadPool.setThreadCount)
/usr/lib64/python2.7/site-packages/vdsm/schedule.py:150(Scheduler._pop_expired_calls)
<- 17767 0.272 0.674
/usr/lib64/python2.7/site-packages/vdsm/schedule.py:131(Scheduler._loop)
/usr/lib64/python2.7/string.py:511(replace)
<- 267579 0.255 0.350 /usr/lib64/python2.7/xmlrpclib.py:174(escape)