Alto consumo de %SYS

Page last edited hace 2208 días 8 horas
De Solaris-ES
Saltar a: navegación, buscar

Problemática[editar]

Se detecta un alto consumo de CPU, y el %SYS >= %USR.
root@quebec # sar 1 10
SunOS quebec 5.10 Generic_144488-17 sun4u    02/17/2012

14:38:48    %usr    %sys    %wio   %idle
14:38:49      10      26       0      64
14:38:50      12      29       0      60
14:38:51      31      52       0      18
14:38:53      32      37       0      31
14:38:54      20      29       0      51
14:38:55      22      42       0      36
14:38:57      22      32       0      46
14:38:58      18      41       0      40
14:38:59      18      63       0      18
14:39:00      11      18       0      71
Dado esto abrimos una incidencia en Oracle y nos informan que el problema puede estar generado por la re-colocación de las
paginas de memoria que Solaris realiza automáticamente.

Dado esto nos sugieren que modifiquemos el parametro de Kernel "pg_contig_disable". Con esta informacion buscamos en 
Google y encontramos la siguiente nota de SAP 724713

pg_contig_disable=0[editar]

Significa que el sistema, en el momento de la asignación de memoria "reordena" la memoria interna para encontrar una cantidad 
de memoria contigua. Dependiendo del tamaño de la memoria que tiene la máquina y la cantidad de fragmentación debido al gran 
numero de procesos esto puede tardar algún tiempo y generar algo consumo del %SYS.


Segun SAP[editar]

Please do not use any old /etc/system settings from SAP note 395438 with Solaris 10.

It is no longer required to set parameter rlim_fd_cur in /etc/system, as mentioned in previous versions of this SAP note.
Resource control process.max-file-descriptor can be used to set the soft limit for the maximum number of open files per process.

The "Large Page Out Of the Box" (LPOOB) feature of the Solaris 10 memory management, first implemented in  Solaris 10 1/06
(Update 1), can lead to performance problems when the system runs out of large chunks of free contiguous memory. 
This is because the Solaris 10 kernel by default will attempt to relocate memory pages to free up space for creating larger
blocks of contiguous memory. Known symptoms are high %system CPU time in vmstat, high number of cross calls in mpstat, and 
Oracle calling mmap(2) to /dev/zero for getting more memory.

Memory page relocation for satisfying large page allocation requests can be disabled by setting the following Solaris kernel
parameter in /etc/system:

set pg_contig_disable=1

This will not switch off the LPOOB feature. Large memory pages will still be used when enough free space of contiguous memory
is available, so the benefits of this feature will remain.

Other sources (e.g. SAP notes) may recommend further /etc/system parameters for Solaris 10 in certain cases.


Verificación[editar]

Luego de leer la nota, podemos observar que tanto el %SYS en el vmstat como las Cross-call del mpstat estan elevadas, no pudimos
comprobar las llamas a mmap porque la vida de los procesos es muy corta como para analizarla.
Ej:
root@quebec # sar 1 10
SunOS quebec 5.10 Generic_144488-17 sun4u    02/17/2012

14:38:48    %usr    %sys    %wio   %idle
14:38:49      10      26       0      64
14:38:50      12      29       0      60
14:38:51      31      52       0      18
14:38:53      32      37       0      31
14:38:54      20      29       0      51
14:38:55      22      42       0      36
14:38:57      22      32       0      46
14:38:58      18      41       0      40
14:38:59      18      63       0      18
14:39:00      11      18       0      71
root@quebec # mpstat 1 3
CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  0  310  27 1549   547   23  714   13   83  230    3  2759   12  18   0  70
  1  282  31 2137   927  588  781   16   88  260    3  3150   13  20   0  67
  2  330  33 1750   393   25  782   14   91  251    4  3190   13  19   0  68
  3  247  27 1569   366   26  714   13   84  228    3  2844   12  17   0  71
  4  265  27 1720   768  420  702   13   83  220    3  2511   10  18   0  72
  5  276  31 1867  1215  875  731   13   77  281    3  3117   12  22   0  65
  6  332  33 1758   395   25  789   14   92  251    3  3227   13  19   0  68
  7  242  27 1604   369   25  723   13   84  229    3  2844   12  17   0  71
  8  340  28 1421   287   23  583   12   74  241    3  2600   10  18   0  72
  9  312  35 1759   338   24  711   13   82  268    4  3115   12  19   0  68
 10  348  36 1776   484  154  706   14   85  270    4  2687   10  20   0  70
 11  263  28 1496   345   74  592   12   74  240    3  2468   10  17   0  72
 12  283  27 1483   735  485  554   11   66  263    3  2453   10  20   0  70
 13  304  34 1738   495  199  674   12   79  275    3  3052   12  20   0  68
 14  349  35 1669   358   52  683   13   82  266    4  2996   12  20   0  69
 15  256  27 1877   836  587  613   15   73  253    3  2630   11  19   0  70
CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  0  431  13 1785   405   17  376   45  146 1234    1  2231   10  85   0   5
  1   76  22 2128   689  558  308   44  119  604    0 24920   44  53   0   3
  2  398  30 1268   235   14  477   53  181  718    0  6061   41  54   0   5
  3  104  45 1939   219   14  445   46  175 1061    0  5216   30  66   0   4
  4  256  24 2892  1230  929  400   33  153  890    0  1533   16  76   0   8
  5  591  49 6584   278   42  437   60  164  809    0  2729   20  72   0   8
  6   85  24 2116   211   16  355   44  122  404    3 26436   65  29   0   6
  7  466  64 3900   469   28  891  143  283 1144    1  5727   24  65   0  11
  8  699  62 3289   324   24  609   65  224 1036    0  2521   13  75   0  13
  9  453  64 7301   330   32  564  118  196 1402    0 11418   23  68   0   9
 10  251  46 1461   467  167  548   64  179  857    1 11160   25  63   0  12
 11  153  15 1612   278  124  230   42   93  404    2  4121   60  36   0   4
 12  472  72 4611   332   29  599   94  206  767    0  2452   20  70   0  10
 13  317  31  911   235   24  376   45  140  632    0 21538   38  58   0   4
 14  670  30 5141   224   45  356   47  138  736    1  5493   36  59   0   5
 15  315  44 4006   734  567  388   55  141  950    0  1483   14  80   0   6
CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  0  171  34  356   497   28  509    7  122  130    0  3212   12  14   0  74
  1    0   3 2466   436  406   32    8    8  338    0 46829   75  22   0   3
  2  250  18 1839   232   22  350    5   70  505    0  1927   12  41   0  48
  3  117  40 2450   341   49  492    9   94  512    0   835    4  39   0  57
  4  201  25 3574  2444 2249  234   12   49  551    0  1767   25  58   0  17
  5  473  13 1871   238   35  319    8   65  714    0  1619    9  56   0  35
  6    0  21 3818   231   26  350    6   73  321    0  3329   22  37   0  41
  7  801  18 1075   226   23  323   13   85  336    0 12929   31  37   0  33
  8  511  26 5769   244    8  441    7   72  274    8  4309   11  29   0  60
  9   69  25  525   114   15  139    9   35   79    0  8826   41  50   0  10
 10    0  58  224   375  101  439   11   83  348    0  5378   24  47   0  29
 11  268  20  305   346  104  404    7   89  265    0 24816   26  19   0  55
 12  660  12  851   182   21  251    6   55  559    1  1645    7  43   0  50
 13  157  36 1102   216   20  324    8   69  406    0 22538   33  31   0  37
 14  314  14  153   212   19  302   14   58  236    0 13807   22  51   0  27
 15   78  37  400   626  417  430    7   95  218    0  4553   18  22   0  60


Quienes pueden propiciar este comportamiento[editar]

Contención al reordenar la paginas de memoria pg_contig[editar]

Con DTrace podemos ver que procesos utilizan el recurso de pg_contig continuamente
La muestra es de: 46m
root@quebec # time dtrace -qn 'fbt::page_geti_contig_pages:entry{@[execname]=count();}'
^C

  DashboardAgent                             2
  java                                       4
  emdctl                                     5
  dtrace                                    36
  vxsvc                                    652
  nmcbufp                                 1008
  sqlplus                                 1247
  tnsping                                 1346
  rman                                    1618
  emagent                                 2421
  lsnrctl                                 2426
  perl                                    8802
  oracle                                 59647
  tnslsnr                                59850

Nota: En esta muestra podemos ver que el proceso "tnslsnr" es el que mas llamadas genera.
La muestra es de: 4m
root@quebec # time dtrace -qn 'fbt::page_geti_contig_pages:entry{@[execname,curpsinfo->pr_psargs]=count();}'
^C
  dtrace               dtrace -qn fbt::page_geti_contig_pages:entry{@[execname,curpsinfo->pr_psargs]=c                1
  nmcbufp              ./nmcbufp (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=zzzzzz-prd)(Port=1521))(CON                1
  perl                 /oracle/gc/gc102/agent10g/perl/bin/perl /oracle/gc/gc102/agent10g/bin/emctl.pl                 1
  tnslsnr              /oracle/pkg15/soft/bd/bd112/bin/tnslsnr LISTENER_MSTTVP -inherit                               1
  tnsping              /oracle/pkg15/soft/bd/bd112/bin/tnsping (ADDRESS=(PROTOCOL=TCP)(HOST=xxxxxx-prd                1
  tnsping              /oracle/pkg22/soft/bd/bd102/bin/tnsping (ADDRESS=(PROTOCOL=TCP)(HOST=pppppp-prd                2
  perl                 /oracle/gc/gc102/agent10g/perl/bin/perl /oracle/gc/gc102/agent10g/bin/emwd.pl a                3
  java                 /oracle/gc/gc102/agent10g/jdk/bin/java -DORACLE_HOME=/oracle/gc/gc102/agent10g                 4
  emagent              /oracle/pkg14/soft/gc/gc102/agent10g/bin/emagent                                               5
  emagent              /oracle/gc/gc102/agent10g/bin/emagent                                                          8
  perl                 /oracle/pkg19/soft/gc/gc102/agent10g/perl/bin/perl /oracle/pkg19/soft/gc/gc102/                9
  emagent              /oracle/pkg15/soft/gc/gc102/agent10g/bin/emagent                                              10
  emagent              /oracle/pkg22/soft/gc/gc102/agent10g/bin/emagent                                              10
  perl                 /oracle/pkg22/soft/gc/gc102/agent10g/perl/bin/perl /oracle/pkg22/soft/gc/gc102/               12
  perl                 /oracle/gc/gc102/agent10g/perl/bin/perl /oracle/gc/gc102/agent10g/sysman/admin/               14
  perl                 /oracle/pkg14/soft/gc/gc102/agent10g/perl/bin/perl /oracle/pkg14/soft/gc/gc102/               17
  perl                 /oracle/pkg15/soft/gc/gc102/agent10g/perl/bin/perl /oracle/pkg15/soft/gc/gc102/               26
  vxsvc                /opt/VRTSob/bin/vxsvc -m                                                                      44
  emagent              /oracle/pkg19/soft/gc/gc102/agent10g/bin/emagent                                              80
  oracle               oracleORADWH (LOCAL=NO)                                                                     1394
  tnslsnr              /oracle/pkg22/soft/bd/bd102/bin/tnslsnr LISTENER_XXXXXX -inherit                            3028

Nota: En una muestra mas pequeña podemos ver que el proceso "tnslsnr" esta asociado al LISTENER_XXXXXX. 
Dado esto se solicita que se analice el pool de conexiones ya que no las esta gestionando correctamente.


Contención a nivel de Filesystem (fragmentación de la memoria)[editar]

Se ve contención a nivel de UFS durante las escrituras al filesystem.

En algunos casos los threads esperan bastante tiempo (100ms) para asegurar el loqueo, esto ocurre cuando múltiples
procesos intentan escribir en el mismo archivo concurrentemente. Direct IO remueve esta limitación y reduce la contención
por el loqueo.
Nota: Mas información ver el documento 1005087.1 "Pros and Cons of Using Direct I/O for Databases".
Con el comando vmstat -p podemos ver si la cache del filesystem esta trabajando.
# vmstat -p 1
    memory           page          executable      anonymous      filesystem 
  swap  free  re  mf  fr  de  sr  epi  epo  epf  api  apo  apf  fpi  fpo  fpf
42422208 13076936 6733 4692 65 0 0 1269  0    0   16    0    0 38131  68   65
30910320 5456784 1513 6802 157 0 0  0    0    0    0    0    0  205  165  157
30925080 5466720 1766 8247 135 0 0  0    0    0    0    0    0    0  135  135
30919384 5461480 1596 10735 254 0 0 0    0    0  539    0    0  135  262  254
30909672 5457568 1498 8164 237 0 0  0    0    0 1552    0    0 1164  253  237
30912432 5460824 3886 8482 222 0 0  0    0    0    0    0    0 12284 238  222
En un equipo que no cachea vía UFS podemos ver una estadística como la siguiente:
# vmstat -p 1
    memory           page          executable      anonymous      filesystem 
  swap  free  re  mf  fr  de  sr  epi  epo  epf  api  apo  apf  fpi  fpo  fpf
76425032 10226744 535 899 26 0 14 187    0    0    4    7    7 1472   19   19
75134112 9139176 310 861 0 0   0    0    0    0    0    0    0    0    0    0
75133776 9139144 0 18  0   0   0    0    0    0    0    0    0    0    0    0
75133776 9139144 0 0   0   0   0    0    0    0    0    0    0    0    0    0
75133776 9139144 4 565 0   0   0    0    0    0    0    0    0    0    0    0
75134160 9139576 0 4   0   0   0    0    0    0    0    0    0    0    0    0
Realizamos un trace para ver que FS están siendo accedidos en el momento de la contención de lock.

Si los FS son de la base de datos de Oracle, podemos habilitar el DirectIO, desde el /etc/vfstab o desde la propia base de
datos utilizando la opción "_filesystemio_options"

El script nos muestra el punto de montaje del filesystem, el tipo de lock (lectura / escritura), el proceso y la cantidad en
el periodo de tiempo.

dtrace -qn 'fbt:ufs:ufs_rwlock:entry
{
   this->vnode = (vnode_t *)arg0; 
   this->vfs = (vfs_t *)this->vnode->v_vfsp; 
   this->mntpt = (uintptr_t)this->vfs == 0 ? 0 : (refstr_t *)this->vfs->vfs_mntpt; 
   self->mountstr = (uintptr_t)this->mntpt == 0 ? "-" : stringof(this->mntpt->rs_string); 
   @fs[self->mountstr,arg1 == 0 ? "R" : "W",curpsinfo->pr_psargs] = count();
}
END
{
   printa("%-35s %-3s %-82s %@8d\n",@fs);
}'

WorkArround[editar]

WorkArround: Contención al reordenar la paginas de memoria pg_contig[editar]

Para solventar este problema podemos deshabilitar el parametro en el kernel en caliente y vemos como se comporta el sistema. 
Este cambio no es disruptivo.
En Caliente 
   echo "pg_contig_disable/W 1" | mdb -kw
Fijo 
   Agregar en el /etc/system set pg_contig_disable=1 y luego reiniciar.
Nota: Este parámetro le dice al sistema que no intente re-colocar la memoria y que la utilice tal cual como esta
      (de forma no continua).


WorkArround: Contención a nivel de Filesystem (fragmentación de la memoria)[editar]

Temporal:
# mount -o remount,forcedirectio /oracle/pkg57/oraxxxx/redo1
# mount -o remount,noforcedirectio /oracle/pkg57/oraxxxx/redo1
Permanente: /etc/vfstab
/dev/vx/dsk/oraxxxx/redo1     /dev/vx/rdsk/oraxxxx/redo1    /oracle/pkg57/oraxxxx/redo1     ufs 2 no logging,forcedirectio