[PATCH] Enhance time sampling of async IO VFS functions

[Ralph Boehme]

On Fri, Feb 26, 2016 at 09:12:05AM -0800, Jeremy Allison wrote:
> On Fri, Feb 26, 2016 at 03:33:42PM +0100, Ralph Boehme wrote:
> > Hi!
> > 
> > The problem:
> > 
> > when using vfs_time_audit to log slow VFS functions, a blocking sync
> > operation will cause previously sheduled async IO operations to
> > accumulate the penalty from the blocking sync operation. Example:
> > 
> > 1. SMB2 read request received, added to the async queue
> > 
> > 2. SMB2 create_file request comes in, is processed and blocks
> > 
> > 3. async read completes in the dispatcher thread, completion callback
> >    will be called when we enter the main tevent loop
> > 
> > 4. open() completes after N seconds
> > 
> > 5. main tevent event loop is entered, async results are processed
> > 
> > 6. async read result is processed, time sampling will include the N
> >    seconds blocked in open()
> > 
> > Fixing this involves adding time sampling to all async IO "backends"
> > (libasys, used in vfs_default, and all VFS modules that do their own
> > async IO, so glusterfs, aio_fork and aio_linux) and passing the time
> > sample up the VFS stack.
> > 
> > For passing it up the VFS stack I need to stick an additional arg to
> > all $IO_recv() VFS functions, which is cumbersome but the only way I
> > see to get this through.
> 
> I like what you're trying to do but I *hate* adding the extra
> arg to the VFS functions. Can we think of any other way to do
> this ?

We could also just use one pointer arg to a struct vfs_aio_state or
similar, instead of keep adding args over the years.

> As all these functions take a tevent_req pointer can't you
> do something clever with using the talloc hierarchy to pass
> up the extra data ?

Yes, I though about that too, see below.

> Hmmm. Looks to me like adding:
> 
> _PUBLIC_ void *talloc_find_child_byname(const void *context, const char *name)
> 
> would be a great addition to talloc for this :-).

I though about adding struct tevent_req.async.(uint64_t)duration and
getter/setter functions
tevent_req_set_duration()/tevent_req_get_duration().

This could then be used by the implementation of an async request to
set the duration and the caller can read it, further passing up the
stack and processing as needed.

-Ralph

-- 
SerNet GmbH, Bahnhofsallee 1b, 37081 Göttingen
phone: +49-551-370000-0, fax: +49-551-370000-9
AG Göttingen, HRB 2816, GF: Dr. Johannes Loxen
http://www.sernet.de,mailto:kontakt@sernet.de