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)