Upstream timed out

Igor Sysoev is at rambler-co.ru
Sun Sep 9 11:51:22 MSD 2007


On Sun, Sep 09, 2007 at 10:06:24AM +0300, Vladimir Shiray wrote:

> Потому, что это был первый тест и на нем сразу же посыпались ошибки.
> 
> Внизу четыре новых теста, которые показывают, что проблема возникает
> когда при запросе от nginx "backend" возвращает код возврата "304".
> Особой разницы между удаленным и локальным тестом не наблюдается,
> при обращении напрямую к "backend" данная проблема не проявляется.
> 
> 
> Вот результат удаленного теста (rtt: 60ms) без "-H" для "-c 40"
> 
> siege -c 40 -t 60S http://dev.kbb1.com/icons/blank.gif
> 
> Transactions:                    3984 hits
> Availability:                 100.00 %
> Elapsed time:                  60.48 secs
> Data transferred:               0.56 MB
> Response time:                  0.13 secs
> Transaction rate:              65.87 trans/sec
> Throughput:                     0.01 MB/sec
> Concurrency:                    8.57
> Successful transactions:        3984
> Failed transactions:               0
> Longest transaction:            5.37
> Shortest transaction:           0.12
> 
> И вот результат удаленного теста (rtt: 60ms) с "-H ... -c 5"
> 
> siege -c 5 -t 60S -H "If-Modified-Since: Sat, 20 Nov 2004 20:16:24 GMT" 
> http://dev.kbb1.com/icons/blank.gif
> 
> Transactions:                      16 hits
> Availability:                  76.19 %
> Elapsed time:                  59.64 secs
> Data transferred:               0.00 MB
> Response time:                  0.16 secs
> Transaction rate:               0.27 trans/sec
> Throughput:                     0.00 MB/sec
> Concurrency:                    0.04
> Successful transactions:          16
> Failed transactions:               5
> Longest transaction:            0.47
> Shortest transaction:           0.12
> 
> Результат при обращении напрямую к Apache, минуя nginx, из соседнего
> виртуального окружения.
> 
> siege -c 5 -t 60S -H "If-Modified-Since: Sat, 20 Nov 2004 20:16:24 GMT" 
> http://dev.kbb1.com/icons/blank.gif
> 
> Transactions:                     586 hits
> Availability:                 100.00 %
> Elapsed time:                  60.20 secs
> Data transferred:               0.00 MB
> Response time:                  0.00 secs
> Transaction rate:               9.73 trans/sec
> Throughput:                     0.00 MB/sec
> Concurrency:                    0.01
> Successful transactions:         586
> Failed transactions:               0
> Longest transaction:            0.01
> Shortest transaction:           0.00
> 
> Результат при обращении через nginx, из соседнего
> виртуального окружения.
> 
> siege -c 5 -t 60S -H "If-Modified-Since: Sat, 20 Nov 2004 20:16:24 GMT" 
> http://dev.kbb1.com/icons/blank.gif
> 
> Transactions:                      14 hits
> Availability:                  73.68 %
> Elapsed time:                  60.42 secs
> Data transferred:               0.00 MB
> Response time:                  0.00 secs
> Transaction rate:               0.23 trans/sec
> Throughput:                     0.00 MB/sec
> Concurrency:                    0.00
> Successful transactions:          14
> Failed transactions:               5
> Longest transaction:            0.01
> Shortest transaction:           0.00

Пришлите мне отладочный лог тестирования с ошибками.

> Alexey Karagodov wrote:
> >на апач напрямую тоже самое ... а почему -c 5 ? отчего так мало?
> >
> >2007/9/7, Vladimir Shiray <vlad at kbb1.com>:
> >  
> >>С ним все по другому. Сразу же посыпались таймауты.
> >>Хотя он и не дожидается таймаута nginx (120с), а срабатывает его
> >>собственный (30с).
> >>
> >>siege -d 2 -c 5 -t 180S -H "If-Modified-Since: Sat, 20 Nov 2004 20:16:24
> >>GMT" http://dev.kbb1.com/icons/blank.gif
> >>
> >>Lifting the server siege...      done.
> >>Transactions:                      36 hits
> >>Availability:                  65.45 %
> >>Elapsed time:                 180.24 secs
> >>Data transferred:               0.00 MB
> >>Response time:                  3.73 secs
> >>Transaction rate:               0.20 trans/sec
> >>Throughput:                     0.00 MB/sec
> >>Concurrency:                    0.75
> >>Successful transactions:          36
> >>Failed transactions:              19
> >>Longest transaction:           15.48
> >>Shortest transaction:           0.44
> >>
> >>Если убрать параметр "-H" из теста, то все проходит без проблем.
> >>При этом кол-во транзакций получается значительно больше.
> >>
> >>siege -d 2 -c 5 -t 180S  http://dev.kbb1.com/icons/blank.gif
> >>
> >>Lifting the server siege...      done.
> >>Transactions:                     588 hits
> >>Availability:                 100.00 %
> >>Elapsed time:                 180.51 secs
> >>Data transferred:               0.08 MB
> >>Response time:                  0.50 secs
> >>Transaction rate:               3.26 trans/sec
> >>Throughput:                     0.00 MB/sec
> >>Concurrency:                    1.64
> >>Successful transactions:         588
> >>Failed transactions:               0
> >>Longest transaction:            3.59
> >>Shortest transaction:           0.41
> >>
> >>
> >>Alexey Karagodov wrote:
> >>    
> >>>помучай его siege-ем например, нгинх, апач и т.д., чего получится
> >>>
> >>>07.09.07, Vladimir Shiray<vlad at kbb1.com> написал(а):
> >>>
> >>>      
> >>>>Igor Sysoev wrote:
> >>>>
> >>>>        
> >>>>>On Fri, Sep 07, 2007 at 01:36:43PM +0300, Vladimir Shiray wrote:
> >>>>>
> >>>>>
> >>>>>
> >>>>>          
> >>>>>>Igor Sysoev wrote:
> >>>>>>
> >>>>>>
> >>>>>>            
> >>>>>>>On Thu, Sep 06, 2007 at 11:12:25AM +0300, Vladimir Shiray wrote:
> >>>>>>>
> >>>>>>>
> >>>>>>>
> >>>>>>>
> >>>>>>>              
> >>>>>>>>в error.log постоянно попадают ошибки, типа:
> >>>>>>>>   "upstream timed out (110: Connection timed out) while reading
> >>>>>>>>   upstream"
> >>>>>>>>
> >>>>>>>>После очистки лога и перезапуска nginx, на 150000 подключений
> >>>>>>>>получил 426 таких сообщений.
> >>>>>>>>
> >>>>>>>>Сам сервер запущен внутри OpenVZ окружения (CentOS 4.5 32bit). Перед
> >>>>>>>>последними
> >>>>>>>>проверками, окружение было остановлено и запущено снова.
> >>>>>>>>В /proc/user_beancounters и в логах ядра 
> >>>>>>>>(2.6.18-ovz028stab039.1-smp)
> >>>>>>>>все "чисто".
> >>>>>>>>
> >>>>>>>>У сервера есть три upstream, один докальный в "соседнем" VPS и два
> >>>>>>>>удаленных
> >>>>>>>>(rtt: 150ms и 60ms). Ошибки присутствуют для каждого из них.
> >>>>>>>>
> >>>>>>>>------
> >>>>>>>>
> >>>>>>>>nginx-0.5.29  (c двумя патчами: patch-0.6.2.2, patch-0.6.5.1)
> >>>>>>>>
> >>>>>>>>
> >>>>>>>>
> >>>>>>>>                
> >>>>>>>Как уже посоветовали, можно логировать $upstream_response_time
> >>>>>>>
> >>>>>>>Эти ошибки на https'ных соединениях с бэкендами или на обычных ?
> >>>>>>>
> >>>>>>>
> >>>>>>>
> >>>>>>>
> >>>>>>>              
> >>>>>>Игорь, похоже ошибка появляется когда "backend" возвращает код "304".
> >>>>>>Я проверил все последние локальные ошибки из error.log и в access.log
> >>>>>>у всех из них стоит код 304.
> >>>>>>
> >>>>>>В моем предыдущем ответе на сообщение от "umask" есть также
> >>>>>>соответствующие строки лога из Apache.
> >>>>>>
> >>>>>>
> >>>>>>            
> >>>>>Вот этот запрос - /icons/blank.gif всегда заканичвается таймаутом или 
> >>>>>нет ?
> >>>>>
> >>>>>
> >>>>>
> >>>>>          
> >>>>Нет. Большая часть запрососв проходит нормально.
> >>>>
> >>>>Нагрузка на локальный backend очень небольшая,
> >>>>поэтому сложно получить частоту появления таких ошибок.
> >>>>
> >>>>Пробовал пускать ab  с удаленного сервера, но для такого простого теста
> >>>>ошибка не проявляется. Внизу результаты. Тоже самое пускал и с
> >>>>ключом "-k" - никакой существенной разницы.
> >>>>
> >>>>ab -n 100 -c 2 -H "If-Modified-Since: Sat, 20 Nov 2004 20:16:24 GMT"
> >>>>http://dev.kbb1.com/icons/blank.gif
> >>>>
> >>>>Server Software:        nginx/0.5.29
> >>>>Server Hostname:        dev.kbb1.com
> >>>>Server Port:            80
> >>>>
> >>>>Document Path:          /icons/blank.gi
> >>>>Document Length:        1029 bytes
> >>>>
> >>>>Concurrency Level:      2
> >>>>Time taken for tests:   22.600107 seconds
> >>>>Complete requests:      100
> >>>>Failed requests:        0
> >>>>Write errors:           0
> >>>>Non-2xx responses:      100
> >>>>Total transferred:      130000 bytes
> >>>>HTML transferred:       102900 bytes
> >>>>Requests per second:    4.42 [#/sec] (mean)
> >>>>Time per request:       452.002 [ms] (mean)
> >>>>Time per request:       226.001 [ms] (mean, across all concurrent 
> >>>>requests)
> >>>>Transfer rate:          5.58 [Kbytes/sec] received
> >>>>
> >>>>Connection Times (ms)
> >>>>              min  mean[+/-sd] median   max
> >>>>Connect:      196  224  11.0    226     240
> >>>>Processing:   200  227  11.0    227     245
> >>>>Waiting:      199  226  11.1    227     244
> >>>>Total:        396  451  21.5    454     484
> >>>>
> >>>>Percentage of the requests served within a certain time (ms)
> >>>>  50%    454
> >>>>  66%    467
> >>>>  75%    470
> >>>>  80%    473
> >>>>  90%    478
> >>>>  95%    480
> >>>>  98%    483
> >>>>  99%    484
> >>>> 100%    484 (longest request)
> >>>>
> >>>>
> >>>>        
> >>
> >>    
> 
> 

-- 
Игорь Сысоев
http://sysoev.ru





More information about the nginx-ru mailing list