+-------------------------------------------------------------+
|=---------------=[ S O L A R I S 10 ]=---------------------=|
|=-----------------------------------------------------------=|
|=----=[ZFS, GNOME-Terminal, SSH, Rsync, XDMCP e DTrace]=----=|
+-------------------------------------------------------------+
|=---------------------=[ byLeal ]=--------------------------=|
+-------------------------------------------------------------+
CONTEÚDO:
1. INTRODUÇÃO................ 1
2. A MÁQUINA................. 1
3. A TAREFA.................. 2
4. O PROBLEMA................ 2
5. A INVESTIGAÇÃO............ 3
5.1 Provider SYSCALL...... 3
5.2 ERRINFO............... 5
5.3 Provider SYSINFO...... 6
5.4 Breve................. 7
5.5 SYSCALL: read(2)...... 12
5.6 PROCSYSTIME.............18
6. CONCLUSÃO................. 22
1. INTRODUÇÃO:
O presente documento visa relatar os procedimentos efetua-
dos, bem como apresentar os resultados obtidos, na tarefa de
identificação da causa do atraso anormal em uma tarefa de sin-
cronismo de arquivos. Utilizando a ferramenta DTrace, disponí-
vel no sistema operacional Solaris 10 (S10).
2. A MÁQUINA:
Vamos a configuração do servidor S10:
+-----------------------------------------------------------+
| Memoria: 4096 Megabytes |
| |
| Processador (psrinfo -v): |
| Status of virtual processor 0 as of: 12/07/2006 14:16:23 |
| on-line since 11/28/2006 10:59:44. |
| The i386 processor operates at 3000 MHz, |
| and has an i387 compatible floating point processor. |
| Status of virtual processor 1 as of: 12/07/2006 14:16:23 |
| on-line since 11/28/2006 10:59:53. |
| The i386 processor operates at 3000 MHz, |
| and has an i387 compatible floating point processor. |
+-----------------------------------------------------------+
A tarefa foi executada logo após a instalação e atualização
do S10, apenas com os serviços que estão disponibilizados por
padrão. A seguir temos uma visão do estado do servidor segun-
dos antes da execução:
Comando: vmstat 1
kthr memory page disk
r b w swap free re mf pi po fr de sr cd cd s0 s1
0 0 0 4780200 3230076 5 30 3 10 10 0 3 6 6 2 2
0 0 0 2019116 527296 0 51 0 0 0 0 0 0 0 0 0
0 0 0 2019108 527288 0 1 0 0 0 0 0 0 0 0 0
0 0 0 2019108 527288 0 0 0 0 0 0 0 0 0 0 0
0 0 0 2019108 527288 0 1 0 0 0 0 0 0 0 0 0
0 0 0 2019108 527288 0 0 0 0 0 0 0 129 132 0 0
0 0 0 2019108 527288 0 1 0 0 0 0 0 0 0 0 0
0 0 0 2019108 527288 0 1 0 0 0 0 0 0 0 0 0
0 0 0 2019108 527288 0 1 0 0 0 0 0 0 0 0 0
0 0 0 2019108 527288 0 1 0 0 0 0 0 0 0 0 0
0 0 0 2019108 527288 0 0 0 0 0 0 0 129 120 0 0
0 0 0 2019108 527288 0 0 0 0 0 0 0 0 0 0 0
continuação...
faults cpu
in sy cs us sy id
1056 1154 499 1 1 98
1158 1206 523 1 2 97
1574 1599 696 1 1 98
1230 1315 541 1 1 98
1414 1477 638 1 1 98
2065 1334 1467 0 3 97
1154 1170 518 1 0 99
1325 1375 558 0 1 98
1336 1377 569 1 1 98
1440 1450 621 1 1 98
1890 1189 1417 1 2 97
1260 1372 555 1 1 98
3. A TAREFA:
A tarefa a ser feita era simples: Efetuar o sincronismo en-
tre dois diretórios. O diretório de ORIGEM estava em um servi-
dor Linux, e o diretório de DESTINO encontrava-se na máquina
S10.
O utilitário executado foi o rsync(1), que será utilizado fu-
turamente para sincronismo deste mesmo diretório. Mas esta é
a primeira execução, portanto todo conteúdo do diretório DirB,
precisará ser transferido (13GB de dados).
Eis o comando: rsync -av -e ssh user@IP:/DirA/DirB .
O comando acima foi executado dentro de um gnome-terminal(1),
em uma sessão JDS, iniciada a partir de um desktop Linux (Ubun
tu - 6.10), utilizando o protocolo XDMCP. O diretório "." é um
sistema de arquivos ZFS.
4. O PROBLEMA:
Após alguns minutos (na realidade ~1hora), fui conferir a ve-
locidade de gravação, e quanto restava para ser transferido.
O comando que executei foi: zpool iostat colorado 3
capacity operations bandwidth
pool used avail read write read write
--------- ----- ----- ----- ----- ----- -----
colorado 606M 147G 0 84 329 384K
colorado 606M 147G 0 71 0 149K
colorado 606M 147G 0 0 0 0
colorado 606M 147G 0 81 0 164K
colorado 606M 147G 0 0 0 0
colorado 606M 147G 0 74 0 121K
colorado 606M 147G 0 75 0 147K
colorado 606M 147G 0 0 0 0
colorado 606M 147G 0 57 0 121K
colorado 606M 147G 0 0 0 0
colorado 607M 147G 0 64 0 137K
colorado 607M 147G 0 59 0 149K
colorado 607M 147G 0 0 0 0
colorado 607M 147G 0 63 0 125K
colorado 607M 147G 0 0 0 0
colorado 607M 147G 0 56 0 140K
colorado 607M 147G 0 64 0 141K
colorado 607M 147G 0 0 0 0
colorado 607M 147G 0 65 0 133K
No decorrer de quase uma hora de transferência, este não era
o retorno que esperava. As duas máquinas envolvidas estão na
mesma rede, com uma conexão ethernet giga, sem erros, e a mes-
ma transferência para um terceiro servidor Linux na mesma re-
de, terminava em minutos. Sei que a conexão deste servidor em
particular, poderia estar causando o problema. Mas com o fato
desta mesma máquina dias atrás ter rodado Linux sem apresentar
problemas, utilizando a mesma estrutura de rede, me fez sus-
peitar do ZFS.
5. A INVESTIGAÇÃO
Bom, termos um ambiente sem problemas é o objetivo, mas isto
é uma tarefa bem difícil. O ideal é que quando apareçam proble
mas: 1) tenhamos ferramentas para identificar suas causas, e
2) quando possível, resolvê-los.
obs.: Os comandos a seguir foram executados durante a tarefa
de sincronismo.
5.1 Provider SYSCALL
Solaris tem inúmeras ferramentas para executar tarefas de de-
puração, e identificação de erros ou problemas de performance.
Mas a novidade fica por conta da linguagem D. Então, vamos ver
até onde conseguimos chegar com alguns scripts:
script: dtrace -n 'syscall:::entry {@[execname]=count()}'
O comando acima ficou executando por ~5 minutos, e o objetivo
era contar (count()) o número de "system calls" (syscall:::en-
try), executada por processo (execname). O resultado é mostra-
do a seguir:
snmpdx 2
xfs 4
sac 6
ttymon 9
wnck-applet 10
dsdm 14
dtlogin 16
syslogd 16
metacity 21
init 27
automountd 29
fmd 30
inetd 30
svc.configd 30
svc.startd 30
gnome-smproxy 32
snmpd 32
utmpd 51
mapping-daemon 60
clock-applet 80
screen-4.0.2 148
nautilus 248
zpool 297
gnome-vfs-daemon 300
nfsmapid 510
nscd 512
sendmail 605
xscreensaver 761
sshd 805
Xsun 1186
ssh 1606
dtgreet 2969
gnome-netstatus- 2988
dtrace 7547
gnome-panel 8400
gconfd-2 9583
mixer_applet2 15026
rsync 60671
gnome-terminal 267771
Como podemos observar, o gnome-terminal(1) que deveria ser a-
penas um coadjuvante, está com o papel principal no nosso am-
biente. Executando quase 5 vezes mais chamadas de sistema do
que o aplicativo rsync(1).
A pergunta que fica é:
"O que o gnome-terminal(1) está fazendo"?
Para começar a responder esta pergunta, vamos para mais um pe
queno programa em D:
script: dtrace -n syscall:::entry'/execname == "gnome-termin
al"/ {@[probefunc] = count()}'
Executando o script acima por mais cinco minutos, conseguimos
agrupar a contagem de chamadas de sistema (syscall), somente
para o gnome-terminal(1).
obs.: Apenas eu estou logado no sistema, e apenas um gnome-
terminal está em execução.
A seguir temos o retorno do comando:
ioctl 6821
writev 11921
systeminfo 43661
write 64200
pollsys 105918
read 121687
readv 133679
Podemos identificar uma quantidade bastante grande de "leitu-
ras", ou "tentativas de leitura". Observe a presença da sys-
call pollsys(2), também apresentando um número bem elevado de
requisições.
obs.: Note que a falta da syscall lseek, nos leva a crer que
os dados são sequenciais. Portanto: 1) Estamos lendo sequen-
cialmente um arquivo, ou 2) Estamos lendo um "file descriptor"
(FD) que não suporta "seek" (ex.: um terminal ou socket).
Com uma quantidade tão grande de chamadas de sistema, uma in-
formação interessante seria a quantidade de erros no retorno
destas requisições.
Utilizando o script D "errinfo", disponibilizado no DTrace-
Toolkit, podemos responder esta pergunta (também executado por
~5 minutos).
comando: errinfo -cn gnome-terminal
Tracing... Hit Ctrl-C to end.
^C
EXEC SYSCALL ERR COUNT DESC
gnome-terminal readv 11 43197 Resource temporarily unavailable
gnome-terminal read 11 74286 Resource temporarily unavailable
Praticamente metade das chamadas para "read" and "readv" re-
tornam erro de "recurso temporariamente indisponível". Sendo
que estas duas chamadas de sistema são as mais executadas pelo
gnome-terminal(1). Mas nós faremos a análise mais aprofundada
deste erro mais adiante. Por enquanto, vale lembrar apenas que
ERR 11, conforme o arquivo /usr/include/sys/errno.h:
#define EAGAIN 11 /* Resource temporarily unavailable */
E conforme a página manual da syscall read(2):
EAGAIN Mandatory file/record locking was set,
O_NDELAY or O_NONBLOCK was set, and there
was a blocking record lock; total amount of
system memory available when reading using
raw I/O is temporarily insufficient; no data
is waiting to be read on a file associated
with a tty device and O_NONBLOCK was set; or
no message is waiting to be read on a stream
and O_NDELAY or O_NONBLOCK was set.
5.2 Provider SYSINFO
Podemos deduzir que por estar executando bem mais chamadas
que os outros processos, o gnome-terminal(1) esteja recebendo
mais parcelas de CPU. Mas para confirmar isto, podemos execu-
tar um outro pequeno script D:
script :
dtrace -n 'sysinfo:::pswitch {@[execname] = count();}'
ttymon 1
dtlogin 2
sac 2
init 3
snmpdx 3
xfs 4
metacity 5
wnck-applet 5
syslogd 8
automountd 11
gnome-smproxy 14
utmpd 16
screen-4.0.2 22
clock-applet 25
snmpd 45
nfsmapid 88
fmd 90
svc.startd 91
inetd 92
svc.configd 94
sshd 103
xscreensaver 140
mapping-daemon 177
sendmail 181
nautilus 229
gnome-vfs-daemon 298
fsflush 300
zpool 305
nscd 579
Xsun 592
dtrace 602
gconfd-2 1266
gnome-netstatus- 1520
gnome-panel 1555
dtgreet 1730
mixer_applet2 3450
rsync 4091
ssh 5377
gnome-terminal 163121
sched 305042
Como o script que executamos sinaliza cada vez que um proces-
so ganha acesso ao processador, o resultado acima comprova
nossa suspeita. Mais uma vez o tempo de execuçao do script foi
~5 minutos.
Na tentativa de isolar o problema, vamos executar o mesmo sin
cronismo dentro de uma conexão SSH simples, sem utilizar o gno
me-termina, nem o XDMCP.
comando: time rsync -av -e ssh user@IP:/DirA/DirB .
sent 9871968 bytes received 11948679206 bytes 3621060.16 by
tes/sec total size is 11908868051 speedup is 1.00
real 55m2.148s
user 6m38.540s
sys 4m55.741s
Totalmente dentro do esperado. Na realidade, o sistema de ar-
quivos no servidor Linux aponta 13GB (XFS), no ZFS os mesmos
dados são apresentados como: 12GB ("du -h /DirA/DirB" em ambos
os casos).
Não temos culpados, mas já temos dois inocentes: Rsync(1), e
o ZFS.
5.3 Breve
Para continuarmos nossa investigação na performance do acesso
remoto ao ambiente gráfico, e mais especificamente a execução
de um processo dentro do gnome-terminal (com atualização de te
la), vamos escrever um pequeno programa em C:
+------------------------------------------------------------+
| PROGRAMA: breve.c |
+------------------------------------------------------------+
| #include |
| |
| int main (int argc, char **argv) |
| { |
| char path[32]=”/home/leal/p/a/teste”; |
| int c = 0; |
| FILE *fd; |
| |
| while ( c < 10000 ) { |
| if (!(fd = fopen(path, "w"))) { |
| printf ("Error!n"); exit (1); |
| } |
| fclose(fd); |
| printf ("Br %in", c); |
| c++; |
| } |
| exit (0); |
| } |
+------------------------------------------------------------+
A idéia do "loop" e das chamadas open(2)/close(2)/write(2),
no programa breve, é visualizar o atraso na execução de todo
o processo, em decorrência do "bloqueio" na atualização do
terminal. Isto é, a criação e atualização dos arquivos pelo
rsync(1), tarefa principal, ficar esperando o retorno do gno-
me-terminal, tarefa secundária.
obs.: A partir deste ponto, nossos testes serão efetuados so-
bre a execução do programa "breve". A tarefa de sincronismo
foi cancelada.
Após a compilação, executamos o programa em uma conexão SSH:
comando: time ./breve
real 0m0.342s
user 0m0.032s
sys 0m0.309s
O programa executou em menos de um segundo (342 milisegundos
para ser exato). Logo em seguida, testamos a execução através
da interface gráfica(XDMCP), dentro de um gnome-terminal(1):
comando: time ./breve
real 0m56.058s
user 0m0.032s
sys 0m0.286s
Nada bom... 56 segundos! Vamos visualizar as chamadas de sis-
tema que nosso programa está executando. Para isto, primeiro
rodamos o script D e em seguida executamos o programa "breve".
script: dtrace -n 'syscall:::entry /execname == "breve"/
{@[probefunc] = count()}'
fstat64 1
getcwd 1
getpid 1
getrlimit 1
ioctl 1
memcntl 1
rexit 1
sysconfig 1
sysi86 1
munmap 2
setcontext 2
resolvepat 3
xstat 4
mmap 7
write 10000
close 10001
open 10002
Perfeito, basicamente as iterações de abertura e fechamento
do arquivo que criamos, e 10000 chamadas a sycall "write", exe
cutadas através do "printf()".
Precisamos calcular a latência de cada operação, para saber-
mos qual chamada exatamente está causando atraso. Para isso
executaremos o seguinte programa em D:
+------------------------------------------------------------+
| PROGRAMA: latencia.d |
+------------------------------------------------------------+
| #!/usr/sbin/dtrace -s |
| #pragma D option quiet |
| int x; |
| |
| syscall::$2:entry |
| /execname == $$1/ |
| { |
| self->ENTRADA = timestamp; |
| x = x + 1; |
| } |
| |
| syscall::$2:return |
| /self->ENTRADA/ |
| { |
| this->SAIDA = timestamp - self->ENTRADA; |
| this->TIME = ( this->SAIDA / 1000000 ); |
| printf(”%10d : %10d millisecondsn”, x, this->TIME); |
| self->ENTRADA = 0; |
| } |
+------------------------------------------------------------+
O script latencia.d irá contabilizar o tempo de execução pa-
ra cada chamada de sistema que for solicitada através da linha
de comando ( 2º argumento), para o programa em questão (1º ar-
gumento). Iremos utilizar este script para verificar os tempos
de execução de cada uma das três principais chamadas de siste-
ma que nosso programa breve executa: open(2), close(2) e wri-
te(2).
script: ./latencia.d breve open >/tmp/latencia.log
comando: tail /tmp/latencia.log
9995 : 0 milliseconds
9996 : 0 milliseconds
9997 : 0 milliseconds
9998 : 0 milliseconds
9999 : 0 milliseconds
10000 : 0 milliseconds
10001 : 0 milliseconds
10002 : 0 milliseconds
script: awk ‘{print $3}’ /tmp/latencia.log | sort -u
0
Obs.: utilizaremos o script awk acima para nos certificar que
todos os valores são zero. Caso contrário, o comando “sort -u”
nos informará as diferenças.
No caso das chamadas “open”, todas executaram sem problemas e
com tempos normais.
script: ./latencia.d breve close >/tmp/latencia.log
comando: tail /tmp/latencia.log
9953 : 0 milliseconds
9954 : 0 milliseconds
9955 : 0 milliseconds
9956 : 0 milliseconds
9957 : 0 milliseconds
9958 : 0 milliseconds
9959 : 0 milliseconds
9960 : 0 milliseconds
script: awk ‘{print $3}’ /tmp/latencia.log | sort -u
0
O mesmo aconteceu com a chamada close(2)...
script: ./latencia.d breve write >/tmp/latencia.log
comando: tail /tmp/latencia.log
9993 : 0 milliseconds
9994 : 0 milliseconds
9995 : 0 milliseconds
9996 : 0 milliseconds
9997 : 0 milliseconds
9998 : 0 milliseconds
9999 : 0 milliseconds
10000 : 0 milliseconds
script: awk ‘{print $3}’ /tmp/latencia.log | sort -u | tail
354
355
357
359
362
375
380
383
549
737
Aí está! Agora vamos utilizar outro script, desta vez escrito
em perl, para podermos obter algumas informações importantes
sobre os tempos de execução da chamada write(2):
a) média
b) desvio-padrão
c) total
d) etc..
comando: awk ‘{print $3}’ /tmp/latencia.log | /home/leal/p/to
ols/report.pl
ops: 10000
max: 737
min: 0
med: 317
avg: 5.3684
sum: 53684 <===== 53 segundos!
dev: 41.6126596456448
O programa rodando em um gnome-terminal(1), através do proto-
colo XDMCP, demorou 56 segundos para praticamente contar até
10000! A interação com o usuário, o "-v" do nosso programa,
levou 53 segundos para imprimir cerca de 10 dígitos por linha.
Mas nosso problema com o rsync(1) ainda é pior, pois os ca-
minhos de cada arquivo são informados na tela, o que normal-
mente contém bem mais que 10 dígitos. Para chegarmos mais
próximos deste problema, vamos alterar nossa linha de:
printf ("Br %in", c);
para:
printf ("Brrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr
%in", c);
Vamos efetuar o teste com esta alteração, aumentando a string
do nosso comando "printf" para aproximadamente 60 caracteres..
comando: time ./breve
real 3m46.918s <===== 3 minutos!
user 0m0.043s
sys 0m0.325s
Com nosso pequeno programa "breve", conseguimos definitiva-
mente inocentar a tarefa de sincronismo, e o sistema de arqui-
vos ZFS. Portanto, nossa investigação fica restrita ao gnome-
terminal(1), e a conexão XDMCP.
Podemos começar executando nosso programa em um gnome-
terminal remotamente, sem a utilização do XDMCP. No caso, uti-
lizaremos um túnel ssh como transporte.
comando: time ./breve
real 0m0.371s
user 0m0.031s
sys 0m0.315s
Valores muito próximos dos que visualizamos em uma conexão
ssh simples (caracter). Neste caso foram 371 milisegundos, con
tra 342 milisegundos da execução diretamente no terminal ssh.
5.4 SYSCALL: read(2)
Ainda estamos devendo uma análise um pouco mais apurada do re
torno das chamadas read(2). Constatamos durante a tarefa de
sincronismo, que metade das requisições retornavam erro "11".
Vamos utilizar um outro script D para visualizarmos melhor o
retorno destas chamadas:
obs.: Conforme a página manual, a chamada read(2) tem como
código de retorno a quantidade de bytes lidos, ou -1 sinali-
zando erro. No caso de final de arquivo, o retorno é 0. Então
só temos um argumento no retorno: arg0.
script: dtrace -n 'syscall::read:return /execname == "gnome-
terminal"/ { @Size = quantize(arg0); }'
dtrace: description 'syscall::read:return ' matched 1 probe
^C
value ------------- Distribution ------------- count
-2 | 0
-1 |@@@@@@@@@@@@@@@@@@@@ 48793
0 | 0
1 | 0
2 | 1
4 | 1
8 | 0
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@ 50119
64 | 3
128 | 1
256 | 0
512 | 968
1024 | 0
Realmente confirmado. Metade das chamadas read(2) retornaram
-1. Isto foi o que constatamos ao executar o script errinfo du
rante nossa tarefa de sincronismo. A maioria das chamadas que
retornam OK, são requisições de até 32 bytes (16-32).
Conforme a página manual da system call read(2):
...
When attempting to read a file associated with a terminal
that has no data currently available:
o If O_NDELAY is set, read() returns 0.
o If O_NONBLOCK is set, read() returns -1 and sets errno
to EAGAIN.
e ainda...
When attempting to read a file associated with a socket or a
stream that is not a pipe, a FIFO, or a terminal, and the
file has no data currently available:
o If O_NDELAY or O_NONBLOCK is set, read() returns -1 and
sets errno to EAGAIN.
...
Portanto, vamos agrupar as chamadas read(2) por file des-
criptor, para que depois possamos conferir se o que diz na
página manual se encaixa nesse caso.
Conforme o protótipo da função read(2):
ssize_t read(int fildes, void *buf, size_t nbyte);
/
||
====== 1° argumento
script: dtrace -n 'syscall::read:entry /execname == "gnome-t
erminal"/ { @[arg0] = count(); }'
dtrace: description 'syscall::read:entry ' matched 1 probe
^C
21 1282
4 98611
Agora precisamos listar os FDs que estão sendo utilizados pe-
lo gnome-terminal(1), para identificar os de número 21 e 4. O
que conseguimos com o comando:
pfiles `pgrep gnome-terminal`
------------------------ corte aqui ------------------------
3243: gnome-terminal
Current rlimit: 256 file descriptors
0: S_IFCHR mode:0666 dev:270,0 ino:6815752 uid:0 gid:3
rdev:13,2
O_RDONLY|O_LARGEFILE
/devices/pseudo/mm@0:null
1: S_IFCHR mode:0666 dev:270,0 ino:6815752 uid:0 gid:3
rdev:13,2
O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
/devices/pseudo/mm@0:null
2: S_IFCHR mode:0666 dev:270,0 ino:6815752 uid:0 gid:3
rdev:13,2
O_WRONLY|O_APPEND|O_CREAT|O_LARGEFILE
/devices/pseudo/mm@0:null
3: S_IFDOOR mode:0444 dev:279,0 ino:63 uid:0 gid:0 size:0
O_RDONLY|O_LARGEFILE FD_CLOEXEC door to nscd[111]
/var/run/name_service_door
4: S_IFSOCK mode:0666 dev:276,0 ino:32241 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
SOCK_STREAM
SO_KEEPALIVE,SO_SNDBUF(49152),SO_RCVBUF(49640),
IP_NEXTHOP(232.193.0.0)
sockname: AF_INET6 ::ffff:10.X.X.y port: 33130
peername: AF_INET6 ::ffff:192.X.X.y port: 6020
5: S_IFIFO mode:0000 dev:278,0 ino:2095 uid:100 gid:1 size:0
O_RDWR
6: S_IFIFO mode:0000 dev:278,0 ino:2095 uid:100 gid:1 size:0
O_RDWR
7: S_IFIFO mode:0000 dev:278,0 ino:2096 uid:100 gid:1 size:0
O_RDWR
8: S_IFIFO mode:0000 dev:278,0 ino:2096 uid:100 gid:1 size:0
O_RDWR
9: S_IFIFO mode:0000 dev:278,0 ino:2097 uid:100 gid:1 size:0
O_RDWR
10: S_IFIFO mode:0000 dev:278,0 ino:2097 uid:100 gid:1 size:0
O_RDWR|O_NONBLOCK
11: S_IFCHR mode:0644 dev:270,0 ino:78118918 uid:0 gid:3
rdev:149,1
O_RDONLY
/devices/pseudo/random@0:urandom
12: S_IFIFO mode:0000 dev:278,0 ino:2098 uid:100 gid:1 size:0
O_RDWR
13: S_IFIFO mode:0000 dev:278,0 ino:2098 uid:100 gid:1 size:0
O_RDWR
14: S_IFSOCK mode:0666 dev:276,0 ino:34603 uid:0 gid:0 size:0
O_RDWR FD_CLOEXEC
SOCK_STREAM
SO_SNDBUF(16384),SO_RCVBUF(5120)
sockname: AF_UNIX
peername: AF_UNIX /tmp/.ICE-unix/3185
15: S_IFSOCK mode:0666 dev:276,0 ino:36821 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
SOCK_STREAM
SO_SNDBUF(16384),SO_RCVBUF(5120)
sockname: AF_UNIX
peername: AF_UNIX /var/tmp/orbit-leal/linc-c76-0-45890
0e8838cd
16: S_IFSOCK mode:0666 dev:276,0 ino:38208 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
SOCK_STREAM
SO_REUSEADDR,SO_SNDBUF(49152),SO_RCVBUF(49152),
IP_NEXTHOP(0.192.0.0)
sockname: AF_INET 0.0.0.0 port: 33131
17: S_IFSOCK mode:0666 dev:276,0 ino:38012 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
SOCK_STREAM
SO_REUSEADDR,SO_SNDBUF(16384),SO_RCVBUF(5120)
sockname: AF_UNIX /var/tmp/orbit-leal/linc-cab-0-45894
36c4fcba
18: S_IFSOCK mode:0666 dev:276,0 ino:38649 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
SOCK_STREAM
SO_REUSEADDR,SO_SNDBUF(16384),SO_RCVBUF(5120)
sockname: AF_UNIX /var/tmp/orbit-leal/linc-cab-0-45894
36c4fcba
peername: AF_UNIX
19: S_IFSOCK mode:0666 dev:276,0 ino:34604 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
SOCK_STREAM
SO_REUSEADDR,SO_SNDBUF(16384),SO_RCVBUF(5120)
sockname: AF_UNIX /var/tmp/orbit-leal/linc-cab-0-45894
36c4fcba
peername: AF_UNIX
20: S_IFSOCK mode:0666 dev:276,0 ino:5048 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
SOCK_STREAM
SO_SNDBUF(16384),SO_RCVBUF(5120)
sockname: AF_UNIX
peername: AF_UNIX /var/tmp/orbit-leal/linc-c7d-0-4589
05d5d058b
21: S_IFCHR mode:0000 dev:270,0 ino:41498 uid:0 gid:0
rdev:23,5
O_RDWR|O_NONBLOCK
/devices/pseudo/clone@0:ptm
22: S_IFIFO mode:0000 dev:278,0 ino:2099 uid:100 gid:1 size:0
O_RDWR
23: S_IFIFO mode:0000 dev:278,0 ino:2099 uid:100 gid:1 size:0
O_RDWR
24: S_IFIFO mode:0000 dev:278,0 ino:2100 uid:100 gid:1 size:0
O_RDWR
25: S_IFSOCK mode:0666 dev:276,0 ino:36545 uid:0 gid:0 size:0
O_RDWR
SOCK_STREAM
SO_SNDBUF(16384),SO_RCVBUF(5120)
sockname: AF_UNIX
26: S_IFIFO mode:0000 dev:278,0 ino:2100 uid:100 gid:1 size:0
O_RDWR|O_NONBLOCK
------------------------ corte aqui ------------------------
Vamos exibi-los novamente para facilitar a identificação:
------------------------ corte aqui ------------------------
4: S_IFSOCK mode:0666 dev:276,0 ino:32241 uid:0 gid:0 size:0
O_RDWR|O_NONBLOCK FD_CLOEXEC
SOCK_STREAM
SO_KEEPALIVE,SO_SNDBUF(49152),SO_RCVBUF(49640),
IP_NEXTHOP(232.193.0.0)
sockname: AF_INET6 ::ffff:10.X.X.y port: 33130
peername: AF_INET6 ::ffff:192.X.X.y port: 6020
------------------------ corte aqui ------------------------
Este é o socket que representa a conexão entre o servidor e
a minha estação de trabalho (os IP's são fictícios). Note que
conforme a página manual, este FD está com a flag "O_NONBLOCK"
habilitada. Portanto, gnome-terminal(1) receberá erros EAGAIN
no acesso a este FD, caso os dados não estejam prontos.
------------------------ corte aqui ------------------------
21: S_IFCHR mode:0000 dev:270,0 ino:41498 uid:0 gid:0
rdev:23,5
O_RDWR|O_NONBLOCK
/devices/pseudo/clone@0:ptm
------------------------ corte aqui ------------------------
O FD acima é referente ao nosso terminal, e seria interessan-
te sabermos se temos um número grande de erros "EAGAIN" neste
FD, pois temos a flag "O_NONBLOCK" habilitada também.
Então vamos discriminar os FDs e identificar quantos erros 11
estão sendo gerados para cada um... Vamos começar com o FD 4:
script: dtrace -n 'syscall::read:entry /execname == "gnome-t
erminal" && arg0 == 4/ {self->FLAG = 1;} syscall::read:retur
n /self-> FLAG / {@[arg0] = count(); self->FLAG =0;}'
dtrace: description 'syscall::read:entry ' matched 2 probes
^C
-1 48827
32 49823
Agora vamos para o FD 21...
script: dtrace -n 'syscall::read:entry /execname == "gnome-t
erminal" && arg0 == 21/ {self->FLAG = 1;} syscall::read:retur
n /self-> FLAG / {@[arg0] = count(); self->FLAG =0;}'
dtrace: description 'syscall::read:entry ' matched 2 probes
^C
2 1
106 1
293 1
318 1
555 1
53 2
550 69
54 90
55 205
560 899
Perfeito, os erros EAGAIN estão aparentemente no acesso ao FD
que representa nossa conexão. Mas isto é apenas uma constata-
ção para entendermos as informações que estamos verificando.
Não necessariamente esta seja a razão do atrazo na execução.
Talvez seja apenas uma característica da programação, e não
esteja gerando problemas. Vamos calcular a latência das chama-
das read(2)/readv(2), para sabermos se são problema ou não.
script: ./latencia.d gnome-terminal read > /tmp/latencia.log
script: awk '{print $3}' /tmp/latencia.log | sort -u
0
script: ./latencia.d gnome-terminal readv > /tmp/latencia.log
script: awk '{print $3}' /tmp/latencia.log | sort -u
0
Conforme vimos nos resultados acima, nosso problema não está
nas chamadas read(2), e nem nas chamadas readv(2).
obs.: O que me intriga é que temos a utilização da chamada
pollsys(2), e mesmo assim temos chamadas read(2) sendo execu-
tadas sobre FD que não estão prontos para leitura. Conforme a
página manual da chamada poll(2):
DESCRIPTION
The poll() function provides applications with a mechanism
for multiplexing input/output over a set of file descrip-
tors. For each member of the array pointed to by fds,
poll() examines the given file descriptor for the event(s)
specified in events. The number of pollfd structures in the
fds array is specified by nfds. The poll() function identi-
fies those file descriptors on which an application can read
or write data, or on which certain events have occurred.
Ainda precisamos identificar no gnome-terminal(1), onde estão
os quase três minutos de latencia. No DTraceToolkit temos um
script D muito útil para nos fornecer esta informação:
procsystime.
Vamos executá-lo e observar os resultados:
script: ./procsystime -a -n gnome-terminal
Hit Ctrl-C to stop sampling...
^C
Elapsed Times for processes gnome-terminal,
SYSCALL TIME (ns)
fcntl 15805
fstat64 32766
brk 11092009
ioctl 17873960
systeminfo 67372551
read 475826059
readv 852809922
write 1566182042
pollsys 216148192460 <===== 3,6 minutos
TOTAL: 219139397574
CPU Times for processes gnome-terminal,
SYSCALL TIME (ns)
fcntl 4389
fstat64 19034
ioctl 8044618
brk 8088614
systeminfo 15097287
read 263802526
readv 584568168
pollsys 957183040
write 1428503773
TOTAL: 3265311449
Syscall Counts for processes gnome-terminal,
SYSCALL COUNT
fcntl 5
fstat64 5
brk 1342
ioctl 4156
systeminfo 25402
write 52097
pollsys 93410
read 100364
readv 126316
TOTAL: 403097
Os resultados acima foram bastante interessantes. Temos os
tempos de CPU (execução), e o tempo decorrido de cada chama-
da. O que nos faz direcionarmos nossa atenção para a chamada
pollsys(2). Esta chamada de sistema teve uma latência total de
mais de três minutos! Novamente vamos utilizar nosso script de
cálculo de latência para acompanhar a execução de cada requi-
sição efetuada a syscall pollsys(2).
script: ./latencia.d gnome-terminal pollsys > /tmp/latencia.
log
script: awk '{print $3}' /tmp/latencia.log | sort -u | tail
51
54
55
58
6
301
65
7
8
9
script: awk '{print $3}' /tmp/latencia.log | /home/leal/p/to
ols/report.pl
ops: 86652
max: 343
min: 0
med: 47
avg: 1.87045884688178
sum: 162079 <===== 2,7 minutos
dev: 4.86219237692499
Alcançamos mais um ponto em nossa investigação.
Vamos tentar ir um pouco mais longe, e discriminar as rotinas
e funções que estão sendo executadas, cada vez que a chamada
pollsys é invocada.
script: dtrace -n 'syscall::pollsys:entry /execname == "gnom
e-terminal "/ { @[ustack()] = count(); }'
dtrace: description 'syscall::pollsys:entry ' matched 1 probe
^C
libc.so.1`__pollsys+0x15
libc.so.1`pselect+0x18e
libc.so.1`select+0x82
libX11.so.4`_XEventsQueued+0x1ad
libX11.so.4`XPending+0x42
libgdk-x11-2.0.so.0.400.9`gdk_check_xpending+0x1f
14
libc.so.1`__pollsys+0x15
libc.so.1`pselect+0x18e
libc.so.1`select+0x82
libX11.so.4`_XWaitForReadable+0xcf
libX11.so.4`_XRead+0xa9
libX11.so.4`_XReply+0xce
libX11.so.4`XSync+0x65
libgdk-x11-2.0.so.0.400.9`gdk_window_queue+0x72
61
libc.so.1`__pollsys+0x15
libc.so.1`pselect+0x18e
libc.so.1`select+0x82
libX11.so.4`_XWaitForReadable+0xcf
libX11.so.4`_XRead+0xa9
libX11.so.4`_XReply+0xce
libX11.so.4`XSync+0x65
libgdk-x11-2.0.so.0.400.9`gdk_flush+0x2c
211
libc.so.1`__pollsys+0x15
libc.so.1`pselect+0x18e
libc.so.1`select+0x82
libX11.so.4`_XWaitForReadable+0xcf
libX11.so.4`_XRead+0xa9
libX11.so.4`_XReply+0xce
libX11.so.4`XGetGeometry+0x6b
libXft.so.2`XftDrawDepth+0x43
libXft.so.2`XftDrawBitsPerPixel+0x24
libXft.so.2`_XftSmoothGlyphFind+0x4e
libXft.so.2`XftGlyphFontSpecCore+0x356
libXft.so.2`XftDrawGlyphFontSpec+0x124
libXft.so.2`XftDrawCharFontSpec+0xb1
libvte.so.4.4.0`_vte_xft_draw_text+0x238
966
libc.so.1`__pollsys+0x15
libc.so.1`poll+0x52
4837
libc.so.1`__pollsys+0x15
libc.so.1`pselect+0x18e
libc.so.1`select+0x82
libX11.so.4`_XWaitForReadable+0xcf
libX11.so.4`_XRead+0xa9
libX11.so.4`_XReply+0xce
libX11.so.4`XGetImage+0x9f
libX11.so.4`XGetSubImage+0x32
libgdk-x11-2.0.so.0.400.9`_gdk_x11_copy_to_image+0x58d
11593
libc.so.1`__pollsys+0x15
libc.so.1`pselect+0x18e
libc.so.1`select+0x82
libX11.so.4`_XWaitForReadable+0xcf
libX11.so.4`_XRead+0xa9
libX11.so.4`_XReply+0xce
libX11.so.4`XGetImage+0x9f
libX11.so.4`XGetSubImage+0x32
13532
libc.so.1`__pollsys+0x15
libc.so.1`pselect+0x18e
libc.so.1`select+0x82
libX11.so.4`_XWaitForReadable+0xcf
libX11.so.4`_XRead+0xa9
libX11.so.4`_XReply+0xce
libX11.so.4`XGetImage+0x9f
libXft.so.2`XftGlyphFontSpecCore+0x45b
libXft.so.2`XftDrawGlyphFontSpec+0x124
libXft.so.2`XftDrawCharFontSpec+0xb1
libvte.so.4.4.0`_vte_xft_draw_text+0x238
22236
libc.so.1`__pollsys+0x15
libc.so.1`pselect+0x18e
libc.so.1`select+0x82
libX11.so.4`_XWaitForReadable+0xcf
libX11.so.4`_XReadPad+0xea
libX11.so.4`XGetImage+0xea
libXft.so.2`XftGlyphFontSpecCore+0x45b
libXft.so.2`XftDrawGlyphFontSpec+0x124
libXft.so.2`XftDrawCharFontSpec+0xb1
libvte.so.4.4.0`_vte_xft_draw_text+0x238
34983
Perfeito, agora sabemos como estamos chegando nas chamadas
pollsys, e temos esta informação agrupada por "ustack" (user
stack). Agora temos a oportunidade de identificar as fron-
teiras entre bibliotecas, e fica mais fácil isolar o problema.
Com base no exposto acima, constatamos que quase totalidade das chamadas
pollsys(2), são originadas na biblioteca libX11.so.4, na função
_XWaitForReadable. Para comprovarmos esta teoria, precisamos de um
script D que explore o provider PID.
+------------------------------------------------------------+
| PROGRAMA: pid.d |
+------------------------------------------------------------+
| #!/usr/sbin/dtrace -s |
| #pragma D option quiet |
| int x; |
| |
| pid$1:libX11:_XWaitForReadable:entry |
| { |
| self->ENTRADA = timestamp; |
| x = x + 1; |
| } |
| |
| pid$1:libX11:_XWaitForReadable:return |
| /self->ENTRADA/ |
| { |
| this->SAIDA = timestamp - self->ENTRADA; |
| this->TIME = ( this->SAIDA / 1000000 ); |
| printf("%10d : %10d millisecondsn", x, this->TIME); |
| self->ENTRADA = 0; |
| } |
+------------------------------------------------------------+
./pid.d `pgrep gnome-terminal` > /tmp/latencia.log
awk '{print $3}' /tmp/latencia.log | /home/leal/p/tools/report.pl
ops: 80577
max: 220
min: 0
med: 29
avg: 2.46742867071249
sum: 198818 <===== 3,3 minutos
dev: 5.02238185341986
6. CONCLUSÃO
Poderíamos continuar esta investigação por bastante tempo,
mas já conseguimos identificar a causa do atraso na nossa ta-
refa de sincronismo, e também pudemos perceber o poder desta
ferramenta DTrace. Com scripts realmente simples, e uma noção
básica de como os sistemas POSIX funcionam, fica relativamente
fácil iniciarmos a utilização desta ferramenta e como conse-
quência, identificar a causa de problemas.
