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 0×2a10041fca0, 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.
4 June 2009 a las 11:31 pm
Buenísimo, tío, eres un auténtico crack; de mayor quiero ser como tú.
Muchísimas gracias.
5 June 2009 a las 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
5 June 2009 a las 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”
11 June 2009 a las 7:33 pm
Thanks for the useful info. It’s so interesting
12 June 2009 a las 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
30 July 2009 a las 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.
20 August 2009 a las 11:58 am
Muy bueno… tendre que ponerme las pilas con el dtrace.. pero mira que me cuesta eh??
9 September 2009 a las 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…