I/O probe manager

I/O probe manager provides capabilities to trace I/O operation events in various layers of AIX® I/O stack. Use the syscall probe manager to trace application I/O request that is triggered by a read/write system call. Use I/O probe manager to probe further into the syscall layer.

Use I/O probe manager to analyze response time of I/O operations of a block device that segregates the service time and queuing delay.

The following layers are supported:

• Logical File System (LFS)
• Virtual File System (VFS)
• Enhanced Journaled File Systems (JFS2)
• Logical Volume Manager (LVM)
• Small Computer System Interface (SCSI) disk driver
• Generic block devices

The primary use cases for I/O probe manager are as follows:

• Identify the following patterns of I/O usage of a device. Valid devices can be a disk, logical volume, or volume group, or file system (type or mount path) in a specified time period:
  • I/O operation count
  • Size of I/O operations
  • Type of I/O operation (read/write)
  • Sequential or random nature of I/O
• Get process or thread-wise usage information of a file system (type or mount path), logical volume, volume group, or disk.
• Get an end-to-end mapping of I/O flow among various layers (wherever possible).
• Monitor a specific I/O resource usage. For example:
  • Trace any write operations of the /etc/password file.
  • Trace read operation on block 0 of the hdisk0 device.
  • Trace when a new logical volume is opened in root volume group (rootvg).
• For Multipath I/O (MPIO) disks, get path-specific information by the following actions:
  • Get path-wise usage and response time information.
  • Identify path switching or path failure.
• For I/O errors, get more details about the error in disk driver layer.

Probe specification

I/O probes must be specified in the following format in Vue script:

@@io:sub_type:io_event:operation_type:filter[|filter …]

Probe sub type

The second tuple signifies the sub type of the probe that indicates the layer of AIX I/O stack that contains the probe. This tuple can have one of the following values:

For a disk type of second tuple, the third tuple can have the following values:

For every entry, a corresponding exit probe is defined that has the same __iobuf->bufid value available at both the probe points. The entry event can be followed by multiple iostart events, but at least one of them must have the same __iobuf->bufid value. Every iostart event has a matching iodone event that has the same __iobuf->child_bufid value.

For an LVM type of second tuple, the third tuple can have the following values:

For generic block device probes, the third tuple can have the following values:

For JFS2 file system probes, the third tuple can have the following values:

For Virtual file system (VFS) probes, the third tuple can have the following values:

Probe operation type

The fourth tuple indicates the type of I/O operation that is specified by the probe. The fourth tuple can have one of the following values:

Probe filter

The fifth tuple is the filter tuple that helps in filtering more specific probes according to the requirement. The possible values are subtype dependent. Multiple values can be specified separated by | character, and the probe starts if it matches any of those filters. If the value of the fifth tuple is *, no filtering occurs and the probe starts if other tuples match. If multiple selectors are specified, and one of them is *, it is equivalent to the whole tuple value of *.

For disk probes, the fifth tuple can have the following values:

@@io:disk:entry:*:hdisk0|FC

For Logical Volume Manager (LVM) probes, the fifth tuple can have the following values:

The following probe starts for any logical volume that belongs to either root volume group (rootvg), or test volume group (testvg) (at iostart event, for write operation only):

@@io:lvm:iostart:write:rootvg|testvg

Consider the following examples for generic block device probes:

@@io:bdev:iostart:*:cd0

@@io:bdev:iodone:read:hdisk3|hdisk5

For JFS2 file system probes, the fifth tuple can have following values:

Consider following examples for the JFS2 file system probes:

@@io:jfs2:buf_map:*:/usr|/tmp

For Virtual file system (VFS) probes, the fifth tuple can have following values:

Consider the following examples for the Virtual file system (VFS) probes:

@@io:vfs:entry:read:JFS2

@@io:vfs:exit:*:/usr|JFS

I/O probe related built-in variables for Vue scripts

You can use the special __iobuf built-in variable to access various information about the I/O buffer that is employed in the current I/O operation. It is accessible in probes of sub types: disk, lvm, and bdev. Its member elements can be accessed by using the __iobuf->member syntax.

__iobuf built-in variable has the following members:

__file built-in variable

You can use the __file special built-in variable to get various information about file operation. It is available in probes of sub type VFS. Its member elements can be accessed by using the __file->member syntax.

The __file built-in variable has the following members:

__lvol built-in variable

__volgrp built-in variable

__volgrp built-in variable has following members:

__diskinfo built-in variable

__diskcmd built-in variable

__diskcmd built-in variable has following members:

__iopath built-in variable

__iopath has following members:

__j2info built-in variable

__j2info has the following members:

Example scripts for I/O probe manager

1. Script to trace any write operation to the /etc/passwd file:

   
   int write(int, char *, int);
   @@BEGIN  {
           target_inodeid = fpath_inodeid("/etc/passwd");
   }
   @@syscall:*:write:entry {
           if (fd_inodeid(__arg1) == target_inodeid) {
                   printf("write on /etc/passwd: timestamp=%A, pid=%lld, pname=[%s], uid=%lld\n",
                           timestamp(), __pid, __pname, __uid);
           }
   }
   If the scripts is in a VUE file, names etc_passwd.e. The script can be run as:
   # probevue etc_passwd.e
   In another terminal, if the user (root) runs:
   # mkuser user1
   Then probevue displays an output similar to the following example:
   write on /etc/passwd: timestamp=Mar/03/15 16:10:07, pid=14221508, pname=[mkuser], uid=0
   
   

2. Script to find the maximum and minimum I/O operation time for a disk (for example, hdisk0) in a period. Also, find the block number, requested byte count, time of operation and type of operation (read or write) corresponding to the maximum or minimum time.

long long min_time, max_time;
@@BEGIN {
        min_time = max_time = 0;
}
@@io:disk:entry:*:hdisk0 {
        ts_entry[__iobuf->bufid] = (long long)timestamp();
}
@@io:disk:exit:*:hdisk0 {
        if (ts_entry[__iobuf->bufid]) { /* only if we recorded entry time */
                ts_now = timestamp();
                op_type = (__iobuf->bflags & B_READ) ? "READ" : "WRITE";
                dt = (long long)diff_time(ts_entry[__iobuf->bufid], ts_now, MICROSECONDS);
                if (min_time == 0 || dt < min_time) {
                        min_time = dt;
                        min_blknum = __iobuf->blknum;
                        min_bcount = __iobuf->bcount;
                        min_ts = ts_now;
                        min_optype = op_type;
                }
                if (max_time == 0 || dt > max_time) {
                        max_time = dt;
                        max_blknum = __iobuf->blknum;
                        max_bcount = __iobuf->bcount;
                        max_ts = ts_now;
                        max_optype = op_type;
                }
                ts_entry[__iobuf->bufid] = 0;
        }
}
@@END {
        printf("Maximum and minimum IO operation time for [hdisk0]:\n");
        printf("Max: %lld usec, block=%lld, byte count=%lld, operation=%s, time of operation=[%A]\n",
                max_time, max_blknum, max_bcount, max_optype, max_ts);
        printf("Min: %lld usec, block=%lld, byte count=%lld, operation=%s, time of operation=[%A]\n",
                min_time, min_blknum, min_bcount, min_optype, min_ts);
}

Let this script be in a VUE file named disk_min_max_time.e. It can be executed as:
# probevue disk_min_max_time.e
Let there be some IO activity on hdisk0 (dd command can be used). 
Then after a few minutes, if the above command is terminated (by pressing CTRL-C), then it will print output similar to:
^CMaximum and minimum IO operation time for [hdisk0]:
Max: 48174 usec, block=6927976, byte count=4096, operation=READ, time of operation=[Mar/04/15 03:31:07]
Min: 133 usec, block=6843288, byte count=4096, operation=READ, time of operation=[Mar/04/15 03:31:03]