Any known issues with randomly slow clone() syscal under 2.6.32-33-pve?

Z

zerkms

New Member
Jan 23, 2013
16
0
1
Today I've discovered that sometimes a trivial bash curl call takes too long. The request was performed from one our server to another and further investigations showed that the destination server is quick and responds in milliseconds after a request received.

Then I found that it's a curl call that is slow.

Armed with strace I've noticed that according to its log it's a clone() syscall that is slow.

The relevant strace looks like:

Code: 
1421983762.595237 clone(child_stack=0x7f5dd957af70, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f5dd957b9d0, tls=0x7f5dd957b700, child_tidptr=0x7f5dd957b9d0) = 235121421983762.595298 clock_gettime(CLOCK_MONOTONIC, {3740303, 713692778}) = 0
1421983762.595337 clock_gettime(CLOCK_MONOTONIC, {3740303, 713721600}) = 0
1421983762.595369 clock_gettime(CLOCK_MONOTONIC, {3740303, 713754163}) = 0
1421983762.595415 clock_gettime(CLOCK_MONOTONIC, {3740303, 713799226}) = 0
1421983762.595464 clock_gettime(CLOCK_MONOTONIC, {3740303, 713849127}) = 0
1421983762.595493 clock_gettime(CLOCK_MONOTONIC, {3740303, 713878231}) = 0
1421983762.595530 clock_gettime(CLOCK_MONOTONIC, {3740303, 713915333}) = 0
1421983762.595592 clock_gettime(CLOCK_MONOTONIC, {3740303, 713977699}) = 0
1421983762.595616 clock_gettime(CLOCK_MONOTONIC, {3740303, 713999637}) = 0
1421983762.595636 clock_gettime(CLOCK_MONOTONIC, {3740303, 714018267}) = 0
1421983762.595657 clock_gettime(CLOCK_MONOTONIC, {3740303, 714040341}) = 0
1421983762.595678 clock_gettime(CLOCK_MONOTONIC, {3740303, 714061528}) = 0
1421983762.595698 clock_gettime(CLOCK_MONOTONIC, {3740303, 714081372}) = 0
1421983762.595718 clock_gettime(CLOCK_MONOTONIC, {3740303, 714102478}) = 0
1421983762.595744 clock_gettime(CLOCK_MONOTONIC, {3740303, 714126708}) = 0
1421983762.595766 poll(0, 0, 4)         = 0 (Timeout)
1421983762.599899 clock_gettime(CLOCK_MONOTONIC, {3740303, 718282522}) = 0
1421983762.599925 clock_gettime(CLOCK_MONOTONIC, {3740303, 718308152}) = 0
1421983762.599946 clock_gettime(CLOCK_MONOTONIC, {3740303, 718328954}) = 0
1421983762.599966 clock_gettime(CLOCK_MONOTONIC, {3740303, 718354308}) = 0
1421983762.599993 clock_gettime(CLOCK_MONOTONIC, {3740303, 718376131}) = 0
1421983762.600013 clock_gettime(CLOCK_MONOTONIC, {3740303, 718395814}) = 0
1421983762.600041 clock_gettime(CLOCK_MONOTONIC, {3740303, 718425356}) = 0
1421983762.600063 clock_gettime(CLOCK_MONOTONIC, {3740303, 718446401}) = 0
1421983762.600084 poll(0, 0, 8)         = 0 (Timeout)
1421983762.608179 clock_gettime(CLOCK_MONOTONIC, {3740303, 726563969}) = 0
1421983762.608207 clock_gettime(CLOCK_MONOTONIC, {3740303, 726590821}) = 0
1421983762.608231 clock_gettime(CLOCK_MONOTONIC, {3740303, 726614935}) = 0
1421983762.608253 clock_gettime(CLOCK_MONOTONIC, {3740303, 726636738}) = 0
1421983762.608276 clock_gettime(CLOCK_MONOTONIC, {3740303, 726660186}) = 0
1421983762.608299 clock_gettime(CLOCK_MONOTONIC, {3740303, 726682901}) = 0
1421983762.608321 clock_gettime(CLOCK_MONOTONIC, {3740303, 726705342}) = 0
1421983762.608355 clock_gettime(CLOCK_MONOTONIC, {3740303, 726738892}) = 0
1421983762.608418 poll(0, 0, 16)        = 0 (Timeout)
1421983762.624584 clock_gettime(CLOCK_MONOTONIC, {3740303, 742970236}) = 0
1421983762.624616 clock_gettime(CLOCK_MONOTONIC, {3740303, 743000712}) = 0
1421983762.624644 clock_gettime(CLOCK_MONOTONIC, {3740303, 743028790}) = 0
1421983762.624672 clock_gettime(CLOCK_MONOTONIC, {3740303, 743057226}) = 0
1421983762.624701 clock_gettime(CLOCK_MONOTONIC, {3740303, 743086058}) = 0
1421983762.624729 clock_gettime(CLOCK_MONOTONIC, {3740303, 743113308}) = 0
1421983762.624756 clock_gettime(CLOCK_MONOTONIC, {3740303, 743141082}) = 0
1421983762.624789 clock_gettime(CLOCK_MONOTONIC, {3740303, 743173852}) = 0
1421983762.624816 poll(0, 0, 32)        = 0 (Timeout)
1421983762.656914 clock_gettime(CLOCK_MONOTONIC, {3740303, 775300475}) = 0
1421983762.656947 clock_gettime(CLOCK_MONOTONIC, {3740303, 775331344}) = 0
1421983762.656975 clock_gettime(CLOCK_MONOTONIC, {3740303, 775359920}) = 0
1421983762.657003 clock_gettime(CLOCK_MONOTONIC, {3740303, 775388013}) = 0
1421983762.657033 clock_gettime(CLOCK_MONOTONIC, {3740303, 775417392}) = 0
1421983762.657080 clock_gettime(CLOCK_MONOTONIC, {3740303, 775482768}) = 0
1421983762.657127 clock_gettime(CLOCK_MONOTONIC, {3740303, 775512398}) = 0
1421983762.657157 clock_gettime(CLOCK_MONOTONIC, {3740303, 775542220}) = 0
1421983762.657186 poll(0, 0, 64)        = 0 (Timeout)
1421983762.721323 clock_gettime(CLOCK_MONOTONIC, {3740303, 839710329}) = 0
1421983762.721357 clock_gettime(CLOCK_MONOTONIC, {3740303, 839742343}) = 0
1421983762.721386 clock_gettime(CLOCK_MONOTONIC, {3740303, 839771544}) = 0
1421983762.721416 clock_gettime(CLOCK_MONOTONIC, {3740303, 839801534}) = 0
1421983762.721446 clock_gettime(CLOCK_MONOTONIC, {3740303, 839831862}) = 0
1421983762.721475 clock_gettime(CLOCK_MONOTONIC, {3740303, 839860312}) = 0
1421983762.721504 clock_gettime(CLOCK_MONOTONIC, {3740303, 839889163}) = 0
1421983762.721533 clock_gettime(CLOCK_MONOTONIC, {3740303, 839918009}) = 0
1421983762.721561 poll(0, 0, 128)       = 0 (Timeout)
1421983762.849793 clock_gettime(CLOCK_MONOTONIC, {3740303, 968179530}) = 0
1421983762.849825 clock_gettime(CLOCK_MONOTONIC, {3740303, 968210363}) = 0
1421983762.849854 clock_gettime(CLOCK_MONOTONIC, {3740303, 968238959}) = 0
1421983762.849884 clock_gettime(CLOCK_MONOTONIC, {3740303, 968268828}) = 0
1421983762.849913 clock_gettime(CLOCK_MONOTONIC, {3740303, 968298108}) = 0
1421983762.849941 clock_gettime(CLOCK_MONOTONIC, {3740303, 968325991}) = 0
1421983762.849968 clock_gettime(CLOCK_MONOTONIC, {3740303, 968353342}) = 0
1421983762.849996 clock_gettime(CLOCK_MONOTONIC, {3740303, 968381281}) = 0
1421983762.850024 poll(0, 0, 256)       = 0 (Timeout)
1421983763.106354 clock_gettime(CLOCK_MONOTONIC, {3740304, 224740902}) = 0
1421983763.106390 clock_gettime(CLOCK_MONOTONIC, {3740304, 224775769}) = 0
1421983763.106432 clock_gettime(CLOCK_MONOTONIC, {3740304, 224817051}) = 0
1421983763.106461 clock_gettime(CLOCK_MONOTONIC, {3740304, 224858181}) = 0
1421983763.106503 clock_gettime(CLOCK_MONOTONIC, {3740304, 224888272}) = 0
1421983763.106530 clock_gettime(CLOCK_MONOTONIC, {3740304, 224915158}) = 0
1421983763.106564 clock_gettime(CLOCK_MONOTONIC, {3740304, 224948951}) = 0
1421983763.106591 clock_gettime(CLOCK_MONOTONIC, {3740304, 224975842}) = 0
1421983763.106618 poll(0, 0, 1000)      = 0 (Timeout)
1421983764.107699 clock_gettime(CLOCK_MONOTONIC, {3740305, 226087274}) = 0
1421983764.107750 clock_gettime(CLOCK_MONOTONIC, {3740305, 226135432}) = 0
1421983764.107780 clock_gettime(CLOCK_MONOTONIC, {3740305, 226164925}) = 0
1421983764.107812 clock_gettime(CLOCK_MONOTONIC, {3740305, 226197837}) = 0
1421983764.107845 clock_gettime(CLOCK_MONOTONIC, {3740305, 226230087}) = 0
1421983764.107883 clock_gettime(CLOCK_MONOTONIC, {3740305, 226267983}) = 0
1421983764.107912 clock_gettime(CLOCK_MONOTONIC, {3740305, 226296562}) = 0
1421983764.107940 clock_gettime(CLOCK_MONOTONIC, {3740305, 226325472}) = 0
1421983764.107968 poll(0, 0, 1000)      = 0 (Timeout)
1421983765.109082 clock_gettime(CLOCK_MONOTONIC, {3740306, 227470940}) = 0
1421983765.109122 clock_gettime(CLOCK_MONOTONIC, {3740306, 227507330}) = 0
1421983765.109150 clock_gettime(CLOCK_MONOTONIC, {3740306, 227535425}) = 0
1421983765.109181 clock_gettime(CLOCK_MONOTONIC, {3740306, 227566130}) = 0
1421983765.109212 clock_gettime(CLOCK_MONOTONIC, {3740306, 227597925}) = 0
1421983765.109241 clock_gettime(CLOCK_MONOTONIC, {3740306, 227626474}) = 0
1421983765.109270 clock_gettime(CLOCK_MONOTONIC, {3740306, 227654569}) = 0
1421983765.109297 clock_gettime(CLOCK_MONOTONIC, {3740306, 227682015}) = 0
1421983765.109325 poll(0, 0, 1000)      = 0 (Timeout)
1421983766.110429 clock_gettime(CLOCK_MONOTONIC, {3740307, 228816238}) = 0
1421983766.110464 clock_gettime(CLOCK_MONOTONIC, {3740307, 228849036}) = 0
1421983766.110492 clock_gettime(CLOCK_MONOTONIC, {3740307, 228876715}) = 0
1421983766.110522 clock_gettime(CLOCK_MONOTONIC, {3740307, 228907443}) = 0
1421983766.110552 clock_gettime(CLOCK_MONOTONIC, {3740307, 228937543}) = 0
1421983766.110580 clock_gettime(CLOCK_MONOTONIC, {3740307, 228965264}) = 0
1421983766.110608 clock_gettime(CLOCK_MONOTONIC, {3740307, 228992842}) = 0
1421983766.110635 clock_gettime(CLOCK_MONOTONIC, {3740307, 229020102}) = 0
1421983766.110663 poll(0, 0, 1000)      = 0 (Timeout)
1421983767.111744 clock_gettime(CLOCK_MONOTONIC, {3740308, 230133260}) = 0
1421983767.111781 clock_gettime(CLOCK_MONOTONIC, {3740308, 230166850}) = 0
1421983767.111807 clock_gettime(CLOCK_MONOTONIC, {3740308, 230192508}) = 0
1421983767.111837 clock_gettime(CLOCK_MONOTONIC, {3740308, 230223800}) = 0
1421983767.111868 clock_gettime(CLOCK_MONOTONIC, {3740308, 230253545}) = 0
1421983767.111893 clock_gettime(CLOCK_MONOTONIC, {3740308, 230277546}) = 0
1421983767.111917 clock_gettime(CLOCK_MONOTONIC, {3740308, 230302330}) = 0
1421983767.111942 clock_gettime(CLOCK_MONOTONIC, {3740308, 230327252}) = 0
1421983767.111967 poll(0, 0, 1000)      = 0 (Timeout)
1421983768.113054 clock_gettime(CLOCK_MONOTONIC, {3740309, 231444805}) = 0
1421983768.113128 clock_gettime(CLOCK_MONOTONIC, {3740309, 231515664}) = 0
1421983768.113159 clock_gettime(CLOCK_MONOTONIC, {3740309, 231544618}) = 0
1421983768.113185 clock_gettime(CLOCK_MONOTONIC, {3740309, 231569508}) = 0
1421983768.113209 clock_gettime(CLOCK_MONOTONIC, {3740309, 231593925}) = 0
1421983768.113240 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
1421983768.113289 setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
1421983768.113329 setsockopt(3, SOL_TCP, TCP_KEEPIDLE, [60], 4) = 0
1421983768.113357 setsockopt(3, SOL_TCP, TCP_KEEPINTVL, [60], 4) = 0
1421983768.113385 fcntl(3, F_GETFL)     = 0x2 (flags O_RDWR)
1421983768.113411 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
1421983768.113435 clock_gettime(CLOCK_MONOTONIC, {3740309, 231819619}) = 0
1421983768.113461 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("xxx.xxx.xxx.xxx")}, 16) = -1 EINPROGRESS (Operation now in progress)

In this example it took ~6 seconds to complete. But during experiments this delay varied from 2-3 up to 15-20 seconds.

Googling didn't reveal any obvious issues with it.

The command call is as easy as

curl http://domain_name/request
 
You must log in or register to reply here.

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Quick Navigation

Home Get Subscription Wiki Downloads Proxmox Customer Portal About

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!
Community platform by XenForo® © 2010-2024 XenForo Ltd.
Top Bottom
Back