Description of problem: depends on BZ 1177634 by having profiling vdsmd dumps, task._run logs found as a performance issue. by looking the profile analysis logUtils very hit the performance. task.py:1155(Task.prepare) <- 159/158 0.043 387.273 task.py:99(Task.wrapper) task.py:869(Task._run) <- 159/158 0.006 383.882 task.py:1155(Task.prepare) logUtils.py:40(wrapper) <- 159/158 0.089 383.862 task.py:869(Task._run) vm.py:2339(Vm.preparePaths) <- 16/15 0.000 379.952 clientIF.py:491(clientIF._recoverVm) clientIF.py:267(clientIF.prepareVolumePath) <- 48/47 0.003 379.950 vm.py:2339(Vm.preparePaths) hsm.py:3188(HSM.prepareImage) <- 16/15 0.000 379.709 logUtils.py:40(wrapper) looks like the logUtils is the main issue, but for comparison the log calls were commented from the Task._run actions. as a results the gone for the topest hotspot profiling results. Version-Release number of selected component (if applicable): 3.5 VT13.5 How reproducible: 100% Steps to Reproduce: 1.25 vms running on host Actual results: using over logs may hit the performance. Expected results: using minimum logs Additional info: further investigation required look like logUtils may have some performance issues.
this is part of VM recovery so not critical for performance of a running system. However, there might be further optimizations possible in preparePaths - Nir, anything interesting there?
Looking in a profile with 25 vms, we don't see any logging related function in the top of the profile: Fri Jan 16 23:54:48 2015 vdsmd_25vms_3_5_jsonrpc_1800sec_cpu.prof 80952438 function calls (82245529 primitive calls) in 1921.656 seconds Ordered by: internal time List reduced from 2637 to 20 due to restriction <20> ncalls tottime percall cumtime percall filename:lineno(function) 275075 611.045 0.002 611.045 0.002 fileSD.py:444(<genexpr>) 36131 56.048 0.002 180.522 0.005 vm.py:2849(Vm._getRunningVmStats) 1673681 41.673 0.000 65.290 0.000 protocoldetector.py:94(MultiProtocolAcceptor._process_events) 157109 40.947 0.000 91.926 0.001 spark.py:211(Parser.buildState) 201940 32.269 0.000 38.662 0.000 spark.py:103(Parser.addRule) 40388 24.992 0.001 29.322 0.001 spark.py:146(Parser.makeFIRST) 16890 23.803 0.001 52.007 0.003 inspect.py:247(getmembers) 926097 21.156 0.000 21.156 0.000 utils.py:425(convertToStr) 80776 19.588 0.000 25.824 0.000 spark.py:28(_namelist) 1712725 19.368 0.000 19.368 0.000 __builtin__:0(poll) 46776 18.388 0.000 42.268 0.001 expatbuilder.py:743(ExpatBuilderNS.start_element_handler) 156451 18.231 0.000 23.948 0.000 migration.py:380(MonitorThread) 40388 15.119 0.000 20.450 0.001 spark.py:68(Scanner.tokenize) 36071 15.000 0.000 30.441 0.001 vm.py:552(VmStatsThread._getDiskStats) 757840 14.385 0.000 18.820 0.000 vm.py:2797(<genexpr>) 191058 14.361 0.005 16.236 0.000 minidom.py:305(_get_elements_by_tagName_helper) 332655 13.853 0.000 13.853 0.000 pthread.py:95(Lock.lock) 413805 13.303 0.000 15.667 0.000 inspect.py:59(isclass) 69872 12.970 0.000 12.970 0.000 libvirtmod:0(virEventRunDefaultImpl) 68582 12.760 0.000 12.760 0.000 posix:0(listdir) This bug is invalid - logging does not have significant effect on the performance.