[Mono-bugs] [Bug 379602] New: Top of PowerTop ...

Mon Apr 14 05:10:22 EDT 2008

https://bugzilla.novell.com/show_bug.cgi?id=379602

           Summary: Top of PowerTop ...
           Product: Mono: Runtime
           Version: unspecified
          Platform: Other
        OS/Version: Other
            Status: NEW
          Severity: Critical
          Priority: P5 - None
         Component: io-layer
        AssignedTo: dick at novell.com
        ReportedBy: mmeeks at novell.com
         QAContact: mono-bugs at lists.ximian.com
          Found By: ---

It seems Mono has a 'busy' loop (perhaps only when using multiple threads ?);
every idling mono app I've ever straced has produced a huge spew of
system-calls every second: eg. my f-spot is doing this:

[pid 13448] 1208163542.885268 futex(0xb787aed8, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 13448] 1208163542.885328 clock_gettime(CLOCK_REALTIME, {1208163542,
885344852}) = 0
[pid 13448] 1208163542.885395 futex(0xb787aef4, FUTEX_WAIT_PRIVATE, 2813, {0,
99655148} <unfinished ...>
[pid 13445] 1208163542.932152 <... futex resumed> ) = -1 ETIMEDOUT (Connection
timed out)
[pid 13445] 1208163542.932198 gettimeofday({1208163542, 932215}, NULL) = 0
[pid 13445] 1208163542.932265 futex(0xb787aa34, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 13445] 1208163542.932316 clock_gettime(CLOCK_REALTIME, {1208163542,
932332528}) = 0
[pid 13445] 1208163542.932377 futex(0xb787aa50, FUTEX_WAIT_PRIVATE, 2915, {0,
99667472} <unfinished ...>
[pid 13449] 1208163542.959147 <... futex resumed> ) = -1 ETIMEDOUT (Connection
timed out)
[pid 13449] 1208163542.959192 gettimeofday({1208163542, 959209}, NULL) = 0
[pid 13449] 1208163542.959261 futex(0xb787afb0, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 13449] 1208163542.959319 clock_gettime(CLOCK_REALTIME, {1208163542,
959343223}) = 0
[pid 13449] 1208163542.959387 futex(0xb787afcc, FUTEX_WAIT_PRIVATE, 2815, {0,
99656777} <unfinished ...>
[pid 13448] 1208163542.985150 <... futex resumed> ) = -1 ETIMEDOUT (Connection
timed out)
[pid 13448] 1208163542.985206 gettimeofday({1208163542, 985223}, NULL) = 0
[pid 13448] 1208163542.985274 futex(0xb787aed8, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 13448] 1208163542.985333 clock_gettime(CLOCK_REALTIME, {1208163542,
985356375}) = 0
[pid 13448] 1208163542.985400 futex(0xb787aef4, FUTEX_WAIT_PRIVATE, 2815, {0,
99643625} <unfinished ...>
[pid 13445] 1208163543.032161 <... futex resumed> ) = -1 ETIMEDOUT (Connection
timed out)
[pid 13445] 1208163543.032216 gettimeofday({1208163543, 32233}, NULL) = 0
[pid 13445] 1208163543.032290 futex(0xb787aa34, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 13445] 1208163543.032361 clock_gettime(CLOCK_REALTIME, {1208163543,
32377854}) = 0
[pid 13445] 1208163543.032428 futex(0xb787aa50, FUTEX_WAIT_PRIVATE, 2917, {0,
99622146} <unfinished ...>
[pid 13449] 1208163543.059143 <... futex resumed> ) = -1 ETIMEDOUT (Connection
timed out)
[pid 13449] 1208163543.059198 gettimeofday({1208163543, 59215}, NULL) = 0
[pid 13449] 1208163543.059263 futex(0xb787afb0, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 13449] 1208163543.059323 clock_gettime(CLOCK_REALTIME, {1208163543,
59346296}) = 0
[pid 13449] 1208163543.059393 futex(0xb787afcc, FUTEX_WAIT_PRIVATE, 2817, {0,
99653704} <unfinished ...>
[pid 13448] 1208163543.085135 <... futex resumed> ) = -1 ETIMEDOUT (Connection
timed out)
[pid 13448] 1208163543.085188 gettimeofday({1208163543, 85205}, NULL) = 0
[pid 13448] 1208163543.085253 futex(0xb787aed8, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 13448] 1208163543.085312 clock_gettime(CLOCK_REALTIME, {1208163543,
85335702}) = 0
[pid 13448] 1208163543.085380 futex(0xb787aef4, FUTEX_WAIT_PRIVATE, 2817, {0,
99664298} <unfinished ...>
[pid 13445] 1208163543.132154 <... futex resumed> ) = -1 ETIMEDOUT (Connection
timed out)
[pid 13445] 1208163543.132200 gettimeofday({1208163543, 132217}, NULL) = 0
[pid 13445] 1208163543.132272 futex(0xb787aa34, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 13445] 1208163543.132332 clock_gettime(CLOCK_REALTIME, {1208163543,
132349359}) = 0
[pid 13445] 1208163543.132400 futex(0xb787aa50, FUTEX_WAIT_PRIVATE, 2919, {0,
99650641} <unfinished ...>
[pid 13449] 1208163543.159142 <... futex resumed> ) = -1 ETIMEDOUT (Connection
timed out)
[pid 13449] 1208163543.159182 gettimeofday({1208163543, 159198}, NULL) = 0
[pid 13449] 1208163543.159244 futex(0xb787afb0, FUTEX_WAKE_PRIVATE, 1) = 0

This unfortunately makes Mono look bad when power consumption is being measured
- the "Green IT" people get unhappy, and - well - it sucks :-) Surely there is
no good excuse for a busy loop ? surely we don't have polling hardware we need
to be watching ? Presumably having 'timeouts' sucks wrt. hiding performance &
latency problems that would otherwise be obvious ?

PowerTop reports:

Top causes for wakeups:
  25.5% ( 30.0)            f-spot : futex_wait (hrtimer_wakeup) 
   8.7% ( 10.3)       <interrupt> : extra timer interrupt 
   8.1% (  9.5)   USB device  3-2 : AX88772  (ASIX Elec. Corp.)
   6.9% (  8.1)                 X : do_setitimer (it_real_fn)
   6.8% (  7.9)       <interrupt> : ehci_hcd:usb3, uhci_hcd:usb5

ie. 30 wakeups / second on an idling machine - which keeps the CPU out of it's
lowest power mode for a great swathe of time. Of course, as you run more mono
applications it gets rather worse:

Wakeups-from-idle per second : 127.6    interval: 15.0s
no ACPI power usage estimate available

Top causes for wakeups:
  17.5% ( 30.1)       <interrupt> : extra timer interrupt 
  17.4% ( 30.0)            f-spot : futex_wait (hrtimer_wakeup) 
  11.6% ( 20.0)           banshee : futex_wait (hrtimer_wakeup) 
  11.6% ( 20.0)           beagled : futex_wait (hrtimer_wakeup) 
..

It'd be nice not to see mono apps at the top of the list :-)

[ the numbers are from SL11.0 ... ]

-- 
Configure bugmail: https://bugzilla.novell.com/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.