LINUX.ORG.RU
ФорумAdmin

Время wait time в Nginx

 , , ,


0

1

Заметил, что в последнее время Nginx ведет себя странно. Меряю время загрузки страницы с помощью Pingdom tools. Получается, что wait time, время ожидания до получения первого байта от веб-сервера после отправки запроса составляет до 200мс для статики и около 300-400 для динамического контента. Это слишком много, так как допустим, если на странице загружается много файлов, изображений, то загрузка может затянуться больше 10 секунд. Но временами, это же самое wait time для статики уменьшается до 10-30мс, тогда сайт начинает летать. Причем, это не зависит от нагрузки на сервер, тестировал на другом сервере, который используется для тестов и не нагружен. Никакие настройки не изменялись. В чем может быть причина такого падения скорости и как сделать, чтобы скорость постоянно была 20-30мс для статики? Для размещения сайта использую VPS.

Вот конфигурационный файл nginx:

user  apache;
worker_processes auto;

events {
        worker_connections 768;
        multi_accept on;
        use epol;
}

http {

        ##
        # Basic Settings
        ##

        sendfile on;
        tcp_nopush on;
        tcp_nodelay on;
        keepalive_timeout 65;
        types_hash_max_size 2048;
        fastcgi_buffers 8 16k;
        fastcgi_buffer_size 32k;
        fastcgi_connect_timeout 300;
        fastcgi_send_timeout 300;
        fastcgi_read_timeout 300;

        proxy_connect_timeout 900;
        proxy_send_timeout 900;
        proxy_read_timeout 900;
        send_timeout 900;


       include /etc/nginx/mime.types;
        default_type application/octet-stream;

        ##
        # SSL Settings
        ##

        ssl_protocols TLSv1 TLSv1.1 TLSv1.2; # Dropping SSLv3, ref: POODLE
        ssl_prefer_server_ciphers on;

        ##
        # Logging Settings
        ##

        access_log /var/log/nginx/access.log;
        # Logging Settings
        ##

        access_log /var/log/nginx/access.log;
        error_log /var/log/nginx/error.log;

        ##
        # Gzip Settings
        ##

        gzip on;
        gzip_disable "msie6";

        gzip_vary on;
        gzip_proxied any;
        gzip_comp_level 6;
        gzip_buffers 16 8k;
        gzip_http_version 1.1;
        gzip_types text/plain text/css application/json application/javascript text/xml application/xml application/xml+rss text/javascript;
        include /etc/nginx/sites-enabled/*;

Вот результат тестирования VPS с помощью UnixBench:

   BYTE UNIX Benchmarks (Version 5.1.3)

   System: losst-2: GNU/Linux
   OS: GNU/Linux -- 3.10.0-514.26.2.el7.x86_64 -- #1 SMP Tue Jul 4 15:04:05 UTC 2017
   Machine: x86_64 (x86_64)
   Language: en_US.utf8 (charmap="UTF-8", collate="UTF-8")
   CPU 0: QEMU Virtual CPU version (cpu64-rhel6) (5333.5 bogomips)
          x86-64, MMX, Physical Address Ext, SYSENTER/SYSEXIT, SYSCALL/SYSRET
   CPU 1: QEMU Virtual CPU version (cpu64-rhel6) (5333.5 bogomips)
          x86-64, MMX, Physical Address Ext, SYSENTER/SYSEXIT, SYSCALL/SYSRET
   12:55:56 up 1 day, 18:05,  2 users,  load average: 0.03, 0.12, 0.09; runlevel 3

------------------------------------------------------------------------
Benchmark Run: Чтв Авг 10 2017 12:55:56 - 13:24:06
2 CPUs in system; running 1 parallel copy of tests

Dhrystone 2 using register variables       28284808.1 lps   (10.0 s, 7 samples)
Double-Precision Whetstone                     3417.1 MWIPS (9.9 s, 7 samples)
Execl Throughput                               2078.3 lps   (29.9 s, 2 samples)
File Copy 1024 bufsize 2000 maxblocks        637104.1 KBps  (30.0 s, 2 samples)
File Copy 256 bufsize 500 maxblocks          183080.3 KBps  (30.0 s, 2 samples)
File Copy 4096 bufsize 8000 maxblocks       1412563.7 KBps  (30.0 s, 2 samples)
Pipe Throughput                             1210675.2 lps   (10.0 s, 7 samples)
Pipe-based Context Switching                 211182.8 lps   (10.0 s, 7 samples)
Process Creation                               4979.9 lps   (30.0 s, 2 samples)
Shell Scripts (1 concurrent)                   5245.5 lpm   (60.0 s, 2 samples)
Shell Scripts (8 concurrent)                   1115.6 lpm   (60.0 s, 2 samples)
System Call Overhead                        1790964.8 lps   (10.0 s, 7 samples)

System Benchmarks Index Values               BASELINE       RESULT    INDEX
Dhrystone 2 using register variables         116700.0   28284808.1   2423.7
Double-Precision Whetstone                       55.0       3417.1    621.3
Execl Throughput                                 43.0       2078.3    483.3
File Copy 1024 bufsize 2000 maxblocks          3960.0     637104.1   1608.8
File Copy 256 bufsize 500 maxblocks            1655.0     183080.3   1106.2
File Copy 4096 bufsize 8000 maxblocks          5800.0    1412563.7   2435.5
Pipe Throughput                               12440.0    1210675.2    973.2
Pipe-based Context Switching                   4000.0     211182.8    528.0
Process Creation                                126.0       4979.9    395.2
Shell Scripts (1 concurrent)                     42.4       5245.5   1237.1
Shell Scripts (8 concurrent)                      6.0       1115.6   1859.4
System Call Overhead                          15000.0    1790964.8   1194.0
                                                                   ========
System Benchmarks Index Score                                        1048.2

------------------------------------------------------------------------
Benchmark Run: Чтв Авг 10 2017 13:24:06 - 13:52:17
2 CPUs in system; running 2 parallel copies of tests

Dhrystone 2 using register variables       55151033.7 lps   (10.0 s, 7 samples)
Double-Precision Whetstone                     6812.5 MWIPS (9.8 s, 7 samples)
Execl Throughput                               5184.0 lps   (30.0 s, 2 samples)
File Copy 1024 bufsize 2000 maxblocks       1055425.2 KBps  (30.0 s, 2 samples)
File Copy 256 bufsize 500 maxblocks          301170.4 KBps  (30.0 s, 2 samples)
File Copy 4096 bufsize 8000 maxblocks       2456330.7 KBps  (30.0 s, 2 samples)
Pipe Throughput                             2401592.7 lps   (10.0 s, 7 samples)
Pipe-based Context Switching                 386639.7 lps   (10.0 s, 7 samples)
Process Creation                              16219.0 lps   (30.0 s, 2 samples)
Shell Scripts (1 concurrent)                   8416.6 lpm   (60.0 s, 2 samples)
Shell Scripts (8 concurrent)                   1146.0 lpm   (60.1 s, 2 samples)
System Call Overhead                        3095366.9 lps   (10.0 s, 7 samples)

System Benchmarks Index Values               BASELINE       RESULT    INDEX
Dhrystone 2 using register variables         116700.0   55151033.7   4725.9
Double-Precision Whetstone                       55.0       6812.5   1238.6
Execl Throughput                                 43.0       5184.0   1205.6
File Copy 1024 bufsize 2000 maxblocks          3960.0    1055425.2   2665.2
File Copy 256 bufsize 500 maxblocks            1655.0     301170.4   1819.8
File Copy 4096 bufsize 8000 maxblocks          5800.0    2456330.7   4235.1
Pipe Throughput                               12440.0    2401592.7   1930.5
Pipe-based Context Switching                   4000.0     386639.7    966.6
Process Creation                                126.0      16219.0   1287.2
Shell Scripts (1 concurrent)                     42.4       8416.6   1985.0
Shell Scripts (8 concurrent)                      6.0       1146.0   1910.0
System Call Overhead                          15000.0    3095366.9   2063.6
                                                                   ========
System Benchmarks Index Score                                        1933.2

VPS ваш или где-то далеко? Если у хостера, то может быть забит канал или какой анализатор трафика, создающий задержку...

Можете попробовать запустить на тестовом сервере tcpdump и там по временам пакетов посмотреть, какие задержки на стороне сервера.

mky ★★★★★
()
Ответ на: комментарий от mky

Хостинг в России, спасибо за совет про tcpdump, так и сделал. Но не совсем понимаю что там происходит:

# tcpdump -n -S -s 0 -vvvvv -A '(tcp dst port 80 or tcp src port 80) and (dst host 95.133.238.84 or src host 95.133.238.84)'
tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
13:07:38.192100 IP (tos 0x0, ttl 54, id 13782, offset 0, flags [DF], proto TCP (6), length 60)
    95.133.238.84.fksp-audit > 185.22.173.108.http: Flags [S], cksum 0x6f1a (correct), seq 3645328098, win 29200, options [mss 1460,sackOK,TS val 3768116 ecr 0,nop,wscale 7], length 0
E..<5.@.6.Z._..T...l...P.GJ.......r.o..........
.9.4........
13:07:38.192226 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 60)
    185.22.173.108.http > 95.133.238.84.fksp-audit: Flags [S.], cksum 0xb48b (incorrect -> 0xba49), seq 979556435, ack 3645328099, win 28960, options [mss 1460,sackOK,TS val 843149496 ecr 3768116,nop,wscale 7], length 0
E..<..@.@.._...l_..T.P..:b.S.GJ...q ...........
2Ap..9.4....
13:07:38.261053 IP (tos 0x0, ttl 54, id 13783, offset 0, flags [DF], proto TCP (6), length 52)
    95.133.238.84.fksp-audit > 185.22.173.108.http: Flags [.], cksum 0x5940 (correct), seq 3645328099, ack 979556436, win 229, options [nop,nop,TS val 3768133 ecr 843149496], length 0
E..45.@.6.Z._..T...l...P.GJ.:b.T....Y@.....
.9.E2Ap.
13:07:38.263067 IP (tos 0x0, ttl 54, id 13784, offset 0, flags [DF], proto TCP (6), length 204)
    95.133.238.84.fksp-audit > 185.22.173.108.http: Flags [P.], cksum 0x4a08 (correct), seq 3645328099:3645328251, ack 979556436, win 229, options [nop,nop,TS val 3768133 ecr 843149496], length 152
E...5.@.6.Y._..T...l...P.GJ.:b.T....J......
.9.E2Ap.GET /wp-content/uploads/2017/07/Snimok-ekrana-ot-2017-07-31-18-56-04-300x169.png HTTP/1.1
Host: test.losst.ru
User-Agent: curl/7.50.1
Accept: */*


13:07:38.263094 IP (tos 0x0, ttl 64, id 43177, offset 0, flags [DF], proto TCP (6), length 52)
    185.22.173.108.http > 95.133.238.84.fksp-audit: Flags [.], cksum 0xb483 (incorrect -> 0x585b), seq 979556436, ack 3645328251, win 235, options [nop,nop,TS val 843149567 ecr 3768133], length 0
E..4..@.@......l_..T.P..:b.T.GK{...........
2Ap..9.E
13:07:38.263262 IP (tos 0x0, ttl 64, id 43178, offset 0, flags [DF], proto TCP (6), length 367)
    185.22.173.108.http > 95.133.238.84.fksp-audit: Flags [P.], cksum 0xb5be (incorrect -> 0x1a2c), seq 979556436:979556751, ack 3645328251, win 235, options [nop,nop,TS val 843149567 ecr 3768133], length 315
E..o..@.@......l_..T.P..:b.T.GK{...........
2Ap..9.EHTTP/1.1 200 OK
Server: nginx/1.13.3
Date: Fri, 18 Aug 2017 10:07:38 GMT
Content-Type: image/png
Content-Length: 64904
Last-Modified: Mon, 31 Jul 2017 15:59:44 GMT
Connection: keep-alive
ETag: "597f53f0-fd88"
Expires: Thu, 31 Dec 2037 23:55:55 GMT
Cache-Control: max-age=315360000
Accept-Ranges: bytes


13:07:38.263293 IP (tos 0x0, ttl 64, id 43179, offset 0, flags [DF], proto TCP (6), length 2948)
    185.22.173.108.http > 95.133.238.84.fksp-audit: Flags [.], cksum 0xbfd3 (incorrect -> 0x39f4), seq 979556751:979559647, ack 3645328251, win 235, options [nop,nop,TS val 843149567 ecr 3768133], length 2896
E.....@.@..k...l_..T.P..:b...GK{...........
2Ap..9.E.PNG
.
IHDR...,................	pHYs..........+.....:IDATx...i.-.u&......3.s...y~9=239....)..jU.....0....m.6...v.._n.`......r.`.k.JU.(."%.L.<g.y..<..D..k........Df&s`.`2...q....k......p{.=.>.M...Q.T.S....k....;trr..G....Y[[...)..n.....<....j...t...J.
..R..qL*......#..~........~..~..~irr.......O<...3gn...v...R..G.Y__..r...o}......x...@.;....S(E..._.J
yrzvy........A.....3g._.|...0.?.._...J..#........M.&.b..B...}M2R.F....y...s.....?`.._.O.......&...g..h....rmt.s...O..qurrl}s.......n..827U..G...V^|.u.....?............?.7m(..K......<v...?.Yb.............?.........../7../~...=.\...L.6..'...i.V.?..._....]...9.....ID.......O..w.........[......X[[...A.K...;wnoo.Y....!.1M...TG..g.=...;7....Nsnv.yc.
  • 13:07:38.263067 - отправил запрос GET /wp-content/uploads/2017/07/Snimok-ekrana-ot-2017-07-31-18-56-04-300x169.png HTTP/1.1
  • 13:07:38.263094 - в ответ отправлена какая-то тарабарщина
  • 13:07:38.263262 - отправлен заголовок ответа
  • 13:07:38.263293 - начало передачи изображения

Получается, что время ожидания составило 226 милисикунд для этой картинки. Хотя curl запрос, которым я запросил эту картинку выдал такое:

curl "http://test.losst.ru/wp-content/uploads/2017/07/Snimok-ekrana-ot-2017-07-31-18-56-04-300x169.png" -s -o /dev/null -w "response_code: %{http_code}\

dns_time: %{time_namelookup}\n\
connect_time: %{time_connect}\n\
AppCon time:\t%{time_appconnect}\n\
pretransfer_time: %{time_pretransfer}\n\
starttransfer_time: %{time_starttransfer}\n\
total_time: %{time_total}
"
response_code: 200
dns_time: 0,004
connect_time: 0,074
AppCon time:	0,000
pretransfer_time: 0,074
starttransfer_time: 0,148
total_time: 1,069
Seriyyy95
() автор топика
Ответ на: комментарий от Seriyyy95

Детально не вникал, но на первый взгляд это не тарабарщина, а просто ACK пакеты. Выводится ведь все заголовки (двоичные), а не только содержимое tcp-пакетов.

Так, обычно tcpdump запускается с выводом в файл (опция -w), понятно, что с указанием фильтра, чтобы в файл писались только нужные пакеты, а уже потом можно пакеты из файла выводить в различных форматах, или смотреть в wireshark.

13:07:38.192100 — сервером получен SYN-пакет
13:07:38.192226 — сервером отправлен SYN+ACK-пакет
значит http-сервер принял (accept) соединение

13:07:38.263067 — сервером полуен GET-запрос
13:07:38.263293 — сервер начал передачу файла в формате PNG

В первом случае задержка 116 микросекунд, во втором 226 микросекунды. Именно микро-, а не милли-, http сервер не тормозит.

Но при этом между SYN+ACK от сервера и последующим ACK от клиента задержка 13:07:38.261053 - 13:07:38.192226 = 69 миллисекунд.

Где и почему возникает задержка пакетов понять будет сложно. Записывайте tcpdump на клиенте и на сервере, сравнивайте их. Попробуйте, если есть возможность, с разных ip-адресов клиентов (с разных провайдеров).

ping с клиента до сервера какое время показывает и насколько оно стабильно?

mky ★★★★★
()
Ответ на: комментарий от mky

Если выполнять ping с моего домашнего ip - то 60 миллисекунд:

64 bytes from losst-2 (185.22.173.108): icmp_seq=1 ttl=56 time=66.4 ms
64 bytes from losst-2 (185.22.173.108): icmp_seq=2 ttl=56 time=66.5 ms
64 bytes from losst-2 (185.22.173.108): icmp_seq=3 ttl=56 time=66.9 ms
64 bytes from losst-2 (185.22.173.108): icmp_seq=4 ttl=56 time=70.0 ms
64 bytes from losst-2 (185.22.173.108): icmp_seq=5 ttl=56 time=86.6 ms

С другого VPS в Москве уже 9 миллисекунд:

64 bytes from losst-2 (185.22.173.108): icmp_seq=1 ttl=60 time=9.34 ms
64 bytes from losst-2 (185.22.173.108): icmp_seq=2 ttl=60 time=9.30 ms
64 bytes from losst-2 (185.22.173.108): icmp_seq=3 ttl=60 time=9.33 ms
64 bytes from losst-2 (185.22.173.108): icmp_seq=4 ttl=60 time=9.50 ms
Seriyyy95
() автор топика
Ответ на: комментарий от Seriyyy95

Но, если ping 66-80 мс, то каким образом:

Но временами, это же самое wait time для статики уменьшается до 10-30мс...

Или издредка и пинг становится быстрым?

mky ★★★★★
()
Вы не можете добавлять комментарии в эту тему. Тема перемещена в архив.