Подтвердить что ты не робот

Где происходит отсрочка HTTP POST?

Я разрабатываю веб-службу на Ubuntu 14.04 на С++, используя cpp-netlib в асинхронном режиме. Служба должна отвечать на данные, отправленные через HTTP POST в теле сообщения. Я наблюдаю плохую производительность при приеме ввода более 1К, и я хочу это исправить.

Если данные относительно малы, менее 1 КБ, сервер получает данные почти мгновенно. Если данные составляют более 1 КБ, после первой функции обратного вызова асинхронного считывания происходит примерно одна секундная задержка до того, как первый фрагмент фактических данных будет представлен обратному вызову. После начальной задержки последующие куски поступают почти мгновенно.

Как я могу устранить эту задержку? Является ли это артефактом использования curl для публикации тестовых данных? Как я могу легко проверить производительность завитка для публикации данных?

Вы можете найти минимальный исходный код, демонстрирующий проблему на github. Вот команда, которую я использую для отправки данных на сервер:

rcook$ curl -d @AsyncDaemon.h http://localhost:8787/foo

Здесь приведен пример его вывода (аннотированный):

rcook$ ./async_daemon 
1431387368.321863: AsyncDaemon constructor
1431387368.322446: receive thread beginning

*** It waiting for a connection here.

1431387371.536191: begin transaction 0 on thread 24050
1431387371.536237: transaction 0 constructor
1431387371.536273: received 1206 byte request for /foo from 127.0.0.1:49402
1431387371.536312: invoked asynchronous read
1431387371.536321: end transaction handler
1431387371.536335: begin asynchronous read callback on thread 24050
1431387371.536348: read 0 bytes
1431387371.536386: invoked asynchronous read
1431387371.536394: end asynchronous read callback

*** The asynchronous read callback is invoked quickly, but gets no data.
*** There is then a pause of just over one second before the asynchronous
*** read callback is invoked again.

1431387372.537203: begin asynchronous read callback on thread 24050
1431387372.537253: read 1024 bytes
1431387372.537307: invoked asynchronous read
1431387372.537317: end asynchronous read callback

*** There is no significant delay when reading the next chunk.

1431387372.537429: begin asynchronous read callback on thread 24050
1431387372.537469: read 182 bytes
1431387372.537478: finished reading the body
1431387372.537746: wrote response
1431387372.537763: transaction 0 destructor
1431387372.537772: end asynchronous read callback

*** The server is then killed with a keyboard interrupt.

^C1431387375.382186: terminating with signal 2
1431387375.382231: initiating shutdown
1431387375.382241: stopping server
1431387375.382363: server run finished
1431387375.382423: receive thread ending
1431387375.382522: AsyncDaemon destructor

Как вы можете видеть, после первого обращения к асинхронному обратному вызову (и получает нулевые байты данных, BTW), он запрашивает другой блок ввода. На этом этапе происходит пауза чуть более одной секунды, прежде чем этот вход поступит, от 1431387371.536394 до 1431387372.537203 в этом примере. Что происходит в это время? Как я могу устранить эту задержку?

Я провел несколько исследований в Интернете и провел несколько экспериментов (синхронный или асинхронный режим с cpp-netlib (без эффекта), curl vs. libcurl (без эффекта)), но не смог найти ответ.

Обновление: Дамп TCP

По предложению jxh я запустил дамп tcp во время выборочной транзакции:

00:28:01.304446 IP6 localhost.52265 > localhost.8787: Flags [S], seq 3956487146, win 43690, options [mss 65476,sackOK,TS val 395479802 ecr 0,nop,wscale 7], length 0
00:28:01.304461 IP6 localhost.8787 > localhost.52265: Flags [R.], seq 0, ack 3956487147, win 0, length 0
00:28:01.305014 IP localhost.49421 > localhost.8787: Flags [S], seq 1668603425, win 43690, options [mss 65495,sackOK,TS val 395479803 ecr 0,nop,wscale 7], length 0
00:28:01.305039 IP localhost.8787 > localhost.49421: Flags [S.], seq 4010788604, ack 1668603426, win 43690, options [mss 65495,sackOK,TS val 395479803 ecr 395479803,nop,wscale 7], length 0
00:28:01.305079 IP localhost.49421 > localhost.8787: Flags [.], ack 1, win 342, options [nop,nop,TS val 395479803 ecr 395479803], length 0
00:28:01.305185 IP localhost.49421 > localhost.8787: Flags [P.], seq 1:176, ack 1, win 342, options [nop,nop,TS val 395479803 ecr 395479803], length 175
00:28:01.305210 IP localhost.8787 > localhost.49421: Flags [.], ack 176, win 350, options [nop,nop,TS val 395479803 ecr 395479803], length 0
00:28:02.306555 IP localhost.49421 > localhost.8787: Flags [P.], seq 176:1382, ack 1, win 342, options [nop,nop,TS val 395480053 ecr 395479803], length 1206
00:28:02.306620 IP localhost.8787 > localhost.49421: Flags [.], ack 1382, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 0
00:28:02.307223 IP localhost.8787 > localhost.49421: Flags [P.], seq 1:52, ack 1382, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 51
00:28:02.307270 IP localhost.49421 > localhost.8787: Flags [.], ack 52, win 342, options [nop,nop,TS val 395480053 ecr 395480053], length 0
00:28:02.307494 IP localhost.8787 > localhost.49421: Flags [P.], seq 52:66, ack 1382, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 14
00:28:02.307522 IP localhost.49421 > localhost.8787: Flags [.], ack 66, win 342, options [nop,nop,TS val 395480053 ecr 395480053], length 0
00:28:02.307765 IP localhost.8787 > localhost.49421: Flags [F.], seq 66, ack 1382, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 0
00:28:02.307867 IP localhost.49421 > localhost.8787: Flags [F.], seq 1382, ack 67, win 342, options [nop,nop,TS val 395480053 ecr 395480053], length 0
00:28:02.307917 IP localhost.8787 > localhost.49421: Flags [.], ack 1383, win 1373, options [nop,nop,TS val 395480053 ecr 395480053], length 0

Я не очень опытен с tcpdump, но он похож на поток 175 байтов на сервер (заголовки HTTP?), затем после задержки чуть более одной секунды на сервер отправляется 1206 байт, за которым следует 51 байтовый блок с минимальной задержкой, за которым следует ответ сервера.

Это говорит мне, что задержка вводится на стороне клиента, вероятно, в curl. Кто-нибудь знает, почему?

4b9b3361

Ответ 1

Проблема решена благодаря методам отладки и диагностики, предложенным @jxh.

Добавление --trace - --trace-time в команду curl показало, что завиток проводил эту загадочную секунду, ожидая, что сервер вернет ответ 100 Continue, прежде чем отправит остальную часть запроса:

01:31:44.043611 == Info: Connected to localhost (127.0.0.1) port 8787 (#0)
01:31:44.043726 => Send header, 175 bytes (0xaf)
0000: 50 4f 53 54 20 2f 66 6f 6f 20 48 54 54 50 2f 31 POST /foo HTTP/1
0010: 2e 31 0d 0a 55 73 65 72 2d 41 67 65 6e 74 3a 20 .1..User-Agent: 
0020: 63 75 72 6c 2f 37 2e 33 35 2e 30 0d 0a 48 6f 73 curl/7.35.0..Hos
0030: 74 3a 20 6c 6f 63 61 6c 68 6f 73 74 3a 38 37 38 t: localhost:878
0040: 37 0d 0a 41 63 63 65 70 74 3a 20 2a 2f 2a 0d 0a 7..Accept: */*..
0050: 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20 Content-Length: 
0060: 31 32 30 36 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79 1206..Content-Ty
0070: 70 65 3a 20 61 70 70 6c 69 63 61 74 69 6f 6e 2f pe: application/
0080: 78 2d 77 77 77 2d 66 6f 72 6d 2d 75 72 6c 65 6e x-www-form-urlen
0090: 63 6f 64 65 64 0d 0a 45 78 70 65 63 74 3a 20 31 coded..Expect: 1
00a0: 30 30 2d 63 6f 6e 74 69 6e 75 65 0d 0a 0d 0a    00-continue....
01:31:45.045626 == Info: Done waiting for 100-continue
01:31:45.045831 => Send data, 1206 bytes (0x4b6)

Это известный недостаток в cpp-netlib (по крайней мере, начиная с версии 0.11.0), что он не поддерживает отправку ответа 100 Continue, который ожидает завиток.

Затем решение стало убедительным завитком, чтобы не дождаться ответа 100 Continue. Как я здесь обнаружил, добавление -H 'Expect:' в командную строку curl делает трюк. При этом вся транзакция занимает около миллисекунды.

Поскольку я ответил на свой вопрос, я не буду принимать свой ответ в течение нескольких недель, чтобы дать другим шанс внести что-то лучше.