Bug 1182670

Summary:	[performance] task._run debug logs hit the performance
Product:	Red Hat Enterprise Virtualization Manager	Reporter:	Eldad Marciano <emarcian>
Component:	vdsm	Assignee:	Nir Soffer <nsoffer>
Status:	CLOSED NOTABUG	QA Contact:	Aharon Canan <acanan>
Severity:	high	Docs Contact:
Priority:	unspecified
Version:	3.5.0	CC:	amureini, bazulay, ecohen, fromani, gklein, iheim, lpeer, lsurette, michal.skrivanek, nsoffer, yeylon
Target Milestone:	---
Target Release:	3.5.0
Hardware:	x86_64
OS:	Linux
Whiteboard:	storage
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2015-01-19 12:31:26 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	Storage	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1177634

Description Eldad Marciano 2015-01-15 16:51:30 UTC

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.

Comment 1 Michal Skrivanek 2015-01-19 07:59:24 UTC

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?

Comment 2 Nir Soffer 2015-01-19 12:31:26 UTC

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.