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