Bug 217366

Matthew Wilcox <willy@infradead.org> writes:

On Wed, Apr 26, 2023 at 05:58:06PM +0000, Kernel.org Bugbot wrote:
> When running a threaded program, and opening a file descriptor that
> is a power of 2 (starting at 64), the call takes a very long time to
> complete. Normally such a call takes less than 2us. However with this
> issue, I've seen the call take up to around 50ms. Additionally this only
> happens the first time, and not subsequent times that file descriptor is
> used. I'm guessing there might be some expansion of some internal data
> structures going on. But I cannot see why this process would take so long.

Because we allocate a new block of memory and then memcpy() the old
block of memory into it.  This isn't surprising behaviour to me.
I don't think there's much we can do to change it (Allocating a
segmented array of file descriptors has previously been vetoed by
people who have programs with a million file descriptors).  Is it
causing you problems?

(via https://msgid.link/ZEl34WthS8UNJnNd@casper.infradead.org)

Al Viro <viro@zeniv.linux.org.uk> replies to comment #1:

On Wed, Apr 26, 2023 at 08:13:37PM +0100, Matthew Wilcox wrote:
> On Wed, Apr 26, 2023 at 05:58:06PM +0000, Kernel.org Bugbot wrote:
> > When running a threaded program, and opening a file descriptor that
> > is a power of 2 (starting at 64), the call takes a very long time to
> > complete. Normally such a call takes less than 2us. However with this
> > issue, I've seen the call take up to around 50ms. Additionally this only
> > happens the first time, and not subsequent times that file descriptor is
> > used. I'm guessing there might be some expansion of some internal data
> > structures going on. But I cannot see why this process would take so long.
> 
> Because we allocate a new block of memory and then memcpy() the old
> block of memory into it.  This isn't surprising behaviour to me.
> I don't think there's much we can do to change it (Allocating a
> segmented array of file descriptors has previously been vetoed by
> people who have programs with a million file descriptors).  Is it
> causing you problems?

FWIW, I suspect that this is not so much allocation + memcpy.
        /* make sure all fd_install() have seen resize_in_progress
	 * or have finished their rcu_read_lock_sched() section.
	 */
	if (atomic_read(&files->count) > 1)
		synchronize_rcu();

in expand_fdtable() is a likelier source of delays.

(via https://msgid.link/20230426194628.GU3390869@ZenIV)

Matthew Wilcox <willy@infradead.org> replies to comment #2:

On Wed, Apr 26, 2023 at 08:46:28PM +0100, Al Viro wrote:
> On Wed, Apr 26, 2023 at 08:13:37PM +0100, Matthew Wilcox wrote:
> > On Wed, Apr 26, 2023 at 05:58:06PM +0000, Kernel.org Bugbot wrote:
> > > When running a threaded program, and opening a file descriptor that
> > > is a power of 2 (starting at 64), the call takes a very long time to
> > > complete. Normally such a call takes less than 2us. However with this
> > > issue, I've seen the call take up to around 50ms. Additionally this only
> > > happens the first time, and not subsequent times that file descriptor is
> > > used. I'm guessing there might be some expansion of some internal data
> > > structures going on. But I cannot see why this process would take so
> long.
> > 
> > Because we allocate a new block of memory and then memcpy() the old
> > block of memory into it.  This isn't surprising behaviour to me.
> > I don't think there's much we can do to change it (Allocating a
> > segmented array of file descriptors has previously been vetoed by
> > people who have programs with a million file descriptors).  Is it
> > causing you problems?
> 
> FWIW, I suspect that this is not so much allocation + memcpy.
>         /* make sure all fd_install() have seen resize_in_progress
>        * or have finished their rcu_read_lock_sched() section.
>        */
>       if (atomic_read(&files->count) > 1)
>               synchronize_rcu();
> 
> in expand_fdtable() is a likelier source of delays.

Perhaps?  The delay seemed to be roughly doubling with the test program,
so I assumed it was primarily the memcpy() cost for the reporter's
system:

FD=64 duration=12565293
FD=128 duration=24755063
FD=256 duration=7602777

... although now I've pasted it, I see my brain skipped one digit, so
256 was faster than 64, not about twice as slow as 128.

(via https://msgid.link/ZEmB1bOJFz72K0ho@casper.infradead.org)

Al Viro <viro@zeniv.linux.org.uk> replies to comment #2:

On Wed, Apr 26, 2023 at 08:46:28PM +0100, Al Viro wrote:
> On Wed, Apr 26, 2023 at 08:13:37PM +0100, Matthew Wilcox wrote:
> > On Wed, Apr 26, 2023 at 05:58:06PM +0000, Kernel.org Bugbot wrote:
> > > When running a threaded program, and opening a file descriptor that
> > > is a power of 2 (starting at 64), the call takes a very long time to
> > > complete. Normally such a call takes less than 2us. However with this
> > > issue, I've seen the call take up to around 50ms. Additionally this only
> > > happens the first time, and not subsequent times that file descriptor is
> > > used. I'm guessing there might be some expansion of some internal data
> > > structures going on. But I cannot see why this process would take so
> long.
> > 
> > Because we allocate a new block of memory and then memcpy() the old
> > block of memory into it.  This isn't surprising behaviour to me.
> > I don't think there's much we can do to change it (Allocating a
> > segmented array of file descriptors has previously been vetoed by
> > people who have programs with a million file descriptors).  Is it
> > causing you problems?
> 
> FWIW, I suspect that this is not so much allocation + memcpy.
>         /* make sure all fd_install() have seen resize_in_progress
>        * or have finished their rcu_read_lock_sched() section.
>        */
>       if (atomic_read(&files->count) > 1)
>               synchronize_rcu();
> 
> in expand_fdtable() is a likelier source of delays.

	A bit more background: we want to avoid grabbing ->file_lock in
fd_install() if at all possible.  After all, we have already claimed
the slot (back when we'd allocated the descriptor) and nobody else is
allowed to shove a file reference there.

	Which is fine, except for the fact that expansion of descriptor
table needs to allocate a new array, copy the old one into it and replace
the old one with it.

	Lockless fd_install() might overlap with the "copy" step in
the above and end up getting lost.  So in fd_install() we check if
there's a resize in progress before deciding to go for the lockless path.
Which means that on the resize side we need to mark the descriptor table
as getting resized, then wait long enough for all threads already in
fd_install() to get through.

(via https://msgid.link/20230426195821.GV3390869@ZenIV)

Al Viro <viro@zeniv.linux.org.uk> replies to comment #3:

On Wed, Apr 26, 2023 at 08:56:05PM +0100, Matthew Wilcox wrote:
> On Wed, Apr 26, 2023 at 08:46:28PM +0100, Al Viro wrote:
> > On Wed, Apr 26, 2023 at 08:13:37PM +0100, Matthew Wilcox wrote:
> > > On Wed, Apr 26, 2023 at 05:58:06PM +0000, Kernel.org Bugbot wrote:
> > > > When running a threaded program, and opening a file descriptor that
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
	This.  The cost of allocation and copy doesn't depend upon the number
of threads; synchronize_rcu() call, OTOH, is conditional upon that being more
than 1.

> > > > is a power of 2 (starting at 64), the call takes a very long time to
> > > > complete. Normally such a call takes less than 2us. However with this
> > > > issue, I've seen the call take up to around 50ms. Additionally this
> only
> > > > happens the first time, and not subsequent times that file descriptor
> is
> > > > used. I'm guessing there might be some expansion of some internal data
> > > > structures going on. But I cannot see why this process would take so
> long.
> > > 
> > > Because we allocate a new block of memory and then memcpy() the old
> > > block of memory into it.  This isn't surprising behaviour to me.
> > > I don't think there's much we can do to change it (Allocating a
> > > segmented array of file descriptors has previously been vetoed by
> > > people who have programs with a million file descriptors).  Is it
> > > causing you problems?
> > 
> > FWIW, I suspect that this is not so much allocation + memcpy.
> >         /* make sure all fd_install() have seen resize_in_progress
> >      * or have finished their rcu_read_lock_sched() section.
> >      */
> >     if (atomic_read(&files->count) > 1)
> >             synchronize_rcu();
> > 
> > in expand_fdtable() is a likelier source of delays.
> 
> Perhaps?  The delay seemed to be roughly doubling with the test program,
> so I assumed it was primarily the memcpy() cost for the reporter's
> system:
> 
> FD=64 duration=12565293
> FD=128 duration=24755063
> FD=256 duration=7602777
> 
> ... although now I've pasted it, I see my brain skipped one digit, so
> 256 was faster than 64, not about twice as slow as 128.

(via https://msgid.link/20230426203305.GW3390869@ZenIV)

(In reply to Bugbot from comment #1)
> Matthew Wilcox <willy@infradead.org> writes:
> 
> On Wed, Apr 26, 2023 at 05:58:06PM +0000, Kernel.org Bugbot wrote:
> > When running a threaded program, and opening a file descriptor that
> > is a power of 2 (starting at 64), the call takes a very long time to
> > complete. Normally such a call takes less than 2us. However with this
> > issue, I've seen the call take up to around 50ms. Additionally this only
> > happens the first time, and not subsequent times that file descriptor is
> > used. I'm guessing there might be some expansion of some internal data
> > structures going on. But I cannot see why this process would take so long.
> 
> Because we allocate a new block of memory and then memcpy() the old
> block of memory into it.  This isn't surprising behaviour to me.
> I don't think there's much we can do to change it (Allocating a
> segmented array of file descriptors has previously been vetoed by
> people who have programs with a million file descriptors).  Is it
> causing you problems?

Yes. I'm using using sockets for IPC. Specifically haproxy with its SPOE protocol. Low latency is important. Normally a call (including optional connect if a new connection is needed) will easily complete in under 100us. So I want to set a timeout of 1ms to avoid blocking traffic. However because this issue effectively randomly pops up, that 1ms timeout is too low, and the issue can actually impact multiple in-flight requests because haproxy tries to share that one IPC connection for them all. But if I raise the timeout (and I'd have to raise it to something like 100ms, as I've seen delays up to 47ms in just light testing), then I run the risk of significantly impacting traffic if there is a legitimate slowdown. While a low timeout and the occasional failure is probably the better of the two options, I'd prefer not to fail at all.

Christian Brauner <brauner@kernel.org> replies to comment #6:

On Wed, Apr 26, 2023 at 11:42:01PM +0000, Kernel.org Bugbot wrote:
> phemmer+kernel writes via Kernel.org Bugzilla:
> 
> (In reply to Bugbot from comment #1)
> > Matthew Wilcox <willy@infradead.org> writes:
> > 
> > On Wed, Apr 26, 2023 at 05:58:06PM +0000, Kernel.org Bugbot wrote:
> > > When running a threaded program, and opening a file descriptor that
> > > is a power of 2 (starting at 64), the call takes a very long time to
> > > complete. Normally such a call takes less than 2us. However with this
> > > issue, I've seen the call take up to around 50ms. Additionally this only
> > > happens the first time, and not subsequent times that file descriptor is
> > > used. I'm guessing there might be some expansion of some internal data
> > > structures going on. But I cannot see why this process would take so
> long.
> > 
> > Because we allocate a new block of memory and then memcpy() the old
> > block of memory into it.  This isn't surprising behaviour to me.
> > I don't think there's much we can do to change it (Allocating a
> > segmented array of file descriptors has previously been vetoed by
> > people who have programs with a million file descriptors).  Is it
> > causing you problems?
> 
> Yes. I'm using using sockets for IPC. Specifically haproxy with its SPOE
> protocol. Low latency is important. Normally a call (including optional
> connect if a new connection is needed) will easily complete in under 100us.
> So I want to set a timeout of 1ms to avoid blocking traffic. However because
> this issue effectively randomly pops up, that 1ms timeout is too low, and the
> issue can actually impact multiple in-flight requests because haproxy tries
> to share that one IPC connection for them all. But if I raise the timeout
> (and I'd have to raise it to something like 100ms, as I've seen delays up to
> 47ms in just light testing), then I run the risk of significantly impacting
> traffic if there is a legitimate slowdown. While a low timeout and the
> occasional failure is probably the better of the two options, I'd prefer not
> to fail at all.

I wonder if you could use io_uring for this. The problem sounds a lot
like it could be solved by using the fixed file descriptor feature. The
async and linking operation nature of it might be rather valuable for
this as well...

(via https://msgid.link/20230427-arbeit-davor-6b1b48bc555a@brauner)

Matthew Wilcox <willy@infradead.org> replies to comment #6:

On Wed, Apr 26, 2023 at 11:42:01PM +0000, Kernel.org Bugbot wrote:
> Yes. I'm using using sockets for IPC. Specifically haproxy with its
> SPOE protocol. Low latency is important. Normally a call (including
> optional connect if a new connection is needed) will easily complete
> in under 100us. So I want to set a timeout of 1ms to avoid blocking
> traffic. However because this issue effectively randomly pops up,
> that 1ms timeout is too low, and the issue can actually impact
> multiple in-flight requests because haproxy tries to share that one
> IPC connection for them all. But if I raise the timeout (and I'd have
> to raise it to something like 100ms, as I've seen delays up to 47ms in
> just light testing), then I run the risk of significantly impacting
> traffic if there is a legitimate slowdown. While a low timeout and
> the occasional failure is probably the better of the two options,
> I'd prefer not to fail at all.

A quick workaround for this might be to use dup2() to open a newfd
that is larger than you think your process will ever use.  ulimit -n
is 1024 (on my system), so choosing 1023 might be a good idea.
It'll waste a little memory, but ensures the fd array will never need to
expand.

(via https://msgid.link/ZEq8iSl985aqEy4%2B@casper.infradead.org)

(In reply to Bugbot from comment #8)
> Matthew Wilcox <willy@infradead.org> replies to comment #6:
> 
> On Wed, Apr 26, 2023 at 11:42:01PM +0000, Kernel.org Bugbot wrote:
> > Yes. I'm using using sockets for IPC. Specifically haproxy with its
> > SPOE protocol. Low latency is important. Normally a call (including
> > optional connect if a new connection is needed) will easily complete
> > in under 100us. So I want to set a timeout of 1ms to avoid blocking
> > traffic. However because this issue effectively randomly pops up,
> > that 1ms timeout is too low, and the issue can actually impact
> > multiple in-flight requests because haproxy tries to share that one
> > IPC connection for them all. But if I raise the timeout (and I'd have
> > to raise it to something like 100ms, as I've seen delays up to 47ms in
> > just light testing), then I run the risk of significantly impacting
> > traffic if there is a legitimate slowdown. While a low timeout and
> > the occasional failure is probably the better of the two options,
> > I'd prefer not to fail at all.
> 
> A quick workaround for this might be to use dup2() to open a newfd
> that is larger than you think your process will ever use.  ulimit -n
> is 1024 (on my system), so choosing 1023 might be a good idea.
> It'll waste a little memory, but ensures the fd array will never need to
> expand.

That's a good idea. I was originally considering opening a bunch of file descriptors one by one. But if it will grow even while skipping all the FDs in between, then that seems like it should work. At least for the app which I control. I don't know that it'd be a welcome change on the haproxy side though. And both sides would need it to completely alleviate the issue.