Solaris: Problema de lentitud en Solaris 10

Normalmente no suelo contar demasiado sobre el día a día de mi trabajo, pero a veces ocurren cosas curiosas que creo que son interesantes contarlas, sobre todo, por si pueden ser de ayuda para otros que se encuentren con el mismo problema, o por lo menos parecido. La semana pasada unos compañeros del departamento, no voy a citar sus nombres para respetar su anonimato, a los que llamaremos Miguel y Rafa, me comentaron que tenían problemas al copiar un fichero de una máquina con Solaris 9 a otra con Solaris 10, esta última, la acababamos de instalar unas semanas antes y estabamos terminando de configurarla.

Lo extraño del caso es que ellos estaban realizando un simple <b>scp</b> desde la máquina con Solaris 9 hacia la nueva máquinas con Solaris 10. La transferencia era auténticamente ridícula, solo se conseguían un ratio de 47KB/s, el fichero en cuestión tenía un tamaño de 32GB. Una velocidad de transferencia tan baja es justificación suficiente para echar un ojo a las máquinas, ya que claramente hay un problema de rendimiento. Descartamos que el problema tuviera su origen en la máquina con Solaris 9, ya que esta máquina lleva 4 años funcionando en producción y nunca ha dado un problema (es cierto que este podría ser el primero, pero decidimos centrarnos en estudiar la máquina con Solaris 10).

Lo primero que me llamó la atención fue el porcentaje de sys frente al porcentaje de usr de la salida del comando vmstat.

root@host01 # vmstat 1
 kthr      memory            page            disk          faults      cpu
 r b w   swap  free  re  mf pi po fr de sr s0 s1 s4 s5   in   sy   cs us sy id
 0 0 0 46271944 37647960 1474 2580 6262 2 2 0 8 4 4 1 1 6969 25018 10575 4 2 94
 0 0 0 45262992 34876136 113 164 0 0 0 0 0  0  0  0  0  451 2197  291  0  6 93
 0 0 0 45262696 34876744 2 28 0 0  0  0  0  0  0  0  0  440  754  293  0  5 95
 0 0 0 45262656 34876648 0 14 0 0  0  0  0  0  0  0  0  496  851  313  0  6 94
 0 0 0 45262656 34876576 1 21 0 0  0  0  0  0  0  0  0  490 1289  310  0  7 93
 0 0 0 45262576 34876528 2 13 0 0  0  0  0  0  0  0  0  464  769  281  0  6 94
 1 0 0 45262576 34876496 2 6 0  0  0  0  0  0  0  0  0  426 1071  309  0  3 96
 2 0 0 45262552 34876464 22 255 0 7 7 0  0  0  0  0  0  508 1369  376  0  6 94
 2 0 0 45262152 34876128 2 26 0 0  0  0  0  0  0  0  0  515  754  381  0  7 93
 2 0 0 45262136 34876088 0 9 0  0  0  0  0  1  1  0  0  613 1259  332  0  9 90
 2 0 0 45261160 34876064 19 151 0 7 7 0  0  0  0  0  0  566 1333  366  0  8 92
 2 0 0 45260352 34875912 149 440 0 0 0 0 0  0  0  0  0  503 1287  309  0  8 92
 2 0 0 45259640 34874736 3 97 0 0  0  0  0  0  0  0  0  474 1588  384  0  4 95
 2 0 0 45261976 34875752 27 172 0 0 0 0  0  0  0  0  0  494  703  308  0  6 94

No es muy normal que sys sea mayor que usr y sobre todo cuando el porcentaje de usr es mas o menos 0. Había que averiguar por qué se estaba empleando tanto tiempo de sys. A mi personalmente me gusta utilizar mdb, pero primero suelo utilizar el comando mpstat para ver la distribución de carga entre los distintos procesadores.

root@host01 # mpstat 1
CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  0    0   0  251   239  135   57    0    8    4    0    13    0   2   0  98
  1    0   0   16    42   11   61    0    1    6    0     0    0   1   0  99
  2    0   0    4     3    2    0    0    0    1    0     0    0 100   0   0
  3    0   0   25     7    2    9    0    0    1    0     0    0   0   0 100
 56    0   0   13    40   22   31    0    2    1    0    14    0   1   0  99
 57    0   0    0     2    0    4    0    3    5    0     0    0   0   0 100
 58    0   0    0     4    0    6    0    1    1    0     4    0   0   0 100
 59    0   0    0     3    0    6    0    2    5    0     1    0   0   0 100
 80   25   0    1     5    0    4    1    1    5    0   673    0   0   0 100
 81    0   0    0     2    0    2    0    0    1    0     0    0   0   0 100
 82    0   0    0    16    0   32    0    3    4    0   167    0   0   0 100
 83    0   0    0     2    0    2    0    1    1    0     0    0   1   0  99
120    0   0    2    14    0   32    0    5   10    0    98    0   0   0 100
121    0   0    0     2    0    2    0    1    3    0     0    0   0   0 100
122    0   0    0     4    0   11    0    5    7    0     7    0   0   0 100
123    0   0    0     2    0    6    0    3    7    0     0    0   0   0 100
136    0   0    0     4    0    8    0    3    4    0     5    0   1   0  99
137    0   0    0     2    0    2    0    1    7    0     0    0   0   0 100
138    0   0    0     4    0    8    0    3   10    0    25    0   1   0  99
139    0   0    4     6    4    6    0    3    6    0     0    0   0   0 100
176    0   0    0     7    0   17    0    8   10    0    35    0   0   0 100
177    0   0    0     2    0    4    0    2    5    0     0    0   1   0  99
178    0   0    0     2    0    2    0    1    2    0     0    0   0   0 100
179    0   0    0     3    0    6    0    3    9    0     0    0   0   0 100
200    1   0    0    53    0    2    0    0    1    0     0    0  50   0  50
201    0   0    0     2    0    2    0    1    2    0     0    0   0   0 100
202    0   0    2    12    0   24    0    1    7    0    27    0   2   0  98
203    0   0    0     2    0    2    0    1    2    0     0    0   0   0 100
224    1   0    0    42    6    2    0    0    1    0     2    0  51   0  49
225    0   0    0     2    0    5    0    4    7    0     0    0   0   0 100
226    1   0    0    54    2    2    0    0    1    0     0    0  50   0  50
227    1   0    0    53    0    4    0    0    1    0     0    0  50   0  50
CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  0    0   0  136   240  138   69    0    8    2    0    13    0   3   0  97
  1    0   0   62    29    0   57    0    5    4    0     0    0   1   0  99
  2    0   0    4     3    2    0    0    0    1    0     0    0 100   0   0
  3    0   0   29     8    2   11    0    3    1    0     1    0   1   0  99
 56    0   0   22    53   32   36    0    4    9    0    16    0   0   0 100
 57    0   0    0     2    0    2    0    1    1    0     0    0   0   0 100
 58    0   0    0     4    1   10    0    7    9    0     1    0   0   0 100
 59    0   0    0     2    0    2    0    0    1    0     0    0   0   0 100
 80    0   0    1     4    0    6    0    2    1    0   670    1   0   0  99
 81    0   0    0     2    0    2    0    1    1    0     0    0   0   0 100
 82    0   0    0    25    0   48    0    1    3    0   280    0   0   0 100
 83    0   0    0     2    0    8    0    6    8    0     0    0   0   0 100
120    0   0    0     2    0    5    0    3    7    0     0    0   0   0 100
121    0   0    0     2    0    4    0    3    3    0     0    0   0   0 100
122    0   0    0     8    0   14    0    1    3    0    14    0   1   0  99
123    0   0    0     2    0    2    0    1    1    0     0    0   1   0  99
136    0   0    2     5    0    8    0    2    3    0    10    0   0   0 100
137    0   0    0     2    0    4    0    3    8    0     0    0   0   0 100
138    0   0    0     3    0    4    0    1    2    0    45    1   0   0  99
139    0   0    4     6    4    2    0    1    2    0     0    0   0   0 100
176    0   0    0     8    0   15    0    3    5    0    52    1   1   0  98
177    0   0    0     2    0    9    0    7   13    0     0    0   0   0 100
178    0   0    0     2    0    2    0    1    2    0     0    0   0   0 100
179    0   0    0     2    0    7    0    5   11    0     0    0   0   0 100
200    2   0    0    20    0    2    1    0    2    0     0    0  36   0  64
201    0   0    0     2    0    2    0    1    4    0     0    0   0   0 100
202    0   0    0     6    0   16    0    5   17    0    19    0   1   0  99
203    0   0    0     2    0    2    0    1    3    0     0    0   0   0 100
224    5   0    0    27    4    4    1    1    2    0    11    0  36   0  64
225    0   0    0     3    1    3    0    2    8    0     0    0   0   0 100
226    5   0    0    23    3    2    1    0    2    0     0    0  37   0  63
227    2   0    0    21    0    4    1    0    2    0     0    0  36   0  64

Curioso que la CPU 2 esté utilizando el 100% de su tiempo en sys, aquí tenemos la causa que hacía subir el porcentaje de sys del comando vmstat.Con mdb podemos ver qué procesos están corriendo en las distintas CPUs.


root@host01 # mdb -k
Loading modules: [ unix krtld genunix specfs dtrace ufs sd mpt px ssd fcp fctl e
mlxs ip hook neti sctp arp usba nca ipc random cpc crypto ptm sppp nfs ]
> ::cpuinfo
 ID ADDR        FLG NRUN BSPL PRI RNRN KRNRN SWITCH THREAD      PROC
  0 0000180c000  1b    0    0  -1   no    no t-0    2a10001fca0 (idle)
  1 3000bf72000  1b    0    0  -1   no    no t-2    2a100e93ca0 (idle)
  2 3000bf76000  1b    1    0  60   no    no t-260  2a102255ca0 sched
  3 3000bf7c000  1b    0    0  -1   no    no t-3    2a10102fca0 (idle)
 56 3000bfc2000  1b    0    0  -1   no    no t-6    2a1010b7ca0 (idle)
 57 3000bfc6000  1b    0    0  -1   no    no t-41   2a1010ffca0 (idle)
 58 3000bfce000  1b    0    0  -1   no    no t-26   2a101187ca0 (idle)
 59 3000bfd2000  1b    0    0  -1   no    no t-41   2a10120fca0 (idle)
 80 3000bfd6000  1b    0    0  -1   no    no t-2    2a101297ca0 (idle)
 81 3000c016000  1b    0    0  59   no    no t-0    30019823c20 sshd
 82 3000c01a000  1b    0    0  59   no    no t-0    300195238a0 mdb
 83 3000c01e000  1b    0    0  -1   no    no t-36   2a1013efca0 (idle)
120 3000c026000  1b    0    0  -1   no    no t-41   2a101477ca0 (idle)
121 3000c02a000  1b    0    0  -1   no    no t-41   2a1014bfca0 (idle)
122 3000c02e000  1b    0    0  -1   no    no t-32   2a101547ca0 (idle)
123 3000c034000  1b    0    0  -1   no    no t-42   2a1015cfca0 (idle)
136 3000c038000  1b    0    0   0  yes    no t-31   30019844800 oracle
137 3000c07c000  1b    0    0  -1   no    no t-42   2a10169fca0 (idle)
138 3000c080000  1b    0    0  -1   no    no t-42   2a101727ca0 (idle)
139 3000c086000  1b    0    0  -1   no    no t-42   2a1017afca0 (idle)
176 3000bfda000  1b    0    0  -1   no    no t-42   2a10186fca0 (idle)
177 3000bfe0000  1b    0    0  -1   no    no t-42   2a1018b7ca0 (idle)
178 3000bfe4000  1b    0    0  -1   no    no t-42   2a10193fca0 (idle)
179 3000bfea000  1b    0    0  -1   no    no t-61   2a1019c7ca0 (idle)
200 3000c002000  1b    0    0  -1   no    no t-2    2a101a4fca0 (idle)
201 3000c00e000  1b    0    0  -1   no    no t-3    2a101aa5ca0 (idle)
202 3000c012000  1b    0    0  -1   no    no t-3    2a101babca0 (idle)
203 3000c08a000  1b    0    0  -1   no    no t-61   2a101c33ca0 (idle)
224 3000c08e000  1b    0    0   0   no    no t-32   3000c3feee0 oracle
225 3000c094000  1b    0    0  -1   no    no t-3    2a101d03ca0 (idle)
226 3000c146000  1b    0    0  -1   no    no t-3    2a101d8bca0 (idle)
227 3000c14a000  1b    0    0   0  yes    no t-24   3000c3e9540 oracle
>

De la penúltima columan THREAD podemos obtener la direncción donde se almacena al estructura de datos de tipo kthread_t que define al thread que está corriendo en esa CPU, a nosotros nos interesaba la dirección 0x2a10041fca0, con el comando ::findstack podemos ver el contenido del stack del thread.

> 2a102255ca0::findstack
stack pointer for thread 2a102255ca0: 2a102254bd1
  000002a102254ca1 indirtrunc+0x33c()
  000002a102254d71 ufs_itrunc+0x690()
  000002a102255001 ufs_trans_itrunc+0x180()
  000002a1022550e1 ufs_delete+0x3a0()
  000002a1022551c1 ufs_thread_delete+0xdc()
  000002a102255291 thread_start+4()
>
> 2a102255ca0::findstack
stack pointer for thread 2a102255ca0: 2a102254bd1
  000002a102254ca1 indirtrunc+0x33c()
  000002a102254d71 ufs_itrunc+0x690()
  000002a102255001 ufs_trans_itrunc+0x180()
  000002a1022550e1 ufs_delete+0x3a0()
  000002a1022551c1 ufs_thread_delete+0xdc()
  000002a102255291 thread_start+4()
>
> 2a102255ca0::findstack
stack pointer for thread 2a102255ca0: 2a102254bd1
  000002a102254ca1 indirtrunc+0x33c()
  000002a102254d71 ufs_itrunc+0x690()
  000002a102255001 ufs_trans_itrunc+0x180()
  000002a1022550e1 ufs_delete+0x3a0()
  000002a1022551c1 ufs_thread_delete+0xdc()
  000002a102255291 thread_start+4()
>

Lo que obtenemos de la salida del comando ::findstack nos da una pista de qué está haciendo el thread, en este caso está ejecutando funciones referentes al sistema de ficheros UFS y en concreto, se está intentando borrar un fichero, ya que se llama a la función ufs_delete que se encarga de borrar los inodos asignados a un fichero, dentro de ufs_delete se llama a la función ufs_trans_itrunc y en ésta se llama a la función ufs_itrunc encargada de truncar el inodo, borrando los bloques del fichero desde el final al principio.

En este punto, ya conocemos porqué la máquina está dando unos tiempos de respuesta tan bajos, el Kernel está ocupando mucho de su tiempo en truncar un fichero, lo que provoca que el sistema se resienta bastante, de hecho trabajar en la máquina se hace casi imposible, los comandos responden de una forma totalmente aleatoria y la máquina no presenta carga ninguna.

El siguiente paso es conocer qué está intentando borrar el kernel, para ellos contrsuimos un pequeño script de DTRACE que nos ayude a conocer la causa del problema de lentitud.

fbt::ufs_thread_delete:entry
/ pid == $1 /
{ printf("n %s entry:",probefunc); }

fbt::ufs_delete:entry
/ pid == $1 /
{ printf("n %s     t entry: inode %d t dev %d t %s",probefunc,args[1]->i_number,args[1]->i_dev,stringof(args[1]->i_vnode->v_path)); }

fbt::ufs_trans_itrunc:entry
/ pid == $1 /
{ printf("n %s t entry: inode %d t dev %d t %s",probefunc,args[0]->i_number,args[0]->i_dev,stringof(args[0]->i_vnode->v_path)); }

fbt::ufs_itrunc:entry
/ pid == $1 /
{ printf("n %s     t entry: inode %d t dev %d t offset %d t %s",probefunc,args[0]->i_number,args[0]->i_dev,args[1],stringof(args[0]->i_vnode->v_path));
time=timestamp;
}

fbt::ufs_delete:return
/ pid == $1 /
{ printf("n %s     t return: %d",probefunc,args[0]); }

fbt::ufs_trans_itrunc:return
/ pid == $1 /
{ printf("n %s t return: %d",probefunc,args[0]); }

fbt::ufs_itrunc:return
/ pid == $1 /
{ printf("n %s     t return: %d    time: %d s",probefunc,args[0],(timestamp-time)/100000000); }

Solo nos interesa ver las funciones ufs_delete, ufs_trans_itrunc y ufs_itrunc.

La función ufs_delete tiene los siguientes parámetros:

void ufs_delete(struct ufsvfs *ufsvfsp, struct inode *ip, int dolockfs)

Podemos utilizar el segundo argumento para conocer el inodo, con esta información podemos construir una sonda que nos facilite la información del inodo que se está intentando borrar.

Utilizamos printf para mostrar la información de la estructura de datos de tipo inode_t apuntada por el puntero args[1]

  • probefunc, variable con el nombre de la función que estamos instrumentando.
  • args[1]->i_number, número del inodo.
  • args[1]->i_dev, dispositivo de almacenamiento.
  • args[1]->i_vnode->v_path, cadena con el path del fichero.

En el fichero /usr/include/sys/fs/ufs_inode.h podeis encontrar la definición del tipo inode_t

typedef struct inode {
        struct  inode *i_chain[2];      /* must be first */
        struct inode *i_freef;  /* free list forward - must be before i_ic */
        struct inode *i_freeb;  /* free list back - must be before i_ic */
        struct  icommon i_ic;   /* Must be here */
        struct  vnode *i_vnode; /* vnode associated with this inode */
        struct  vnode *i_devvp; /* vnode for block I/O */
        dev_t   i_dev;          /* device where inode resides */
        ino_t   i_number;       /* i number, 1-to-1 with device address */
        off_t   i_diroff;       /* offset in dir, where we found last entry */
                                /* just a hint - no locking needed */
        struct ufsvfs *i_ufsvfs; /* incore fs associated with inode */
        struct  dquot *i_dquot; /* quota structure controlling this file */
        krwlock_t i_rwlock;     /* serializes write/setattr requests */
        krwlock_t i_contents;   /* protects (most of) inode contents */
        kmutex_t i_tlock;       /* protects time fields, i_flag */
        offset_t i_nextr;       /*                                      */
                                /* next byte read offset (read-ahead)   */
                                /*   No lock required                   */
                                /*                                      */
        uint_t  i_flag;         /* inode flags */
        uint_t  i_seq;          /* modification sequence number */
        cachedir_t i_cachedir;  /* Cache this directory on next lookup */
                                /* - no locking needed  */
        long    i_mapcnt;       /* mappings to file pages */
        int     *i_map;         /* block list for the corresponding file */
        dev_t   i_rdev;         /* INCORE rdev from i_oldrdev by ufs_iget */
        size_t  i_delaylen;     /* delayed writes, units=bytes */
        offset_t i_delayoff;    /* where we started delaying */
        offset_t i_nextrio;     /* where to start the next clust */
        long    i_writes;       /* number of outstanding bytes in write q */
        kcondvar_t i_wrcv;      /* sleep/wakeup for write throttle */
        offset_t i_doff;        /* dinode byte offset in file system */
        si_t *i_ufs_acl;        /* pointer to acl entry */
        dcanchor_t i_danchor;   /* directory cache anchor */
        kthread_t *i_writer;    /* thread which is in window in wrip() */
} inode_t;

En el fichero /usr/include/sys/vnode.h, podéis encontrar la definción del tipo vnode_t

typedef struct vnode {
        kmutex_t        v_lock;         /* protects vnode fields */
        uint_t          v_flag;         /* vnode flags (see below) */
        uint_t          v_count;        /* reference count */
        void            *v_data;        /* private data for fs */
        struct vfs      *v_vfsp;        /* ptr to containing VFS */
        struct stdata   *v_stream;      /* associated stream */
        enum vtype      v_type;         /* vnode type */
        dev_t           v_rdev;         /* device (VCHR, VBLK) */

        /* PRIVATE FIELDS BELOW - DO NOT USE */

        struct vfs      *v_vfsmountedhere; /* ptr to vfs mounted here */
        struct vnodeops *v_op;          /* vnode operations */
        struct page     *v_pages;       /* vnode pages list */
        pgcnt_t         v_npages;       /* # pages on this vnode */
        pgcnt_t         v_msnpages;     /* # pages charged to v_mset */
        struct page     *v_scanfront;   /* scanner front hand */
        struct page     *v_scanback;    /* scanner back hand */
        struct filock   *v_filocks;     /* ptr to filock list */
        struct shrlocklist *v_shrlocks; /* ptr to shrlock list */
        krwlock_t       v_nbllock;      /* sync for NBMAND locks */
        kcondvar_t      v_cv;           /* synchronize locking */
        void            *v_locality;    /* hook for locality info */
        struct fem_head *v_femhead;     /* fs monitoring */
        char            *v_path;        /* cached path */
        uint_t          v_rdcnt;        /* open for read count  (VREG only) */
        uint_t          v_wrcnt;        /* open for write count (VREG only) */
        u_longlong_t    v_mmap_read;    /* mmap read count */
        u_longlong_t    v_mmap_write;   /* mmap write count */
        void            *v_mpssdata;    /* info for large page mappings */
        hrtime_t        v_scantime;     /* last time this vnode was scanned */
        ushort_t        v_mset;         /* memory set ID */
        uint_t          v_msflags;      /* memory set flags */
        struct vnode    *v_msnext;      /* list of vnodes on an mset */
        struct vnode    *v_msprev;      /* list of vnodes on an mset */
        krwlock_t       v_mslock;       /* protects v_mset */
} vnode_t;

Las sondas muestras mas o menos la misma información, excepto fbt::ufs_itrunc:entry en la que utilizaremos el segundo argumento de la función ufs_itrunc, que corresponde al desplazamiento dentro del fichero que estamos truncando.

int ufs_itrunc(struct inode *oip, u_offset_t length, int flags, cred_t *cr)
fbt::ufs_itrunc:entry
/ pid == $1 /
{ printf("n %s     t entry: inode %d t dev %d t offset %d t %s",probefunc,args[0]->i_number,args[0]->i_dev,args[1],stringof(args[0]->i_vnode->v_path));
time=timestamp;
}

Como parámetro, el script acepta el PID del proceso que deseamos instrumentar, en nuestro caso el PID del proceso sched que es 0. Ejecutamos el script.

root@host01 # dtrace -q -s ./fbt_ufs_all.d 0 | grep ufs_itrunc
ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4807245824       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4806983680       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4806721536       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4806459392       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4806197248       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4805935104       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4805672960       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4805410816       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4805148672       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4804886528       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4804624384       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4804362240       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4804100096       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4803837952       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4803575808       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4803313664       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4803051520       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4802789376       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4802527232       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4802265088       /soft/FILES_TMP/PRUEBA/dvd2.tar
 ufs_itrunc              return: 2456    time: 2 s
 ufs_itrunc              entry: inode 233205     dev 506806141186        offset 4802002944       /soft/FILES_TMP/PRUEBA/dvd2.tar

Hemos utilizado el comando grep para filtrar la salida de DTRACE, de esta salida nos llama la atención 2 cosas. La primera es que el fichero que se está borrando coincide con uno que se había borrado 3 horas antes, justo cuando la máquina comenzó a perder rendimiento. La segunda cosa que nos llama la atención es el offset, si cogemos dos lineas consecutivas y las restamos

root@tcbbdd02-01 # dc
4803051520
4802789376
-
p
262144
1024
/
p
256

Podemos compribar que se está eliminando el fichero en bloques de 256KB. Esta es la causa de que el Kernel esté empleando mucho tiempo en eliminar un fichero, tiempo que debería estar trabajando en otras tareas, como por ejemplo, asignar tiempo de CPU a los distintos procesos que se están ejecutando. En resumen, hay un problema con el borrado de ficheros en los FS UFS, ahora queda lo facíl, ir a la web de Sun para buscar algún parche y cual es nuestra sorpresa cuando existe un bug reconocido en Solaris 10 sobre la lentitud del borrado de ficheros.

Hemos bajado los parches, los hemos aplicado y ahora la máquina funciona perfectamente.

Conclusión

Alguno de vosotros pensaréis que nos hubieramos ahorrado mucho tiempo, si hubiéramos ido a SunSolve por el último cluster de parches y los hubieramos instalado, reconozco que el resultado hubiera sido el mismo, pero con una pequeña diferencia, nosotros sabemos qué les pasa a nuestras máquinas y podemos dar respuestas. También, porque nos divierte mucho trastear con DTRACE y mdb.

8 Responses

  1. El anónimo Miguel. June 4, 2009 / 11:31 pm

    Buenísimo, tío, eres un auténtico crack; de mayor quiero ser como tú.

    Muchísimas gracias.

  2. Sergio Galvan June 5, 2009 / 9:02 am

    Muy interesante el análisis de rendimiento. Requiere de paciencia, yo si gano algo de ella y me animo con DTRACE que sin duda cada vez me sorprende más.Good job

  3. RuBiCK June 5, 2009 / 10:24 am

    Muy bueno!

    Estoy de acuerdo contigo, siempre es mejor saber por que fallan las cosas y solucionarlas que dar a un botón y que se solucionen “solas”

  4. JamesD June 11, 2009 / 7:33 pm

    Thanks for the useful info. It’s so interesting

  5. Alex Sola June 12, 2009 / 11:23 am

    Enhorabuena por el resultado y por el post. Estoy contigo: hay que saber por qué fallan las máquinas… al fin y al cabo, son nuestras compañeras de trabajo XD

  6. angel July 30, 2009 / 3:07 am

    Te leo y me sorprendes, lo cual no quiere decir que todo lo haya entendido.
    Ánimo con esta tarea, y todas las demás.

    Ángel.

  7. Roser August 20, 2009 / 11:58 am

    Muy bueno… tendre que ponerme las pilas con el dtrace.. pero mira que me cuesta eh??

  8. miliko September 9, 2009 / 9:06 am

    Hummmm…muy interesante tu post, sin duda. Me encanta tu blog, te considero un máquina en Solaris.

    Y yo me pregunto…¿tenéis tiempo en el trabajo para hacer todo eso?. Si pierdo yo ese tiempo en averiguar porqué una máquina recién instalada no va bien me cortan las…me dirían REINSTALA!!! y aplícale el último EIS…

Comments are closed.