ProbeVue: Practical Introduction II

In the second part of the practical introduction of ProbeVue, the use of the interval probe manager and the special BEGIN clause will be presented. To illustrate this, a small monitoring tool, the process activity reporter (Vue script par.e), is to be developed as a continuous example. This should output the number of read and write system calls and the data transferred in KB/s for a selected process at 1 second intervals.

The Interval Probe Manager

With the help of a probe of the probe manager interval, an arbitrary action block can be executed at regular intervals. A probe point of the interval manager has the following form:

interval:*:clock:<number of milli seconds>

We choose a 1000 ms (1 second) interval and print a message every second:

#  cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter */

@@interval:*:clock:1000
{
        printf("clock tick\n");
}

#  chmod +x par.e
#

We start the Vue script par.e and check the output:

# ./par.e
clock tick
clock tick
clock tick
clock tick
^C
#

That looks pretty good, but is the interval between the messages really 1 second? ProbeVue offers the option of accessing the current time using the timestamp() function and outputting it using the printf() function with the conversion specifier "%A":

# cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter */

@@interval:*:clock:1000
{
        printf("%A clock tick\n",timestamp());
}

#

A quick test of the script shows that the interval is really 1 second:

# ./par.e
Mar/20/21 08:35:16 clock tick
Mar/20/21 08:35:17 clock tick
Mar/20/21 08:35:18 clock tick
Mar/20/21 08:35:19 clock tick
Mar/20/21 08:35:20 clock tick
^C
#

Global Variables

Next we want to count the number of read system calls of a process. For this we use the probe manager syscall again, as in the first part of the article. The PID of the process to be monitored has to be specified as an argument when the script is called. The probe point to be used is then:

@@syscall:$1:read:entry

Where "$1" stands for the first passed argument of the script (PID), and the read system call has been selected by the third field.

We store the number of read system calls in a global variable that we call nreads. The type of the variable is int, which allows the storage of integer values. The variable is automatically initialized with 0. As a further statement in the action block, we increase the variable nreads by 1 (++nreads). We extend the printf() statement in the action block of the interval probe to include the output of the integer variable nreads. Overall, the following script results:

# cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter */

@@interval:*:clock:1000
{
        printf("%A %d\n",timestamp(),nreads);
}

@@syscall:$1:read:entry
{
        int nreads;
        ++nreads;
}

#

Every time the specified process starts a read system call, the value of the global variable nreads is increased by 1. After one second, the current timestamp is printed, together with the number of read system calls that have been executed since the Vue script was started:

# ./par.e 10682852
Mar/20/21 08:53:30 0
Mar/20/21 08:53:31 779
Mar/20/21 08:53:32 779
Mar/20/21 08:53:33 779
Mar/20/21 08:53:34 779
Mar/20/21 08:53:35 779
Mar/20/21 08:53:36 779
Mar/20/21 08:53:37 779
Mar/20/21 08:53:38 884
Mar/20/21 08:53:39 1662
Mar/20/21 08:53:40 1662
Mar/20/21 08:53:41 1662
Mar/20/21 08:53:42 1662
Mar/20/21 08:53:43 1662
Mar/20/21 08:53:44 1767
Mar/20/21 08:53:45 1767
^C
#

The declaration of the global variable nreads (line: "int nreads;") can also be made outside the action block, before all clauses. It may then be easier to see that this variable is global and can be used anywhere.

Instead of absolute values, we would like to print the number of calls in the last time interval. For this we need a second global variable (we use oreads), in which the count at the beginning of the interval is remembered. By forming the difference (nreads - oreads) we get the number of calls during the last time interval:

# cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter  */

int nreads;
int oreads;

@@interval:*:clock:1000
{
        printf("%A %d\n",timestamp(),nreads-oreads);
        oreads = nreads;
}

@@syscall:$1:read:entry
{
        ++nreads;
}

#

A test run of the Vue script shows that it delivers the desired output:

# ./par.e 10682852
Mar/20/21 09:47:29 0ll
Mar/20/21 09:47:30 0
Mar/20/21 09:47:31 0
Mar/20/21 09:47:32 779
Mar/20/21 09:47:33 105
Mar/20/21 09:47:34 778
Mar/20/21 09:47:35 0
Mar/20/21 09:47:36 0
Mar/20/21 09:47:37 105
Mar/20/21 09:47:38 778
Mar/20/21 09:47:39 0
Mar/20/21 09:47:40 105
^C
#

Determining the Read Throughput

The number of bytes to be read must be specified for each read system call. The call to read looks like this ("man 2 read"):

ssize_t  read  (FileDescriptor,  Buffer,  NBytes)
       int FileDescriptor;
       void  * Buffer;
       size_t NBytes;

The third argument is the number of bytes to read. From the first part of the article we already know that you have to declare the system call with arguments in the form of a function prototype, if you want to access the arguments in the Vue script. Accordingly, we adopt the following declaration for the read system call in our script:

ssize_t read( int FileDescriptor , void* Buffer , size_t NBytes );

The third argument can then be accessed in the script using the special builtin variable __arg3. For the bytes read, we introduce the two global variables nreadBytes and oreadBytes, analogous to the two previous variables. In the action block of the syscall probe we use __arg3 to sum up the number of bytes read. And in the action block for the interval probe, we print the bytes read in the interval:

# cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter  */

ssize_t read( int FileDescriptor , void* Buffer , size_t NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;

@@interval:*:clock:1000
{
        printf("%A %d %d\n",timestamp(),nreads-oreads,nreadBytes-oreadBytes);
        oreads = nreads;
        oreadBytes = nreadBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

#

Unfortunately, the script can no longer be started, an error message appears immediately:

# ./par.e 10682852
./par.e: 8: unsupported operator in typecast: ,
#

Line 8 contains the declaration of the read system call. The problem is that ProbeVue does not recognize the user-defined data types ssize_t and size_t. The type ssize_t is ultimately the data type signed long, and the type size_t is the data type unsigned long. The latter data types are known to ProbeVue. We therefore replace the two user-defined data types ssize_t and size_t in the declaration of read with the data types signed long and unsigned long.

# cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter  */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;

@@interval:*:clock:1000
{
        printf("%A %d %d\n",timestamp(),nreads-oreads,nreadBytes-oreadBytes);
        oreads = nreads;
        oreadBytes = nreadBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

#

Now the Vue script can be started again and produces the desired output:

# ./par.e 10682852
Mar/20/21 10:26:58 0 0
Mar/20/21 10:26:59 0 0
Mar/20/21 10:27:00 0 0
Mar/20/21 10:27:01 0 0
Mar/20/21 10:27:02 779 2500602
Mar/20/21 10:27:03 0 0
Mar/20/21 10:27:04 105 85632
Mar/20/21 10:27:05 778 2496506
Mar/20/21 10:27:06 105 85632
Mar/20/21 10:27:07 778 2496506
Mar/20/21 10:27:08 105 85632
Mar/20/21 10:27:09 0 0
Mar/20/21 10:27:10 0 0
Mar/20/21 10:27:11 0 0
^C
#

Since we are also interested in the write system calls and the associated throughput, we expand our script and also monitor the write system calls. Like the read system call, the write system call has 3 arguments, the third argument being the number of bytes to be written. So we can essentially take the code from read and simply replace read with write:

# cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );
signed long write( int FileDescriptor , const void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;
int nwrites;
int owrites;
int nwriteBytes;
int owriteBytes;

@@interval:*:clock:1000
{
        printf("%A %d %d %d %d\n",timestamp(),nreads-oreads,nreadBytes-oreadBytes,nwrites-owrites,nwriteBytes-owriteBytes);
        oreads = nreads;
        oreadBytes = nreadBytes;
        owrites = nwrites;
        owriteBytes = nwriteBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

@@syscall:$1:write:entry
{
        ++nwrites;
        nwriteBytes += __arg3;
}

#

The script works right away and now provides both the number of read and write operations of a process as well as the corresponding throughput:

# ./par.e 10682852
Mar/20/21 10:33:59 0 0 0 0
Mar/20/21 10:34:00 0 0 0 0
Mar/20/21 10:34:01 0 0 0 0
Mar/20/21 10:34:02 779 2500602 94 3530
Mar/20/21 10:34:03 0 0 0 0
Mar/20/21 10:34:04 0 0 0 0
Mar/20/21 10:34:05 105 85632 6 1966
Mar/20/21 10:34:06 778 2496506 94 3530
Mar/20/21 10:34:07 105 85632 6 1966
Mar/20/21 10:34:08 778 2496506 94 3530
Mar/20/21 10:34:09 105 85632 6 1966
Mar/20/21 10:34:10 0 0 0 0
Mar/20/21 10:34:11 0 0 0 0
^C
#

Formatted Output

The output of the individual columns shifts from line to line, which makes the output less readable. The function printf() offers the possibility of specifying the width of an output field; the required number of characters is specified in the format string after the "%" character. If an output is shorter, it is simply padded with spaces. For the number of read or write system calls, we initially provide a maximum of 6-digit output; for the throughput values, we would like output in KB/s, whereby we provide up to 7 digits here. To get to KB, we have to divide by 1024. Since integer division does not round, we round ourselves by adding 512 in the nominator:

# cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter  */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );
signed long write( int FileDescriptor , const void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;
int nwrites;
int owrites;
int nwriteBytes;
int owriteBytes;

@@interval:*:clock:1000
{
        printf("%A %6d %7d KB/s %6d %7d KB/s\n",timestamp(),nreads-oreads,(nreadBytes-oreadBytes+512)/1024,nwrites-owrites,(nwriteBytes-owriteBytes+512)/1024);
        oreads = nreads;
        oreadBytes = nreadBytes;
        owrites = nwrites;
        owriteBytes = nwriteBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

@@syscall:$1:write:entry
{
        ++nwrites;
        nwriteBytes += __arg3;
}

#

A test of the new script version shows that the columns are now correctly displayed, which is much easier to read:

# ./par.e 10682852
Mar/20/21 11:47:19      0       0 KB/s      0       0 KB/s
Mar/20/21 11:47:20      0       0 KB/s      0       0 KB/s
Mar/20/21 11:47:21    778    2438 KB/s     94       3 KB/s
Mar/20/21 11:47:22    105      84 KB/s      6       2 KB/s
Mar/20/21 11:47:23    779    2442 KB/s     94       3 KB/s
Mar/20/21 11:47:24    119      97 KB/s      4       2 KB/s
Mar/20/21 11:47:25    778    2438 KB/s     94       3 KB/s
Mar/20/21 11:47:26     73      31 KB/s     18       6 KB/s
^C
#

BEGIN Block

It would be nice to have a heading above the individual columns, so that it is clear which values are shown in which column. The heading would have to be printed once, at the beginning of the script, before one of the action blocks is executed. ProbeVue offers the option of defining a so-called BEGIN block. For this purpose, "@@BEGIN" is used as a pseudo probe type. The following action block is then executed once at the beginning of the script run. We use such a BEGIN block to print a heading for the columns using printf():

# cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter  */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );
signed long write( int FileDescriptor , const void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
int nreadBytes;
int oreadBytes;
int nwrites;
int owrites;
int nwriteBytes;
int owriteBytes;

@@BEGIN
{
        printf("%18s %6s %7s      %6s %7s\n","TIMESTAMP","#READ","READ/s","#WRITE","WRITE/s");
}

@@interval:*:clock:1000
{
        printf("%A %6d %7d KB/s %6d %7d KB/s\n",timestamp(),nreads-oreads,(nreadBytes-oreadBytes+512)/1024,nwrites-owrites,(nwriteBytes-owriteBytes+512)/1024);
        oreads = nreads;
        oreadBytes = nreadBytes;
        owrites = nwrites;
        owriteBytes = nwriteBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

@@syscall:$1:write:entry
{
        ++nwrites;
        nwriteBytes += __arg3;
}

#

So, now all columns have a heading:

# ./par.e 2568903
         TIMESTAMP  #READ  READ/s      #WRITE WRITE/s
Mar/20/21 13:02:46      1      16 KB/s   5914  378432 KB/s
Mar/20/21 13:02:47     13      17 KB/s   5702  364160 KB/s
Mar/20/21 13:02:48     17     256 KB/s   3048  190977 KB/s
Mar/20/21 13:02:49      2      16 KB/s      1       0 KB/s
Mar/20/21 13:02:50     12      39 KB/s   4863  304977 KB/s
Mar/20/21 13:02:51      4      16 KB/s  10671  682816 KB/s
Mar/20/21 13:02:52      1      16 KB/s  11470 -3460287 KB/s
Mar/20/21 13:02:53     22     241 KB/s   5931  375361 KB/s
^C
#

Some Improvements

If you take a closer look at the last output, especially the line from 13:02:52, you can see that there is a negative value there. That is very ugly, and the value is certainly not correct! The reason for this lies in the fact that we have used the data type int (32-bit) for the number of bytes read and written. Obviously there was an overflow here! The data type for the number of bytes in the read and write system call was unsigned long (64-bit). We therefore change the data type from int to unsigned long for the variables storing the number of bytes. When using printf() we have to make sure to change the format specifier from "%7d" (32-bit integer) to "%7lld" (64-bit integer):

#  cat par.e
#! /usr/bin/probevue

/* Description: A process activity reporter */

signed long read( int FileDescriptor , void* Buffer , unsigned long NBytes );
signed long write( int FileDescriptor , const void* Buffer , unsigned long NBytes );

int nreads;
int oreads;
unsigned long nreadBytes;
unsigned long oreadBytes;
int nwrites;
int owrites;
unsigned long nwriteBytes;
unsigned long owriteBytes;

@@BEGIN
{
        printf("%18s %6s %7s      %6s %7s\n","TIMESTAMP","#READ","READ/s","#WRITE","WRITE/s");
}

@@interval:*:clock:1000
{
        printf("%A %6d %7lld KB/s %6d %7lld KB/s\n",timestamp(),nreads-oreads,(nreadBytes-oreadBytes+512)/1024,nwrites-owrites,(nwriteBytes-owriteBytes+512)/1024);
        oreads = nreads;
        oreadBytes = nreadBytes;
        owrites = nwrites;
        owriteBytes = nwriteBytes;
}

@@syscall:$1:read:entry
{
        ++nreads;
        nreadBytes += __arg3;
}

@@syscall:$1:write:entry
{
        ++nwrites;
        nwriteBytes += __arg3;
}

#

After this correction, the overflow no longer occurs (or only occurs after approx. 16 million TB).

With the presented Vue script, the I/O behavior of individual processes can be observed quite well. Of course, many further improvements are possible. But this is left to the reader.

More Articles on ProbeVue

ProbeVue: Practical Introduction

ProbeVue in Action: Identifying a crashing Process?

ProbeVue in Action: Monitoring the Queue Depth of Disks

Weitere Artikel zum Thema ProbeVue

ProbeVue: Praktische Einführung

ProbeVue: Praktische Einführung II

ProbeVue in Action: Identifizieren eines Abstürzenden Prozesses?

ProbeVue in Action: überwachen der ?Queue Depth“ von Platten