quarta-feira, 7 de dezembro de 2011

It wasn't lag at all...

Olá a todos...

Bom, vamos lá...
Não é segredo de que o nosso servidor tem se parecido em muito com Final Fantasy XIV... A diferença é que a Square-Enix possui milhões e milhões de dólares para revisar tudo e também possui uma enorme equipe de TI para trabalhar no sistema. O mesmo não ocorre conosco.

O problema inicial no servidor, foi atribuído a lag... Porém depois de dias testando, chegamos a conclusão de que não era lag...

1º teste - sem kafra.conf 09:47 26/11/2011 ~ 10:05 26/11/2011 ::Lagged:: @ 18 minutes 
2º teste - sem experience.conf 10:08 26/11/2011 ~ 10:16 26/11/2011 ::Lagged:: @ 8 minutes 
3º teste - sem arsinoe.conf 10:13 26/11/2011 ~ 10:29 26/11/2011 ::Lagged:: @ 16 minutes 
4º teste -  sem global function.conf 10:32 26/11/2011 ~ 10:51 26/11/2011 ::Lagged:: @ 19 minutes 
5º teste - sem cashshop.conf 10:53 26/11/2011 ~ 10:59 26/11/2011 ::Lagged:: @ 6 minutes 
6º teste - sem mapflags e warps.conf 11:03 26/11/2011 ~ 11:07 26/11/2011 ::Lagged:: @ 4 minutes 
7º teste - sem monster e athena.conf 11:09 26/11/2011 ~ 11:49 26/11/2011 ::No Lag:: @ 40 minutes 
8º teste - sem jobs.conf 11:53 26/11/2011 ~ 11:56 26/11/2011 ::Lagged:: @ 3 minutes 
9º teste - sem monster.conf 11:59 26/11/2011 ~ 12:18 26/11/2011 ::Lagged:: @ 19 minutes 
==========================================
::Testes dentro do athena.conf:: 1º teste - sem cidades 12:24 26/11/2011 ~ 12:28 26/11/2011 ::Lagged:: @ 4 minutes 
2º teste -  sem mercantes 12:30 26/11/2011 ~ 12:35 26/11/2011 ::Lagged:: @ 5 minutes 
3º teste - sem airport 12:38 26/11/2011 ~ 12:57 26/11/2011 ::Lagged:: @ 18 minutes 
4º teste - sem quests 13:01 26/11/2011 ~ 13:09 26/11/2011 ::Lagged:: @ 8 minutes 
5º teste - sem guias 13:15 26/11/2011 ~ 13:39 26/11/2011 ::Lagged:: @ 20 minutes 
6º teste - sem Kafras e DTS e eventos 19:39 26/11/2011 ~ 20:34 26/11/2011 ::Lagged:: @ 20 minutes 
7º teste - sem others 11:21 27/11/2011 ~ 11:23 27/11/2011 ::Lagged:: @ 2 minutes Confirmed @ 11:34 27/11/2011 
8º teste - sem turbo track 11:37 27/11/2011 ~ 11:51 27/11/2011 ::Lagged:: @ 14 minutes Confirmed @ 12:00 27/11/2011 
9º teste - sem battle arena 12:03 27/11/2011 ~ 12:06 27/11/2011 ::Lagged:: @ 3 minutes 
10º teste - sem Monster Races 12:10 27/11/2011 ~ 12:13 27/11/2011 ::Lagged:: @ 3 minutes 
========================================== 
::Teste dentro do Kafra Folder:: 1º test - no functions_kafras 12:17 27/11/2011 ~ 12:20 27/11/2011 ::Lagged:: @ 3 minutes Confirmed @ 12:26 27/11/2011 
2º test - no cool_event_corp 22:43 27/11/2011 ~ 22:45 27/11/2011 ::Lagged:: @ 2 minutes 
3º test - no dts_warper 22:52 27/11/2011 ~ 23:07 27/11/2011 ::Lagged:: @ 15 minutes 


Como observado, retiramos todos os scripts do servidor e mesmo assim o dito lag continuou. Isso me deixou curioso, então retirei todos os scripts e não tivemos nenhum lag...
Isso chamou minha atenção, e começamos a reparar no lag spike, sua ocorrência e seus efeitos... Então chegamos a conclusão de que não era um lag.
Aqui está um Tracert que realizei no momento de um lag spike de aproximadamente 5 segundos:
  1     1 ms     1 ms     1 ms  192.168.1.1  2    28 ms    24 ms    26 ms  c9524001.virtua.com.br  3    36 ms    32 ms    27 ms  c9520001.virtua.com.br  4    46 ms    34 ms    41 ms  embratel-G0-5-3-3-tacc01.cas.embratel.net.br   5   168 ms   170 ms   145 ms  ebt-T0-5-2-0-tcore02.cas.embratel.net.br   6   160 ms   151 ms   159 ms  ebt-T0-0-0-10-tcore01.spoph.embratel.net.br   7   162 ms   153 ms   135 ms  ebt-Bundle-POS1084-intl04.mianap.embratel.net.br   8   182 ms   176 ms   163 ms  xe-0-3-0-4.r05.miamfl02.us.bb.gin.ntt.net   9   177 ms   206 ms   207 ms  te4-5.ccr02.mia03.atlas.cogentco.com  10   231 ms   206 ms   207 ms  te7-7.ccr02.mia01.atlas.cogentco.com  11   183 ms   171 ms   166 ms  te0-2-0-6.ccr22.iah01.atlas.cogentco.com  12   198 ms   197 ms   201 ms  te0-2-0-3.ccr22.lax01.atlas.cogentco.com  13   204 ms   205 ms   204 ms  te4-3.ccr01.las02.atlas.cogentco.com 14   201 ms   214 ms   213 ms  38.122.78.10 15   214 ms   224 ms   221 ms  webrulon-gw.las1.fiberhub.net 16   204 ms   206 ms   198 ms  208.93.152.22 17   177 ms   238 ms   204 ms  199.167.192.89


Como podem observar, não houve packet loss. Ou seja, sem razão para um freeze como estávamos tendo...
Foi então que passamos a suspeitar de outros fatores... E então chegamos onde estamos hoje, na possibilidade de falta de memória da máquina onde encontra-se o nosso servidor... Como vocês sabem nosso servidor possui uma mecânica diferenciada, além dos mapas feitos pela Aerie Pink, mais scripts do eAmod, mais o src do 3Ceam e Ream, além é claro do sistema do jAthena, ou seja, um servidor que rode o eA normalmente não terá o mesmo desempenho rodando o nosso servidor...
Com isso em mente desligamos a máquina, e religamos efetuando um protocolo de testes de memória, e aqui estão os resultados:

Resultado A (servidor desativado):


top - 15:07:00 up 3 days, 13:18,  1 user,  load average: 0.30, 0.10, 0.03
Tasks:  21 total,   2 running,  19 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:    786432k total,   155324k used,   631108k free,        0k buffers
Swap:        0k total,        0k used,        0k free,        0k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
    1 root      15   0  2156  664  572 S  0.0  0.1   0:11.53 init
 1134 root      15  -4  2260  556  344 S  0.0  0.1   0:00.00 udevd
 1487 root      15   0  1812  616  520 S  0.0  0.1   0:01.29 syslogd
 1505 root      15   0  7204 1064  664 S  0.0  0.1   0:00.05 sshd
 1515 root      18   0  2832  848  680 S  0.0  0.1   0:00.00 xinetd
 1547 root      18   0  3712 1296 1128 S  0.0  0.2   0:00.00 mysqld_safe
 1597 mysql     15   0  137m  24m 5392 S  0.0  3.2   2:36.87 mysqld
 1809 root      15   0  9304 1672  664 S  0.0  0.2   0:15.48 sendmail
 1817 smmsp     16   0  8256 1476  608 S  0.0  0.2   0:00.01 sendmail
 1827 root      15   0 10036 2840 1440 S  0.0  0.4   0:21.44 httpd
 1828 apache    16   0 10036 2660 1188 S  0.0  0.3   0:00.00 httpd
 1836 root      15   0  4492 1100  560 S  0.0  0.1   0:01.00 crond
 1844 root      18   0  5680  700  424 S  0.0  0.1   0:00.00 saslauthd
 1845 root      18   0  5680  440  164 S  0.0  0.1   0:00.00 saslauthd
 1860 apache    15   0 10036 2660 1188 S  0.0  0.3   0:00.01 httpd
 7684 apache    16   0 10036 2652 1188 S  0.0  0.3   0:00.00 httpd
 7686 apache    16   0 10036 2652 1188 S  0.0  0.3   0:00.00 httpd
 7688 apache    15   0 10036 2652 1188 S  0.0  0.3   0:00.00 httpd
 9430 root      18   0 10040 3240 2692 R  0.0  0.4   0:00.03 sshd
 9432 root      18   0  3716 1528 1264 S  0.0  0.2   0:00.02 bash
 9465 root      18   0  2288 1016  816 R  0.0  0.1   0:00.00 top
Resultado B (servidor ativado sem scripts):


top - 15:08:13 up 3 days, 13:19,  1 user,  load average: 1.10, 0.36, 0.12
Tasks:  27 total,   2 running,  25 sleeping,   0 stopped,   0 zombie
Cpu(s):  1.3%us,  0.5%sy,  0.0%ni, 50.0%id, 48.2%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:    786432k total,   339892k used,   446540k free,        0k buffers
Swap:        0k total,        0k used,        0k free,        0k cached


PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 9481 root      18   0  173m 151m 2064 D  3.3 19.7   0:01.32 map-server_sql
    1 root      15   0  2156  664  572 S  0.0  0.1   0:11.53 init
 1134 root      15  -4  2260  556  344 S  0.0  0.1   0:00.00 udevd
 1487 root      15   0  1812  616  520 S  0.0  0.1   0:01.29 syslogd
 1505 root      15   0  7204 1064  664 S  0.0  0.1   0:00.05 sshd
 1515 root      18   0  2832  848  680 S  0.0  0.1   0:00.00 xinetd
 1547 root      18   0  3712 1296 1128 S  0.0  0.2   0:00.00 mysqld_safe
 1597 mysql     15   0  137m  24m 5392 S  0.0  3.2   2:36.91 mysqld
 1809 root      15   0  9304 1672  664 S  0.0  0.2   0:15.49 sendmail
 1817 smmsp     16   0  8256 1476  608 S  0.0  0.2   0:00.01 sendmail
 1827 root      18   0 10036 2840 1440 S  0.0  0.4   0:21.45 httpd
 1828 apache    16   0 10036 2660 1188 S  0.0  0.3   0:00.00 httpd
 1836 root      15   0  4492 1100  560 S  0.0  0.1   0:01.00 crond
 1844 root      18   0  5680  700  424 S  0.0  0.1   0:00.00 saslauthd
 1845 root      18   0  5680  440  164 S  0.0  0.1   0:00.00 saslauthd
 1860 apache    15   0 10036 2660 1188 S  0.0  0.3   0:00.01 httpd
 7684 apache    16   0 10036 2652 1188 S  0.0  0.3   0:00.00 httpd
 7686 apache    16   0 10036 2652 1188 S  0.0  0.3   0:00.00 httpd
 7688 apache    15   0 10036 2652 1188 S  0.0  0.3   0:00.00 httpd
 9430 root      15   0 10040 3240 2692 S  0.0  0.4   0:00.04 sshd
 9432 root      15   0  3716 1528 1264 S  0.0  0.2   0:00.02 bash
 9475 root      15   0  4152 1048  640 S  0.0  0.1   0:00.00 screen
 9477 root      15   0  4152 1072  640 S  0.0  0.1   0:00.00 screen
 9479 root      18   0  4284 1172  640 R  0.0  0.1   0:00.00 screen
 9480 root      15   0 12600 3184 1656 S  0.0  0.4   0:00.00 char-server_sql
 9482 root      18   0 12220 2900 1596 S  0.0  0.4   0:00.00 login-server_sq
 9483 root      15   0  2288 1008  812 R  0.0  0.1   0:00.01 top


Resultado C (servidor ativado com scripts):

top - 15:20:59 up 3 days, 13:32,  2 users,  load average: 0.24, 0.49, 0.39
Tasks:  30 total,   2 running,  28 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.7%us,  0.2%sy,  0.0%ni, 99.1%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:    786432k total,   434028k used,   352404k free,        0k buffers
Swap:        0k total,        0k used,        0k free,        0k cached

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 9481 root      15   0  258m 237m 2776 S  1.3 35.5   0:07.66 map-server_sql
    1 root      15   0  2156  664  572 S  0.0  0.1   0:11.54 init
 1134 root      15  -4  2260  556  344 S  0.0  0.1   0:00.00 udevd
 1487 root      15   0  1812  616  520 S  0.0  0.1   0:01.29 syslogd
 1505 root      15   0  7204 1064  664 S  0.0  0.1   0:00.06 sshd
 1515 root      18   0  2832  848  680 S  0.0  0.1   0:00.00 xinetd
 1547 root      18   0  3712 1296 1128 S  0.0  0.2   0:00.00 mysqld_safe
 1597 mysql     15   0  137m  24m 5392 S  0.0  3.2   2:37.40 mysqld
 1809 root      15   0  9304 1672  664 S  0.0  0.2   0:15.52 sendmail
 1817 smmsp     16   0  8256 1476  608 S  0.0  0.2   0:00.01 sendmail
 1827 root      15   0 10036 2840 1440 S  0.0  0.4   0:21.52 httpd
 1828 apache    16   0 10036 2660 1188 S  0.0  0.3   0:00.00 httpd
 1836 root      15   0  4492 1100  560 S  0.0  0.1   0:01.00 crond
 1844 root      18   0  5680  700  424 S  0.0  0.1   0:00.00 saslauthd
 1845 root      18   0  5680  440  164 S  0.0  0.1   0:00.00 saslauthd
 1860 apache    15   0 10036 2660 1188 S  0.0  0.3   0:00.01 httpd
 7684 apache    16   0 10036 2652 1188 S  0.0  0.3   0:00.00 httpd
 7686 apache    16   0 10036 2652 1188 S  0.0  0.3   0:00.00 httpd
 7688 apache    15   0 10036 2652 1188 S  0.0  0.3   0:00.00 httpd
 9430 root      18   0 10200 3252 2692 S  0.0  0.4   0:00.09 sshd
 9432 root      15   0  3716 1528 1264 S  0.0  0.2   0:00.03 bash
 9475 root      15   0  4152 1060  640 S  0.0  0.1   0:00.00 screen
 9477 root      15   0  4152 1084  640 S  0.0  0.1   0:00.00 screen
 9479 root      18   0  4284 1188  640 S  0.0  0.2   0:00.07 screen
 9480 root      18   0 13268 3748 1776 S  0.0  0.5   0:00.05 char-server_sql
 9482 root      18   0 12352 3092 1596 S  0.0  0.4   0:00.07 login-server_sq
 9489 root      15   0  2288 1012  812 S  0.0  0.1   0:00.21 top
 9504 root      15   0 10200 3248 2692 R  0.0  0.4   0:00.04 sshd
 9506 root      15   0  3716 1520 1264 S  0.0  0.2   0:00.01 bash
 9530 root      15   0  2288 1016  816 R  0.0  0.1   0:00.04 top

Fica evidente a diferença de consumo nos três resultados. Quando a solicitação de memória no map-server ultrapassa a casa dos 40% o servidor trava até que a memória seja liberada, e então nos deparamos com o que os jogadores pensam ser um LAG, na verdade é um server freeze, ou seja o servidor fica sem memória por um período de tempo e até que o aplicativo devolva a memória, fica tudo parado. Por isso, que não apenas os jogadores congelam, mas os monstros também congelam. Se fosse um lag normal, os jogadores congelariam, mas os monstros continuariam agindo normalmente, inclusive matando os jogadores.

Agora que identificamos o problema, estamos trabalhando na correção do mesmo...

Obrigado pela paciência e suporte...

Nenhum comentário:

Postar um comentário