5:18 p.m.
Hi,
Can anyone tell me if it's normal to take over 2 seconds to connect to
the libvirt daemon?
xen1 ~ # time virsh -c 'xen://xen5/' pwd
real 0m2.102s
xen1 ~ # time virsh -c 'xen://xen1/' pwd
real 0m2.217s
Strace shows it sitting for 2.08s on polling the remote socket:
poll([{fd=6, events=POLLIN}, {fd=7, events=POLLIN}], 2, -1) = 1 ([{fd=6,
revents=POLLIN}]) <2.082839>
Not quite sure why though? Experiencing this on both 0.9.7 and 0.9.0.
This happens both with virsh and the perl libvirt bindings.
If i just spawn virsh interactively I only incur that 2s hit on intial
spawn, all commands are very quick and responsive.
Anyone have any suggestions?
- Nathan
--
Nathan March<nathan(a)gt.net>
Gossamer Threads Inc. http://www.gossamer-threads.com/
Tel: (604) 687-5804 Fax: (604) 687-5806
6:48 p.m.
On 12/12/2011 4:35 PM, Nathan March wrote:
On 12/1/2011 3:18 PM, Nathan March wrote:
> Can anyone tell me if it's normal to take over 2 seconds to connect
> to the libvirt daemon?
>
Can anyone comment on this? Even just a quick test to see if it
happens on your systems would be appreciated.
I've rebuilt it with debugging and found the following:
16:47:29.640: 5972: debug : remoteIOEventLoop:10599 : Giving up the buck
66 0x7ff564a59010 (nil)
16:47:29.640: 5972: debug : remoteIO:10773 : All done with our call 66
(nil) 0x7ff564a59010
16:47:29.641: 5972: debug : remoteIO:10673 : Do proc=1 serial=1
length=48 wait=(nil)
16:47:29.641: 5972: debug : remoteIO:10745 : We have the buck 1
0x10c6130 0x10c6130
16:47:31.670: 5972: debug : remoteIODecodeMessageLength:10066 : Got
length, now need 56 total (52 more)
16:47:31.670: 5972: debug : remoteIOEventLoop:10599 : Giving up the buck
1 0x10c6130 (nil)
16:47:31.670: 5972: debug : remoteIO:10773 : All done with our call 1
(nil) 0x10c6130
16:47:31.670: 5972: debug : doRemoteOpen:922 : Adding Handler for remote
events
16:47:31.670: 5972: debug : virEventPollAddHandle:110 : Add handle fd=7
events=1 cb=0x7ff
The 2s gap is pretty visible, not sure why yet.
- Nathan
2:51 a.m.
On 13.12.2011 01:48, Nathan March wrote:
On 12/12/2011 4:35 PM, Nathan March wrote:
> On 12/1/2011 3:18 PM, Nathan March wrote:
>> Can anyone tell me if it's normal to take over 2 seconds to connect
>> to the libvirt daemon?
>>
>
> Can anyone comment on this? Even just a quick test to see if it
> happens on your systems would be appreciated.
>
I've rebuilt it with debugging and found the following:
16:47:29.640: 5972: debug : remoteIOEventLoop:10599 : Giving up the buck
66 0x7ff564a59010 (nil)
16:47:29.640: 5972: debug : remoteIO:10773 : All done with our call 66
(nil) 0x7ff564a59010
16:47:29.641: 5972: debug : remoteIO:10673 : Do proc=1 serial=1
length=48 wait=(nil)
16:47:29.641: 5972: debug : remoteIO:10745 : We have the buck 1
0x10c6130 0x10c6130
16:47:31.670: 5972: debug : remoteIODecodeMessageLength:10066 : Got
length, now need 56 total (52 more)
16:47:31.670: 5972: debug : remoteIOEventLoop:10599 : Giving up the buck
1 0x10c6130 (nil)
16:47:31.670: 5972: debug : remoteIO:10773 : All done with our call 1
(nil) 0x10c6130
16:47:31.670: 5972: debug : doRemoteOpen:922 : Adding Handler for remote
events
16:47:31.670: 5972: debug : virEventPollAddHandle:110 : Add handle fd=7
events=1 cb=0x7ff
The 2s gap is pretty visible, not sure why yet.
Yeah, the gap is obvious. However, this is not telling us why. Can you
please provide the daemon logs? As far as I can tell, we see client
here, waiting for response for 2 secs. Therefore we need to inspect the
daemon for what take it so long.
Michal
1:11 p.m.
On 12/13/2011 12:51 AM, Michal Privoznik wrote:
On 13.12.2011 01:48, Nathan March wrote:
>
> I've rebuilt it with debugging and found the following:
>
> 16:47:29.640: 5972: debug : remoteIOEventLoop:10599 : Giving up the buck
> 66 0x7ff564a59010 (nil)
> 16:47:29.640: 5972: debug : remoteIO:10773 : All done with our call 66
> (nil) 0x7ff564a59010
> 16:47:29.641: 5972: debug : remoteIO:10673 : Do proc=1 serial=1
> length=48 wait=(nil)
> 16:47:29.641: 5972: debug : remoteIO:10745 : We have the buck 1
> 0x10c6130 0x10c6130
> 16:47:31.670: 5972: debug : remoteIODecodeMessageLength:10066 : Got
> length, now need 56 total (52 more)
> 16:47:31.670: 5972: debug : remoteIOEventLoop:10599 : Giving up the buck
> 1 0x10c6130 (nil)
> 16:47:31.670: 5972: debug : remoteIO:10773 : All done with our call 1
> (nil) 0x10c6130
> 16:47:31.670: 5972: debug : doRemoteOpen:922 : Adding Handler for remote
> events
> 16:47:31.670: 5972: debug : virEventPollAddHandle:110 : Add handle fd=7
> events=1 cb=0x7ff
>
> The 2s gap is pretty visible, not sure why yet.
Yeah, the gap is obvious. However, this is not telling us why. Can you
please provide the daemon logs? As far as I can tell, we see client
here, waiting for response for 2 secs. Therefore we need to inspect the
daemon for what take it so long.
Yep, here it is:
11:09:25.687: 7898: debug : virEventPollDispatchHandles:466 : i=5 w=6
11:09:25.687: 7898: debug : virEventPollDispatchHandles:466 : i=6 w=7
11:09:25.687: 7898: debug : virEventPollDispatchHandles:466 : i=7 w=8
11:09:25.687: 7898: debug : virEventPollDispatchHandles:479 : Dispatch
n=7 f=17 w=8 e=1 0x21e19a0
11:09:25.688: 7903: debug : virEventPollUpdateHandle:143 : Update handle
w=7 e=3
11:09:25.688: 7903: debug : virEventPollInterruptLocked:693 : Interrupting
11:09:25.688: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:25.789: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:25.889: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:25.990: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:26.091: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:26.191: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:26.292: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:26.393: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:26.494: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:26.595: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:26.696: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:26.796: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:26.897: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:27.025: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:27.126: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:27.227: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:27.328: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:27.429: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:27.530: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:27.631: 7898: debug : xenStoreDomainIntroduced:1354 : Some domains
were missing, trying again
11:09:27.731: 7898: debug : virEventPollDispatchHandles:466 : i=8 w=9
11:09:27.732: 7898: debug : virEventPollCleanupTimeouts:497 : Cleanup 1
11:09:27.732: 7898: debug : virEventPollCleanupHandles:544 : Cleanup 9
11:09:27.732: 7898: debug : virEventRunDefaultImpl:188 :
11:09:27.732: 7898: debug : virEventPollCleanupTimeouts:497 : Cleanup 1
11:09:27.732: 7898: debug : virEventPollCleanupHandles:544 : Cleanup 9
This is on a freshly booted machine with no VM's running on it, so not
sure what domains it's expecting to find?
- Nathan
1:24 p.m.
On 12/13/2011 11:11 AM, Nathan March wrote:
This is on a freshly booted machine with no VM's running on it, so not
sure what domains it's expecting to find?
- Nathan
Little more info, here's an strace of the libvirtd during that time:
[pid 7898] 11:21:48.450160 write(8, "11:21:48.449: 7898: debug :
xenStoreDomainIntroduced:1354 : Some domains were missing, trying
again\n", 100) = 100
[pid 7898] 11:21:48.450468 nanosleep({0, 100000000}, NULL) = 0
[pid 7898] 11:21:48.550803 rt_sigaction(SIGPIPE, {SIG_IGN, [],
SA_RESTORER, 0x7fc1cfa42400}, {SIG_IGN, [], SA_RESTORER|SA_SIGINFO,
0x7fc1cfa42400}, 8) = 0
[pid 7898] 11:21:48.551095 write(16,
"\1\0\0\0\0\0\0\0\0\0\0\0\16\0\0\0", 16) = 16
[pid 7898] 11:21:48.551351 write(16, "/local/domain\0", 14 <unfinished
...>
[pid 8577] 11:21:48.551597 <... read resumed>
"\1\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0", 16) = 16
[pid 8577] 11:21:48.551729 read(16, "0\0", 2) = 2
[pid 8577] 11:21:48.551937 read(16, <unfinished ...>
[pid 7898] 11:21:48.552081 <... write resumed> ) = 14
[pid 7898] 11:21:48.552193 rt_sigaction(SIGPIPE, {SIG_IGN, [],
SA_RESTORER|SA_SIGINFO, 0x7fc1cfa42400}, NULL, 8) = 0
[pid 7898] 11:21:48.552435 mlock(0x7fc1cdb697d0, 80) = 0
[pid 7898] 11:21:48.552662 mlock(0x7fc1cdb696e0, 136) = 0
[pid 7898] 11:21:48.552886 ioctl(15, SNDCTL_DSP_RESET, 0x7fc1cdb69560) = 0
[pid 7898] 11:21:48.553158 munlock(0x7fc1cdb696e0, 136) = 0
[pid 7898] 11:21:48.553330 munlock(0x7fc1cdb697d0, 80) = 0
[pid 7898] 11:21:48.553524 rt_sigaction(SIGPIPE, {SIG_IGN, [],
SA_RESTORER, 0x7fc1cfa42400}, {SIG_IGN, [], SA_RESTORER|SA_SIGINFO,
0x7fc1cfa42400}, 8) = 0
[pid 7898] 11:21:48.553843 write(16,
"\1\0\0\0\0\0\0\0\0\0\0\0\16\0\0\0", 16) = 16
[pid 7898] 11:21:48.554124 write(16, "/local/domain\0", 14 <unfinished
...>
[pid 8577] 11:21:48.554411 <... read resumed>
"\1\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0", 16) = 16
[pid 8577] 11:21:48.554584 read(16, "0\0", 2) = 2
[pid 8577] 11:21:48.554745 read(16, <unfinished ...>
[pid 7898] 11:21:48.554911 <... write resumed> ) = 14
[pid 7898] 11:21:48.555020 rt_sigaction(SIGPIPE, {SIG_IGN, [],
SA_RESTORER|SA_SIGINFO, 0x7fc1cfa42400}, NULL, 8) = 0
[pid 7898] 11:21:48.555289 mlock(0x7fc1cdb697c0, 80) = 0
[pid 7898] 11:21:48.555461 mlock(0x7fc1cdb696d0, 136) = 0
[pid 7898] 11:21:48.555684 ioctl(15, SNDCTL_DSP_RESET, 0x7fc1cdb69550) = 0
[pid 7898] 11:21:48.555884 munlock(0x7fc1cdb696d0, 136) = 0
[pid 7898] 11:21:48.556088 munlock(0x7fc1cdb697c0, 80) = 0
[pid 7898] 11:21:48.556293 rt_sigaction(SIGPIPE, {SIG_IGN, [],
SA_RESTORER, 0x7fc1cfa42400}, {SIG_IGN, [], SA_RESTORER|SA_SIGINFO,
0x7fc1cfa42400}, 8) = 0
[pid 7898] 11:21:48.556548 write(16,
"\2\0\0\0\0\0\0\0\0\0\0\0\25\0\0\0", 16) = 16
[pid 7898] 11:21:48.556825 write(16, "/local/domain/0/name\0", 21
<unfinished ...>
[pid 8577] 11:21:48.557075 <... read resumed>
"\2\0\0\0\0\0\0\0\0\0\0\0\10\0\0\0", 16) = 16
[pid 8577] 11:21:48.557206 read(16, "Domain-0", 8) = 8
[pid 8577] 11:21:48.557373 read(16, <unfinished ...>
[pid 7898] 11:21:48.557538 <... write resumed> ) = 21
[pid 7898] 11:21:48.557602 rt_sigaction(SIGPIPE, {SIG_IGN, [],
SA_RESTORER|SA_SIGINFO, 0x7fc1cfa42400}, NULL, 8) = 0
[pid 7898] 11:21:48.557872 rt_sigaction(SIGPIPE, {SIG_IGN, [],
SA_RESTORER, 0x7fc1cfa42400}, {SIG_IGN, [], SA_RESTORER|SA_SIGINFO,
0x7fc1cfa42400}, 8) = 0
[pid 7898] 11:21:48.558166 write(16,
"\2\0\0\0\0\0\0\0\0\0\0\0\23\0\0\0", 16) = 16
[pid 7898] 11:21:48.558420 write(16, "/local/domain/0/vm\0", 19
<unfinished ...>
[pid 8577] 11:21:48.558662 <... read resumed>
"\2\0\0\0\0\0\0\0\0\0\0\0*\0\0\0", 16) = 16
[pid 8577] 11:21:48.558887 read(16,
"/vm/00000000-0000-0000-0000-000000000000-7", 42) = 42
[pid 8577] 11:21:48.559150 read(16, <unfinished ...>
[pid 7898] 11:21:48.559331 <... write resumed> ) = 19
[pid 7898] 11:21:48.559464 rt_sigaction(SIGPIPE, {SIG_IGN, [],
SA_RESTORER|SA_SIGINFO, 0x7fc1cfa42400}, NULL, 8) = 0
[pid 7898] 11:21:48.559706 gettimeofday({1323804108, 559781}, NULL) = 0
[pid 7898] 11:21:48.559912 gettid() = 7898
[pid 7898] 11:21:48.560116 write(8, "11:21:48.559: 7898: debug :
xenStoreDomainIntroduced:1354 : Some domains were missing, trying
again\n", 100) = 100
Yet xenstore data for the local dom0 looks fine?
xen3 ~ # xenstore-ls /local/domain/0
vm = "/vm/00000000-0000-0000-0000-000000000000-7"
device = ""
control = ""
platform-feature-multiprocessor-suspend = "1"
error = ""
memory = ""
target = "1048576"
guest = ""
hvmpv = ""
data = ""
description = ""
console = ""
limit = "1048576"
type = "xenconsoled"
domid = "0"
cpu = ""
0 = ""
availability = "online"
name = "Domain-0"
xen3 ~ # xenstore-read /local/domain/0/name
Domain-0
xen3 ~ # xenstore-read /local/domain/0/vm
/vm/00000000-0000-0000-0000-000000000000-7
Bug?
- Nathan
2:59 p.m.
On 12/13/2011 11:24 AM, Nathan March wrote:
On 12/13/2011 11:11 AM, Nathan March wrote:
>
> This is on a freshly booted machine with no VM's running on it, so
> not sure what domains it's expecting to find?
>
> - Nathan
Little more info, here's an strace of the libvirtd during that time:
Anyone have anything they can suggest for this?
- Nathan
2:15 p.m.
On 12/13/2011 11:11 AM, Nathan March wrote:
On 12/13/2011 12:51 AM, Michal Privoznik wrote:
> On 13.12.2011 01:48, Nathan March wrote:
>>
>> I've rebuilt it with debugging and found the following:
>>
>> 16:47:29.640: 5972: debug : remoteIOEventLoop:10599 : Giving up the
>> buck
>> 66 0x7ff564a59010 (nil)
>> 16:47:29.640: 5972: debug : remoteIO:10773 : All done with our call 66
>> (nil) 0x7ff564a59010
>> 16:47:29.641: 5972: debug : remoteIO:10673 : Do proc=1 serial=1
>> length=48 wait=(nil)
>> 16:47:29.641: 5972: debug : remoteIO:10745 : We have the buck 1
>> 0x10c6130 0x10c6130
>> 16:47:31.670: 5972: debug : remoteIODecodeMessageLength:10066 : Got
>> length, now need 56 total (52 more)
>> 16:47:31.670: 5972: debug : remoteIOEventLoop:10599 : Giving up the
>> buck
>> 1 0x10c6130 (nil)
>> 16:47:31.670: 5972: debug : remoteIO:10773 : All done with our call 1
>> (nil) 0x10c6130
>> 16:47:31.670: 5972: debug : doRemoteOpen:922 : Adding Handler for
>> remote
>> events
>> 16:47:31.670: 5972: debug : virEventPollAddHandle:110 : Add handle fd=7
>> events=1 cb=0x7ff
>>
>> The 2s gap is pretty visible, not sure why yet.
> Yeah, the gap is obvious. However, this is not telling us why. Can you
> please provide the daemon logs? As far as I can tell, we see client
> here, waiting for response for 2 secs. Therefore we need to inspect the
> daemon for what take it so long.
Yep, here it is:
11:09:25.687: 7898: debug : virEventPollDispatchHandles:466 : i=5 w=6
11:09:25.687: 7898: debug : virEventPollDispatchHandles:466 : i=6 w=7
11:09:25.687: 7898: debug : virEventPollDispatchHandles:466 : i=7 w=8
11:09:25.687: 7898: debug : virEventPollDispatchHandles:479 : Dispatch
n=7 f=17 w=8 e=1 0x21e19a0
11:09:25.688: 7903: debug : virEventPollUpdateHandle:143 : Update
handle w=7 e=3
11:09:25.688: 7903: debug : virEventPollInterruptLocked:693 :
Interrupting
11:09:25.688: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:25.789: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:25.889: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:25.990: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:26.091: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:26.191: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:26.292: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:26.393: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:26.494: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:26.595: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:26.696: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:26.796: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:26.897: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:27.025: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:27.126: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:27.227: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:27.328: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:27.429: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:27.530: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:27.631: 7898: debug : xenStoreDomainIntroduced:1354 : Some
domains were missing, trying again
11:09:27.731: 7898: debug : virEventPollDispatchHandles:466 : i=8 w=9
11:09:27.732: 7898: debug : virEventPollCleanupTimeouts:497 : Cleanup 1
11:09:27.732: 7898: debug : virEventPollCleanupHandles:544 : Cleanup 9
11:09:27.732: 7898: debug : virEventRunDefaultImpl:188 :
11:09:27.732: 7898: debug : virEventPollCleanupTimeouts:497 : Cleanup 1
11:09:27.732: 7898: debug : virEventPollCleanupHandles:544 : Cleanup 9
This is on a freshly booted machine with no VM's running on it, so not
sure what domains it's expecting to find?
Anyone able to help out here?
- Nathan
4937
days inactive
4973
days old
7 comments
2 participants
participants (2)
-
Michal Privoznik -
Nathan March