Process.get_cpu_percent() useless calls to system-wide cpu_times()

[giampaolo]

From [email protected] on February 13, 2014 14:31:57

I wrote a script that prints in real time the top 10 processes, sorted by CPU 
usage (just like top).


# init CPU meters
for proc in psutil.process_iter():
   proc.get_cpu_percent(interval=None)

for i in range(100):
    time.sleep(1)
    for proc in psutil.process_iter():
        cpu = proc.get_cpu_percent(interval=None)
    ...



The above hogs a whopping 29% CPU. This is what cProfile says:

         2525223 function calls in 129.009 CPU seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      100  100.002    1.000  100.002    1.000 {time.sleep}
    59798    0.714    0.000   20.810    0.000 
build/bdist.linux-x86_64/egg/psutil/__init__.py:679(get_cpu_percent)
    59798    0.158    0.000   16.206    0.000 
build/bdist.linux-x86_64/egg/psutil/__init__.py:1166(cpu_times)
    59798    1.293    0.000   16.048    0.000 
build/bdist.linux-x86_64/egg/psutil/_pslinux.py:270(get_system_cpu_times)
   119596   13.827    0.000   13.827    0.000 {method 'readline' of 'file' objects}
   194235    0.487    0.000   11.195    0.000 
build/bdist.linux-x86_64/egg/psutil/_pslinux.py:460(wrapper)
    59898    0.197    0.000    4.329    0.000 
build/bdist.linux-x86_64/egg/psutil/__init__.py:1031(process_iter)
    59795    0.139    0.000    3.815    0.000 
build/bdist.linux-x86_64/egg/psutil/__init__.py:830(is_running)
    59798    0.805    0.000    3.566    0.000 
build/bdist.linux-x86_64/egg/psutil/_pslinux.py:576(get_cpu_times)
    59802    0.717    0.000    3.494    0.000 
build/bdist.linux-x86_64/egg/psutil/_pslinux.py:597(get_process_create_time)
    59798    0.091    0.000    3.359    0.000 
build/bdist.linux-x86_64/egg/psutil/__init__.py:760(get_ext_memory_info)
    59798    1.210    0.000    3.157    0.000 
build/bdist.linux-x86_64/egg/psutil/_pslinux.py:626(get_ext_memory_info)
   254133    2.902    0.000    2.902    0.000 {open}
   134433    2.726    0.000    2.726    0.000 {method 'read' of 'file' objects}
   254129    1.601    0.000    1.601    0.000 {method 'close' of 'file' objects}
   254329    0.697    0.000    0.697    0.000 {method 'split' of 'str' objects}


The problem is that every single call to get_cpu_percent() internally invokes 
sum(cpu_times()). With maybe some weird exceptions (hybernation?) that should 
be pretty much the same as calling time.time() and multiply by the number of 
CPUs - which is MUCH faster.


Same benchmark, replacing get_cpu_percent() with get_cpu_times(), I get a more 
reasonable 8% CPU usage:


         1323713 function calls in 108.063 CPU seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      100  100.000    1.000  100.000    1.000 {time.sleep}
   119751    0.328    0.000    7.363    0.000 
build/bdist.linux-x86_64/egg/psutil/_pslinux.py:460(wrapper)
    59975    0.165    0.000    4.350    0.000 
build/bdist.linux-x86_64/egg/psutil/__init__.py:1031(process_iter)
    59869    0.140    0.000    3.884    0.000 
build/bdist.linux-x86_64/egg/psutil/__init__.py:830(is_running)
    59875    0.094    0.000    3.712    0.000 
build/bdist.linux-x86_64/egg/psutil/__init__.py:743(get_cpu_times)
    59876    0.680    0.000    3.579    0.000 
build/bdist.linux-x86_64/egg/psutil/_pslinux.py:597(get_process_create_time)
    59875    0.788    0.000    3.457    0.000 
build/bdist.linux-x86_64/egg/psutil/_pslinux.py:576(get_cpu_times)
   119750    2.677    0.000    2.677    0.000 {method 'read' of 'file' objects}
   119751    1.340    0.000    1.340    0.000 {open}
   119750    0.546    0.000    0.546    0.000 {method 'close' of 'file' objects}
   119750    0.440    0.000    0.440    0.000 {method 'split' of 'str' objects}
    59875    0.297    0.000    0.297    0.000 {method 'rfind' of 'str' objects}
      100    0.000    0.000    0.235    0.002 
build/bdist.linux-x86_64/egg/psutil/__init__.py:1016(get_pid_list)
      100    0.140    0.001    0.234    0.002 
build/bdist.linux-x86_64/egg/psutil/_pslinux.py:359(get_pid_list)



I'm sure it's possible to improve even further, as top only uses 1% - not 
sure how tough.

Original issue: http://code.google.com/p/psutil/issues/detail?id=477

[giampaolo]

From g.rodola on February 13, 2014 16:24:32

> The problem is that every single call to get_cpu_percent() internally invokes 
> sum(cpu_times()). With maybe some weird exceptions (hybernation?) that should be
> pretty much the same as calling time.time() and multiply by the number of CPUs - 
> which is MUCH faster.

Mmm are you sure? The two results look very different:

>>> sum(psutil.cpu_times())
459405.7900000001
>>> time.time()
1392336739.063232
>>> 

Anyway, I agree calculating sum(cpu_times()) on every iteration, for every 
process, is sub-optimal.
I see two solutions, and I still don't know whether I like them:

1) - allow to pass system-wide CPU times as an argument as in 
"cpu_percent(self, interval=None, cputimes=None)"

2) - cache sum(cpu_times()) value in a global constant and update it every 0.1 
seconds or something


A third option might be reimplementing psutil.cpu_times() in C and avoid to 
read a file in /proc, but I'm not sure if that's even possible.

Labels: Performance

[giampaolo]

From [email protected] on February 14, 2014 03:45:12

Well, duh? Of course they're different, one is the seconds from 1970, the other 
is the seconds from the last boot. However, since you only care about 
differentials, they're perfectly interchangeable.

t1 = time.time()
t2 = sum(psutil.cpu_times())
time.sleep(10)
t1 = time.time() - t1
t2 = sum(psutil.cpu_times()) - t2
print t1 * psutil.NUM_CPUS
print t2

output:
319.998527527
319.979999989

[giampaolo]

From g.rodola on February 14, 2014 05:33:45

Mmm, interesting. So are you suggesting to replace all sum(psutil.cpu_times()) 
occurrences with time.time()?
I just tried that and that appears to produce higher CPU percentages which no 
longer reflect what's shown by top.
Maybe you want to provide a patch?

[giampaolo]

From g.rodola on February 14, 2014 05:35:17

Note: in order to observe CPU usage of the ongoing processes I simply used 
examples/top.py script.

Labels: -Type-Defect Type-Enhancement

[giampaolo]

From [email protected] on February 14, 2014 07:50:22

Did you remember to multiply time.time() * psutil.NUM_CPUS?

[giampaolo]

From g.rodola on February 14, 2014 18:15:03

You're right.
I committed this change in revision 44329a06f95e .
According to my benchmarks Process.cpu_percent() should now be about 30% faster on Linux.
This was a great catch, thanks.

Status: FixedInHG
Labels: Milestone-2.0.0

[giampaolo]

From g.rodola on March 10, 2014 04:36:50

Closing out as fixed as 2.0.0 version is finally out.

Status: Fixed