Releasing host id takes 4-6 seonds - is this epxected beahvioir?

[Nir Soffer]

Hi David,

I'm working on minimizing the time to stop vdsm domain monitors [1]. When we
stop a monitor, the last thing it does is releasing the domain host id,
invoking the python rem_lockspace api using sync mode.

In my test, I have a system with 30 domain monitor threads. Signaling the
threads to stop takes about 10 milliseconds, but joining the threads takes
about 10 seconds.

Profiling vdsm reveal that the time is spent in rem_lockspace call. In this
example, there were 30 calls (one per thread), each call took 5.560 seconds
(wall time).

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)

       30    0.000    0.000  166.829    5.561 sd.py:469(BlockStorageDomain.releaseHostId)
       30    0.001    0.000  166.829    5.561 clusterlock.py:203(SANLock.releaseHostId)
       30  166.813    5.560  166.813    5.560 sanlock:0(rem_lockspace)

Is this expected behavior?

Can we expect that removing a lockspace will be much faster?

The reason we are concerned about this, is that the current stop timeout for
vdsm is 10 seconds. So if you have many storage domains (I have seen systems
with 40 domains in production), vdsm may be killed before all monitor threads
are stopped, leading to orphaned lockspace, and if the machine is the spm,
orphaned spm resource. From our experience, this prevent stopping of sanlock
daemon, so you cannot upgrade vdsm without rebooting the machine.

[1] http://gerrit.ovirt.org/27573 domainMonitor: Stop domain monitors concurrently

Thanks,                                                                                   
                                                                                     
Nir

[David Teigland]

On Wed, May 14, 2014 at 10:29:16AM -0400, Nir Soffer wrote:
>  Can we expect that removing a lockspace will be much faster? 
The synchronous rem_lockspace looks very much like it could be sped up.
Do you not want to use REM_ASYNC?  If not, then I'll look at optimizing
the sync rem.
Dave

[Nir Soffer]

----- Original Message -----
>  From: "David Teigland" <teigland(a)redhat.com&gt;
>  To: "Nir Soffer" <nsoffer(a)redhat.com&gt;
>  Cc: sanlock-devel(a)lists.fedorahosted.org, "Federico Simoncelli"
> <fsimonce(a)redhat.com&gt;, "Allon Mureinik"
>  <amureini(a)redhat.com&gt;, "Dan Kenigsberg" <danken(a)redhat.com&gt;
>  Sent: Wednesday, May 14, 2014 5:58:42 PM
>  Subject: Re: Releasing host id takes 4-6 seonds - is this epxected beahvioir?
>  
>  On Wed, May 14, 2014 at 10:29:16AM -0400, Nir Soffer wrote:
>  > Can we expect that removing a lockspace will be much faster?
>  
>  The synchronous rem_lockspace looks very much like it could be sped up.
>  Do you not want to use REM_ASYNC? 
We don't have any documentation explaining the need for synchronous version.

Federico, can we use asynchronous version?

>  If not, then I'll look at optimizing
>  the sync rem. 
This seems to be a good idea anyway. Can you explain why the current code takes
4-5 seconds? What is the bottleneck there?

Nir

[David Teigland]

On Wed, May 21, 2014 at 02:26:35AM -0400, Nir Soffer wrote:
>  ----- Original Message -----
>  > From: "David Teigland" <teigland(a)redhat.com&gt;
>  > To: "Nir Soffer" <nsoffer(a)redhat.com&gt;
>  > Cc: sanlock-devel(a)lists.fedorahosted.org, "Federico Simoncelli"
> <fsimonce(a)redhat.com&gt;, "Allon Mureinik"
>  > <amureini(a)redhat.com&gt;, "Dan Kenigsberg" <danken(a)redhat.com&gt;
>  > Sent: Wednesday, May 14, 2014 5:58:42 PM
>  > Subject: Re: Releasing host id takes 4-6 seonds - is this epxected beahvioir?
>  > 
>  > On Wed, May 14, 2014 at 10:29:16AM -0400, Nir Soffer wrote:
>  > > Can we expect that removing a lockspace will be much faster?
>  > 
>  > The synchronous rem_lockspace looks very much like it could be sped up.
>  > Do you not want to use REM_ASYNC?
>  
>  We don't have any documentation explaining the need for synchronous version.
>  
>  Federico, can we use asynchronous version? 
Keep in mind that if you do an async rem_lockspace, and then do
add_lockspace (for the same lockspace) before the remove is done, you'll
get -EAGAIN from the add.

>  > If not, then I'll look at optimizing
>  > the sync rem.
>  
>  This seems to be a good idea anyway. Can you explain why the current code takes
>  4-5 seconds? What is the bottleneck there? 
It's probably from a sleep(1) delay in a couple loops.  At least the one
in rem_lockspace_wait looks like it can be easily changed, so I'll put
that on my list.

Dave

[Federico Simoncelli]

----- Original Message -----
>  From: "Nir Soffer" <nsoffer(a)redhat.com&gt;
>  To: sanlock-devel(a)lists.fedorahosted.org
>  Cc: "Federico Simoncelli" <fsimonce(a)redhat.com&gt;, "Allon
> Mureinik" <amureini(a)redhat.com&gt;, "David Teigland"
>  <teigland(a)redhat.com&gt;, "Dan Kenigsberg" <danken(a)redhat.com&gt;
>  Sent: Wednesday, May 14, 2014 4:29:16 PM
>  Subject: Releasing host id takes 4-6 seonds - is this epxected beahvioir?
>  
>  Hi David,
>  
>  I'm working on minimizing the time to stop vdsm domain monitors [1]. When we
>  stop a monitor, the last thing it does is releasing the domain host id,
>  invoking the python rem_lockspace api using sync mode.
>  
>  In my test, I have a system with 30 domain monitor threads. Signaling the
>  threads to stop takes about 10 milliseconds, but joining the threads takes
>  about 10 seconds.
>  
>  Profiling vdsm reveal that the time is spent in rem_lockspace call. In this
>  example, there were 30 calls (one per thread), each call took 5.560 seconds
>  (wall time).
>  
>     ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>  
>         30    0.000    0.000  166.829    5.561
>         sd.py:469(BlockStorageDomain.releaseHostId)
>         30    0.001    0.000  166.829    5.561
>         clusterlock.py:203(SANLock.releaseHostId)
>         30  166.813    5.560  166.813    5.560 sanlock:0(rem_lockspace)
>  
>  Is this expected behavior?
>  
>  Can we expect that removing a lockspace will be much faster?
>  
>  The reason we are concerned about this, is that the current stop timeout for
>  vdsm is 10 seconds. So if you have many storage domains (I have seen systems
>  with 40 domains in production), vdsm may be killed before all monitor threads
>  are stopped, leading to orphaned lockspace, and if the machine is the spm,
>  orphaned spm resource. 
Small nit: resources are associated to a process so the spm resource cannot
be orphaned.

-- 
Federico