Hey,
Thanks for the reply.
The problem can be repeated easily
- debug.txt : this trace has been generated with CURLOPT_VERBOSE and CURLOPT_STDERRoptions, I don't know if there is a way to include timestamp in the trace
- strace : I've called it with -T, there are time info in system calls and the system calls during the gapare the following ones:
[pid   990] write(23, "09/08/2016 10:16:02 curlWriteCal"..., 60) = 60[pid   990] close(23)                   = 0[pid   990] munmap(0x7fd03ba0b000, 4096) = 0[pid   990] poll([{fd=22, events=POLLIN}], 1, 36) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)[pid   990] poll([{fd=22, events=POLLIN}], 1, 1000) = 1 ([{fd=22, revents=POLLIN}])[pid   990] poll([{fd=22, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 1 ([{fd=22, revents=POLLIN|POLLRDNORM}])[pid   990] recvfrom(22, "oll'\" />\r\n      <var name=\"TELID"..., 1731, 0, NULL, NULL) = 1731[pid   990] time(NULL)                  = 1470730577[pid   990] time(NULL)                  = 1470730577[pid   990] stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0[pid   990] open("/tmp/write.log", O_RDWR|O_CREAT|O_APPEND, 0666) = 23[pid   990] fstat(23, {st_mode=S_IFREG|0660, st_size=153892, ...}) = 0[pid   990] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd03ba0b000[pid   990] write(23, "09/08/2016 10:16:17 curlWriteCal"..., 60) = 60
regardsOliver

      De : Daniel Stenberg <daniel_at_haxx.se>
 À : Farabet Olivier <ofarabet_at_yahoo.fr>; libcurl development <curl-library_at_cool.haxx.se>
 Envoyé le : Mardi 9 août 2016 16h07
 Objet : Re: Abnormal delay while receiving answer from a POST
   
Hey,

Your email ended up mostly gibberish in my end.

But I could deduce that there's a delay in reading the body of a response
to a POST. I've never seen anything like that, as the headers seem to arrive
promptly to the callback but not the body.

I don't know of any proper explanation. When reading the body, libcurl will
basically call recv() and then send that data to the callback. My gut reaction
would be to say that libcurl didn't get the data faster, but I realize your
pcap shows it flying over the network with proper speed (frame #62).

Your strace dump has no timing so its not easy to do anything with, like
figuring out if there's a time gap somewhere.

Your delay_debug.txt trace similarly has no timing and it doesn't say anything
about the response body so it doesn't show the problem at all?

Can you repeat the problem easily?

-- 
  / daniel.haxx.se
  

-------------------------------------------------------------------
List admin: https://cool.haxx.se/list/listinfo/curl-library
Etiquette: https://curl.haxx.se/mail/etiquette.html
Received on 2016-08-09