xen discuss - Apr 2008 - Opensolaris guest eats 100% cpu

Hi,

Installed svn86 under fedora8 xen on athlon 32 bit processor with 768M ram. The
cpu is shown as running at 100% constantly, even when Opensolaris is just
waiting at a shell prompt.

xentop shows 100% usage - typically 20% for dom0 and 80% for domU - have checked
prstat, vmstat and iostat in Opensolaris - no idea what is eating the cpu, but
it is reported as being usually 7%user and 93%system, nothing idle.
Doesn''t seem to be much paging activity either.

I''m mystified - any suggestions as to what I could try next?

Initially I installed svn86 under Virtualbox - it did the same thing there,
that''s why I tried xen.
 
 
This message posted from opensolaris.org

Your hardware is a reason.
 
 
This message posted from opensolaris.org

Hi Boris, thanks for your input. You mean that virtualising opensolaris on a
beige machine is not recommended? :)

Seriously though, I didn''t expect this setup to be fully featured and
blazingly fast, but all we are talking about here is a console shell prompt - no
gui, no destktop etc.

I see that the minimum ram for solaris is 384M, there''s at least 490M
available to the guest, also I see that there seem to be no warnings about
performance on 32bit x86 hardware (much as I would like to run on a 64bit box,
financial constraints apply).

So the question still stands - what is the guest kernel doing, or trying to do,
that makes it chew up the available processing power? Commands input to the
console seem to respond well, no waiting around, no listed process is using more
than a few percent cpu.

I haven''t seen this behaviour before on other guest systems that have
run on this machine.
 
 
This message posted from opensolaris.org

> Installed svn86 under fedora8 xen on athlon 32 bit
> processor with 768M ram. The cpu is shown as running
> at 100% constantly, even when Opensolaris is just
> waiting at a shell prompt. 
I guess you''ve installed opensolaris as a PV domU,
because that althon 32bit processor does not support
HVM, correct?
> xentop shows 100% usage - typically 20% for dom0 and
> 80% for domU - have checked prstat, vmstat and iostat
> in Opensolaris - no idea what is eating the cpu, but
> it is reported as being usually 7%user and 93%system,
> nothing idle. Doesn''t seem to be much paging activity
> either.
What processes were running and consuming cpu,
according to prstat? 

In the OpenSolaris domU, are all services online,
or are there services which are starting up?
check with "svcs -x" and "svcs -ap".

There are a few services that are run exactly once
during the first boot after opensolaris is installed.

E.g. they build icon and font caches for the gnome
desktop, and there is another service that builds
a PPD cache for the print subsystem.  When these
services have built their caches, they should start a
lot faster on the next boot (or they don''t run at all,
because they''ve disabled themself).


In the past I did notice that the PPD cache service
svc:/application/print/ppd-cache-update:default
seems to use a *lot* of time to build it''s cache
when I had installed opensolaris as a PV domU on
an opensuse 10.3 dom0 (both 32-bit), with opensuse
booted from an usb 2.0 hdd.

I''m including some of my notes about this problem:
_____________________________________________________________________________


Synopsis: xen performance problem, with fork/exec for losts of small processes?

=======================================================================
- amd64 dualcore 4200+, 2GB memory
- xen 3.1.?
- dom0: opensuse 10.3, 32-bit
- domU PV: opensolaris snv_81, 1GB memory
  (domU hdd uses the file backend in dom0, dom0 is installed on an USB2.0 HDD)

=======================================================================name =   
''solaris''

#kernel =      
''/media/CDROM/boot/platform/i86xpv/kernel/unix''
#ramdisk =      ''/media/CDROM/boot/x86.miniroot''
#extra =        ''/platform/i86xpv/kernel/unix -kdv - nowin -B
install_media=cdrom''

bootloader =    ''/usr/bin/pygrub''
root =          ''/dev/dsk/c0d0s0''
extra =         ''/platform/i86xpv/kernel/unix -kvd''

memory =        1024
disk =          [ ''file:/files/xen/solaris.img,0,w''
                , ''file:/files/xen/sol11-snv_81.iso,6:cdrom,r''
                ]
vif =           [ ''mac=0:8:c7:d2:82:63'' ]

on_poweroff =   ''destroy''
on_reboot =     ''restart''
on_crash =      ''restart''
=======================================================================
During the first opensolaris domU boot, the service
svc:/application/print/ppd-cache-update:default starts a command / shell script
/lib/svc/method/ppd-cache-update ==> "/usr/sbin/ppdmgr -u -R all -L
all"

This script runs for ~ 60 minutes, which seems to be quite a long time:

# svcs -ap
...
offline*       14:49:01 svc:/application/print/ppd-cache-update:default
               14:49:01      742 ppd-cache-updat
               14:49:01      743 ppdmgr
               14:49:02      751 ppdmgr
               14:49:02      761 ppdmgr
               14:49:03      770 ppdmgr
               15:40:52    21983 gzgrep
               15:40:52    21987 egrep
...


And finally:

# svcs -a
...
online         15:48:42 svc:/application/print/ppd-cache-update:default
...

dom0 "xm top" shows 100% vcpu usage by the Solaris domU.

domU "mpstat 2":

CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  0 126970   0    0   306    6   76   18    0    0    0  1138    1  99   0   0
  0 125806   1    0   310   10   86   20    0    0    0  1205    2  98   0   0
  0 126672   0    0   307    7   86   23    0    0    0  1097    1  99   0   0
  0 121938   0    0   309    9   89   22    0    0    0  1342    2  98   0   0
...

domU "lockstat -kIW -D 20 sleep 20":


filing interrupt: 2011 events in 20.738 seconds (97 events/sec)

Count indv cuml rcnt     nsec Hottest CPU+PIL        Caller                  
-------------------------------------------------------------------------------
  688  34%  34% 0.00     4075 cpu[0]                 __hypercall4            
  132   7%  41% 0.00     3693 cpu[0]                 cmntrap                 
  119   6%  47% 0.00     3554 cpu[0]                 (usermode)              
   69   3%  50% 0.00     4093 cpu[0]                 mutex_enter             
   64   3%  53% 0.00     5749 cpu[0]                 atomic_cas_64           
   54   3%  56% 0.00     3048 cpu[0]                 as_fault                
   50   2%  58% 0.00     3529 cpu[0]                 x86pte_mapout           
   49   2%  61% 0.00     3996 cpu[0]                 rw_exit                 
   43   2%  63% 0.00     2967 cpu[0]                 trap                    
   34   2%  65% 0.00     3588 cpu[0]                 mutex_exit              
   31   2%  66% 0.00     4145 cpu[0]                 as_segcompar            
   31   2%  68% 0.00     3175 cpu[0]                 segvn_fault             
   27   1%  69% 0.00     3085 cpu[0]                 dtrace_xpv_getsystime   
   26   1%  70% 0.00     3669 cpu[0]                 segvn_faultpage         
   26   1%  72% 0.00     4395 cpu[0]                 pfn_to_mfn              
   25   1%  73% 0.00     3224 cpu[0]                 xen_allow_migrate       
   24   1%  74% 0.00     4388 cpu[0]                 htable_release          
   23   1%  75% 0.00     3968 cpu[0]                 x86pte_mapin            
   23   1%  76% 0.00     3088 cpu[0]                 hati_pte_map            
   21   1%  78% 0.00     2805 cpu[0]                 x86pte_set              
-------------------------------------------------------------------------------

# lockstat -kIW -D 20 -s 8 -f __hypercall4 sleep 20

Profiling interrupt: 681 events in 20.324 seconds (34 events/sec)

-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Hottest CPU+PIL        Caller                  
  204  30%  30% 0.00     3536 cpu[0]                 __hypercall4            

      nsec ------ Time Distribution ------ count     Stack                   
      4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@     183       xen_map                 
      8192 |@@                             15        x86pte_mapin            
     16384 |                               6         x86pte_access_pagetable 
                                                     x86pte_set              
                                                     hati_pte_map            
                                                     hati_load_common        
                                                     hat_memload             
-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Hottest CPU+PIL        Caller                  
  184  27%  57% 0.00     3554 cpu[0]                 __hypercall4            

      nsec ------ Time Distribution ------ count     Stack                   
      4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@   174       x86pte_mapout           
      8192 |@                              8         x86pte_release_pagetable
     16384 |                               1         x86pte_set              
     32768 |                               0         hati_pte_map            
     65536 |                               1         hati_load_common        
                                                     hat_memload             
                                                     hat_memload_region      
-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Hottest CPU+PIL        Caller                  
  183  27%  84% 0.00     3598 cpu[0]                 __hypercall4            

      nsec ------ Time Distribution ------ count     Stack                   
      2048 |                               2         xen_flush_va            
      4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@   173       x86pte_set              
      8192 |                               6         hati_pte_map            
     16384 |                               0         hati_load_common        
     32768 |                               0         hat_memload             
     65536 |                               2         hat_memload_region      
                                                     segvn_faultpage         
-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Hottest CPU+PIL        Caller                  
   16   2%  86% 0.00     6121 cpu[0]                 __hypercall4            

      nsec ------ Time Distribution ------ count     Stack                   
      4096 |@@@@@@@                        4         xen_map                 
      8192 |@@@@@@@@@@@@@@@@               9         x86pte_mapin            
     16384 |@@@@@                          3         x86pte_access_pagetable 
                                                     htable_scan             
                                                     htable_walk             
                                                     hat_updateattr          
                                                     hat_clrattr             
-------------------------------------------------------------------------------
Count indv cuml rcnt     nsec Hottest CPU+PIL        Caller                  
   13   2%  88% 0.00     6645 cpu[0]                 __hypercall4            

      nsec ------ Time Distribution ------ count     Stack                   
      4096 |@@@@@@                         3         x86pte_mapout           
      8192 |@@@@@@@@@@@@@                  6         x86pte_release_pagetable
     16384 |@@@@@@@@@                      4         x86pte_inval            
                                                     hat_pte_unmap           
                                                     hat_unload_callback     
                                                     segvn_unmap             
                                                     as_free                 
-------------------------------------------------------------------------------
...
=======================================================================
Another script that runs extremely slow is /boot/solaris/bin/create_ramdisk

# ptime /boot/solaris/bin/create_ramdisk
updating /platform/i86pc/boot_archive
updating /platform/i86pc/amd64/boot_archive

real     7:18.626
user       16.392
sys      6:47.479

# ptime /boot/solaris/bin/create_ramdisk
updating /platform/i86pc/amd64/boot_archive
updating /platform/i86pc/boot_archive

real     7:00.954
user       16.436
sys      6:30.450

Note: CRxxxxxx improved this
===========================
# ptime /boot/solaris/bin/create_ramdisk-CRxxxxxx 
updating /platform/i86pc/boot_archive
updating /platform/i86pc/amd64/boot_archive

real     4:13.974
user       13.023
sys      3:53.885
# ptime /boot/solaris/bin/create_ramdisk-CRxxxxxx
updating /platform/i86pc/boot_archive
updating /platform/i86pc/amd64/boot_archive

real     4:09.974
user       13.031
sys      3:49.772


More improvements with this script
=================================
(instead of fork/exec a "file" command for each file, use "xargs
file")

# ptime /boot/solaris/bin/create_ramdisk-fast 
updating /platform/i86pc/boot_archive
updating /platform/i86pc/amd64/boot_archive

real     2:22.105
user       11.449
sys      2:06.694

# ptime /boot/solaris/bin/create_ramdisk-fast
updating /platform/i86pc/amd64/boot_archive
updating /platform/i86pc/boot_archive

real     2:22.034
user       11.441
sys      2:06.484

=======================================================================
Is there a xen/xVM performance problem, with fork / exec for losts of small
processes?

=======================================================================
With a xen-3.0.4 hypervisor and opensolaris dom0 it works much faster;
the svc:/application/print/ppd-cache-update:default script was done
after ~ 9 minutes.

- Pentium-M, 1.3Ghz, 2G memory
- xen 3.0.4
- dom0: nevada ~build 84
- domU PV: nevada build 81, 1GB memory, zvol hdd backend

# ptime /boot/solaris/bin/create_ramdisk-new 
updating /platform/i86pc/amd64/boot_archive
updating /platform/i86pc/boot_archive

real     2:13.151
user       26.136
sys        35.167
# ptime /boot/solaris/bin/create_ramdisk-new
updating /platform/i86pc/amd64/boot_archive
updating /platform/i86pc/boot_archive

real     1:28.931
user       25.608
sys        31.538


# ptime /boot/solaris/bin/create_ramdisk-snv81 
updating /platform/i86pc/boot_archive
updating /platform/i86pc/amd64/boot_archive

real     2:57.860
user       33.942
sys      1:38.093
# ptime /boot/solaris/bin/create_ramdisk-snv81
updating /platform/i86pc/boot_archive
updating /platform/i86pc/amd64/boot_archive

real     2:34.760
user       32.995
sys      1:34.599
 
 
This message posted from opensolaris.org

I''ll be straight . You already got a nice feed from jkeil. Some time
ago i did testing
suggested by Jurgen and there was some rush from my side :-
installs SNV85 DomU (with kmdb involvment) at Xen 3.2 Linux (CentOS5.1,Ubuntu
7.10) Dom0 (64-bit). I performed sequentially two installs with hard initial
runtimes in about 1.5 hr.
Linux Dom0s just multibooted on the same host  C2D8400, ASUS P5K Premium /WIFI, 
4GB RAM , 2x250 GB Seagate Barracuda Drives (7200 rpm, 16 MB controller cashe).
South Bridge ICH9R obviously set  in AHCI mode. 
Install at Xen 3.2 Ubuntu 7.10 Dom0 ran faster (no issues with NCQ support from
Ubuntu side).
I hardly remind CR for CentOS 5.1, reagarding SATA 2 support (NCQ in particular)
.
Even this issue on CentOS 5.1  noticably slows down Solaris DomU the very first
runtime ( jkeil wrote you about it in details).
My suggestion - stay away from AMD, regardless it''s harware is
inexpensive.
C2D6750, ASUS P5K(E) Deluxe, 4GB-8GB RAM plus SATA Drive as faster as better
would run Solaris PVMs fast enough. WD Raptors are prefferable drives in my
opinion,
Seagate Barracuda much slower (and cheaper) .
 
 
This message posted from opensolaris.org

> Even this issue on CentOS 5.1  noticably slows down
> Solaris DomU the very first runtime ( jkeil wrote you about it in details).
> My suggestion - stay away from AMD, regardless it''s harware is
inexpensive.
> C2D6750, ASUS P5K(E) Deluxe, 4GB-8GB RAM plus SATA Drive as faster as
better
> would run Solaris PVMs fast enough. WD Raptors are prefferable drives in my
opinion,
> Seagate Barracuda much slower (and cheaper) .
I''m not sure if it''s the use of the AMD cpu that could explain
the
bad performance for the /lib/svc/method/ppd-cache-update
script or the /boot/solaris/bin/create_ramdisk script that I''ve
observed.

So far there are way too many apples and oranges with the
comparisons I''ve done:

-  xen 3.1.x / amd64 X2 / opensuse 10.3 dom0 / usb 2.0 hdd / ext filesystem
   (slow)
vs.
- xvm 3.0.4 / amd64 X2 / opensolaris dom0 / 2x nv_sata HDD / striped compressed
zpool
   (fast)
vs.
- xvm 3.0.4 / Pentium M / opensolaris dom0 / notebook ata hdd / gzip compressed
zpool
   (fast)
 
 
This message posted from opensolaris.org

What exactly i am complaining is AM2 boards chip sets and bios without any
connection to Nevada Project.
When Intel makes new CPU model, it also makes, matching this CPU , (North +
South) Bridges chip sets.
 Any board''s vendor ASUS, ABIT,Gigabyte will manufacture boards built
on Intel''s Chips.
 As far as to my knowledge this practice is not regular for AMD.
 
 
This message posted from opensolaris.org

Hi Jurgen, 

Thanks for your information, you are correct in that it is a paravirtualised
guest as the processor does not support HVM. I checked the service status with
the commands suggested; there are quite a few including the ppd service - this
service is shown in prstat as using 8-9% cpu. As per your suggestion I let the
machine run... and run, then run some more. Finally (about 1/2 an hour) the cpu
load eased to what I would expect - it would seem you were right about the cache
building.

Many thanks for your reply, also the hardware information from both yourself and
Boris - I will certainly bear the recommendations in mind for future use.

So, for anyone who finds the same scenario and fears that they have unleashed a
runaway  resource monster on their hardware... Relax, and let it run for a while
:)

Thanks.
 
 
This message posted from opensolaris.org