SYSTEMTAP: TRACE AIO REQUESTS

Body

Here is a small systemtap example that will print 'AIO' requests submitted by a process via 'io_submit()'. It will also print the list of 'AIO' requests that completed and collected by 'io_getevents()'.

The script includes some C functions and definitions that are used to extract information from the 'AIO' control blocks and event structures.

There is no 'filter' available for probes in systemtap so instead we check the program's name, 'tst' here, to restrict the amount of data collected.

NOTE: Systemtap script might need small modifications depending on the system
      you are executing them. This shall be true until all Linux flavors use
      a common set of syntax and probes.

The way to run it, as root, would be:

  # sudo stap -g -o aio1.out aio1.st

The output file would look like this:

  [info] tracking aio starts at Wed May 24 22:27:34 2017

  [tst - 8388 - 8388] io_submit(0x00002b7c4f545000, 2, 0x00007fff5b564c00) [retval = 2]
      iocb[   0] = 0x000000000efaa0d0, fd = 3, data = 0x000000000efaa070
      iocb[   1] = 0x000000000efaa110, fd = 3, data = 0x000000000efaa0a0
  [tst - 8388 - 8388] io_getevents(0x00002b7c4f545000, 0, 2, 0x000000000efaa160) [retval = 2]
      event[   0] = 0x000000000efaa160
        iocb = 0x000000000efaa0d0, fd = 3, data = 0x000000000efaa070
      event[   1] = 0x000000000efaa180
        iocb = 0x000000000efaa110, fd = 3, data = 0x000000000efaa0a0

  [info] tracking aio stops at Wed May 24 22:30:10 2017

The script is like this:

#! /usr/bin/env stap

/*
 * aio1.st: Track a few selected aio system calls.
 *
 * Run as user 'root' using the following command line:
 *
 *     stap -g -o aio1.out aio1.st
 *
 *
 * dalla
 */

/*
 * Set up things for dereferencing the AIO control blocks.
 */
%{
#include <linux/aio_abi.h>
%}

function get_iocb_ptr:long (ptr:long, num:long) %{ /* pure */
    long *addr;

    addr = (long *) (long) THIS->ptr;

    addr += THIS->num;

    THIS->__retvalue = kread(addr);

    CATCH_DEREF_FAULT();
%}

function get_iocb_fd:long (ptr:long) %{ /* pure */
    struct iocb *iocbp;

    iocbp = (struct iocb *) (long) THIS->ptr;

    THIS->__retvalue = kread(&(iocbp->aio_fildes));

    CATCH_DEREF_FAULT();
%}

function get_iocb_data:long (ptr:long) %{ /* pure */
    struct iocb *iocbp;

    iocbp = (struct iocb *) (long) THIS->ptr;

    THIS->__retvalue = kread(&(iocbp->aio_data));

    CATCH_DEREF_FAULT();
%}

function get_event_ptr:long (ptr:long, num:long) %{ /* pure */
    long addr;

    addr = (long) THIS->ptr;

    addr += sizeof(struct io_event) * THIS->num;

    THIS->__retvalue = addr;
%}

function get_event_data:long (ptr:long) %{ /* pure */
    struct io_event *event;

    event = (struct io_event *) (long) THIS->ptr;

    THIS->__retvalue = kread(&(event->data));

    CATCH_DEREF_FAULT();
%}

function get_event_obj:long (ptr:long) %{ /* pure */
    struct io_event *event;

    event = (struct io_event *) (long) THIS->ptr;

    THIS->__retvalue = kread(&(event->obj));

    CATCH_DEREF_FAULT();
%}

global in_io_submit
global in_io_getevents
global my_ioctx
global my_ionum
global my_iocb
global my_evctx
global my_evmin
global my_evmax
global my_evptr

probe begin
{
    printf("[info] tracking aio starts at %s\n", ctime(gettimeofday_s()));
}

probe syscall.io_submit
{
    if (isinstr(execname(), "tst")) {
        in_io_submit[tid()] = 1;
        my_ioctx[tid()] = $ctx_id;
        my_ionum[tid()] = $nr;
        my_iocb[tid()] = $iocbpp;
    }
}

probe syscall.io_submit.return
{
    if (in_io_submit[tid()] == 1) {
        printf("[%s - %d - %d] io_submit(%p, %d, %p) [retval = %d]\n",
               execname(), pid(), tid(),
               my_ioctx[tid()], my_ionum[tid()],
               my_iocb[tid()], $return);

        in_io_submit[tid()] = 0;

        if ($return > 0) {
            max = my_ionum[tid()];
            ptr = my_iocb[tid()];

            for (i = 0; i < max; i++) {
                iocb = get_iocb_ptr(ptr, i);
                fd = get_iocb_fd(iocb);
                data = get_iocb_data(iocb);
                printf("    iocb[%4d] = %p, fd = %d, data = %p\n",
                       i, iocb, fd, data);
            }
        }
    }
}

probe syscall.io_getevents
{
    if (isinstr(execname(), "tst")) {
        in_io_getevents[tid()] = 1;
        my_evctx[tid()] = $ctx_id;
        my_evmin[tid()] = $min_nr;
        my_evmax[tid()] = $nr;
        my_evptr[tid()] = $events;
    }
}

probe syscall.io_getevents.return
{
    if (in_io_getevents[tid()] == 1) {
        printf("[%s - %d - %d] io_getevents(%p, %d, %d, %p) [retval = %d]\n",
               execname(), pid(), tid(),
               my_evctx[tid()], my_evmin[tid()], my_evmax[tid()],
               my_evptr[tid()], $return);

        in_io_getevents[tid()] = 0;

        if ($return > 0) {
            max = $return;
            ptr = my_evptr[tid()];

            for (i = 0; i < max; i++) {
                ev = get_event_ptr(ptr, i);
                data = get_event_data(ev);
                obj = get_event_obj(ev);
                fd = get_iocb_fd(obj);
                printf("    event[%4d] = %p\n", i, ev);
                printf("      iocb = %p, fd = %d, data = %p\n", obj, fd, data);
            }
        }
    }
}

probe end
{
    printf("[info] tracking aio stops at %s\n", ctime(gettimeofday_s()));

    delete in_io_submit;
    delete in_io_getevents;
    delete my_ioctx;
    delete my_ionum;
    delete my_iocb;
    delete my_evctx;
    delete my_evmin;
    delete my_evmax;
    delete my_evptr;

    exit();
}