Hi

I am running latest curl binaries bundled with CentOS7 to measure
responsiveness of a website using an example found online.

# rpm -q curl
curl-7.29.0-19.el7.x86_64

A review of the data showed latency I was not expecting.

The curl command I am running is: curl -4 -s http://www.example.com

When I run curl through strace there was a noticeable, always repeatable,
delay between lines 4 and 5 of the following output:

13578 00:54:17.693069 [00007f95081a0f50] close(3) = 0
13578 00:54:17.693274 [00007f950818ba57] madvise(0x7f94fd350000, 8368128,
MADV_DONTNEED) = 0
13578 00:54:17.693406 [00007f9508463e82] _exit(0) = ?
13578 00:54:17.693494 [????????????????] +++ exited with 0 +++
13577 00:54:17.835138 [00007f9508186a4d] <... poll resumed> ) = 0 (Timeout)
13577 00:54:17.835321 [00007fff1affe7d2] clock_gettime(CLOCK_MONOTONIC,
{100585, 105149583}) = 0
13577 00:54:17.835499 [00007fff1affe7d2] clock_gettime(CLOCK_MONOTONIC,
{100585, 105319542}) = 0

Running curl with additional strace flags (later in the day so timestamps
are different) showed a poll timeout that accounted for the lost
milliseconds.

14:02:54.851738 [00007f418fdc4fe1] clone(child_stack=0x7f4185783eb0,
flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID,
parent_tidptr=0x7f41857849d0, tls=0x
7f4185784700, child_tidptr=0x7f41857849d0) = 26910 <0.000183>
14:02:54.852046 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
181497670}) = 0 <0.000023>
14:02:54.852179 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
181632916}) = 0 <0.000035>
14:02:54.852271 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
181734496}) = 0 <0.000018>
14:02:54.852352 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
181802453}) = 0 <0.000023>
14:02:54.852433 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
181890580}) = 0 <0.000018>
14:02:54.852510 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
182085558}) = 0 <0.000168>
14:02:54.852750 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
182211352}) = 0 <0.000037>
14:02:54.852848 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
182310406}) = 0 <0.000030>
14:02:54.852939 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
182388637}) = 0 <0.000026>
14:02:54.853029 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
182490719}) = 0 <0.000032>
14:02:54.853119 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
182583486}) = 0 <0.000026>
14:02:54.853199 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
182649849}) = 0 <0.000022>
14:02:54.853320 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
182832561}) = 0 <0.000099>
14:02:54.853483 [00007f418fdbaa4d] poll(0, 0, 150) = 0 (Timeout) <0.150283>
14:02:55.003886 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
333381094}) = 0 <0.000054>
14:02:55.004075 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
333548521}) = 0 <0.000050>
14:02:55.004206 [00007fffaabfe7d2] clock_gettime(CLOCK_MONOTONIC, {2381,
333677667}) = 0 <0.000225>

I self-compiled 7.29.0 and installed it in /curl/ on the same host.

# /curl/7.29.0/bin/curl -V
curl 7.29.0 (x86_64-unknown-linux-gnu) libcurl/7.29.0 OpenSSL/1.0.1e
zlib/1.2.7 libidn/1.28
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3
pop3s rtsp smtp smtps telnet tftp
Features: IDN IPv6 Largefile NTLM NTLM_WB SSL libz

# curl -V (this is curl from CentOS)
curl 7.29.0 (x86_64-redhat-linux-gnu) libcurl/7.29.0 NSS/3.15.4 zlib/1.2.7
libidn/1.28 libssh2/1.4.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3
pop3s rtsp scp sftp smtp smtps telnet tftp
Features: AsynchDNS GSS-Negotiate IDN IPv6 Largefile NTLM NTLM_WB SSL libz

The behavior is responsive as expected and the trace output diverges
significantly from the bundled curl.

Here is gdb trace output (traced on system calls) for my compiled curl.

Catchpoint 1 (returned from syscall close), 0x00007ffff76927f0 in
__close_nocancel () at ../sysdeps/unix/syscall-template.S:81
81 T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
(gdb) c
Continuing.

Catchpoint 1 (call to syscall rt_sigaction), 0x00007ffff75e074a in
__GI___libc_sigaction (sig=13, act=act_at_entry=0x7fffffffdf30,
oact=oact_at_entry=0x7fffffffdfd0)
at ../sysdeps/unix/sysv/linux/x86_64/sigaction.c:64
64 result = INLINE_SYSCALL (rt_sigaction, 4,
(gdb) c
Continuing.

Catchpoint 1 (returned from syscall rt_sigaction), 0x00007ffff75e074a in
__GI___libc_sigaction (sig=13, act=act_at_entry=0x7fffffffdf30,
oact=oact_at_entry=0x7fffffffdfd0)
at ../sysdeps/unix/sysv/linux/x86_64/sigaction.c:64
64 result = INLINE_SYSCALL (rt_sigaction, 4,
(gdb) c
Continuing.

Catchpoint 1 (call to syscall brk), 0x00007ffff7697fec in __brk
(addr=addr_at_entry=0x0) at ../sysdeps/unix/sysv/linux/x86_64/brk.c:31
31 __curbrk = newbrk = (void *) INLINE_SYSCALL (brk, 1, addr);
(gdb) c
Continuing.

Catchpoint 1 (returned from syscall brk), 0x00007ffff7697fec in __brk
(addr=addr_at_entry=0x0) at ../sysdeps/unix/sysv/linux/x86_64/brk.c:31
31 __curbrk = newbrk = (void *) INLINE_SYSCALL (brk, 1, addr);
(gdb) c
Continuing.

Here is gdb trace output (traced on system calls) for the bundled curl and
shows where it diverges from the previous output:
Nowhere in my compiled version gdb output is there a reference to
pthread_once.

Catchpoint 1 (returned from syscall close), 0x00007ffff77532a0 in
__close_nocancel () at ../sysdeps/unix/syscall-template.S:81
81 T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
(gdb) c
Continuing.

Catchpoint 1 (call to syscall rt_sigaction), 0x00007ffff73b974a in
__GI___libc_sigaction (sig=sig_at_entry=13, act=act_at_entry=0x7fffffffdf50,
oact=oact_at_entry=0x7fffffffdff0) at
../sysdeps/unix/sysv/linux/x86_64/sigaction.c:64
64 result = INLINE_SYSCALL (rt_sigaction, 4,
(gdb) c
Continuing.

Catchpoint 1 (returned from syscall rt_sigaction), 0x00007ffff73b974a in
__GI___libc_sigaction (sig=sig_at_entry=13, act=act_at_entry=0x7fffffffdf50,
oact=oact_at_entry=0x7fffffffdff0) at
../sysdeps/unix/sysv/linux/x86_64/sigaction.c:64
64 result = INLINE_SYSCALL (rt_sigaction, 4,
(gdb) c
Continuing.

Catchpoint 1 (call to syscall futex), pthread_once () at
../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_once.S:128
128 4: addq $8, %rsp
(gdb) c
Continuing.

I would prefer to go back to the bundled curl so I hope there is a simple
config change I can make.

Does anyone know what is causing the threaded behavior and more importantly
to me the timeout I have described above with curl bundled on CentOS7?

Let me know if additional detail is needed.

-------------------------------------------------------------------
List admin: http://cool.haxx.se/list/listinfo/curl-users
FAQ: http://curl.haxx.se/docs/faq.html
Etiquette: http://curl.haxx.se/mail/etiquette.html
Received on 2014-10-09