DFLY: syscall frequency

April 29th, 2008

What does the syscall traffic look like for a “make buildkernel”?

% ktrace -di -f /home/dion/projects/syscall-hist/trace1.ktlog -t c make buildkernel
% ktrace -di -f /home/dion/projects/syscall-hist/trace2-cw.ktlog -t cw make buildkernel

Then, I used this “thing” to chew the log files and spit out a nicer form. This code is pretty loosely based on the source to kdump.

#include <sys/ktrace.h>
#include <sys/time.h>
 
#include <err.h>
#include <errno.h>
#include <stdio.h>
#include <stdlib.h>
 
static void process_ktrace_log(FILE *logf);
 
uint64_t syscalls[512] = { 0 };
 
int main(int argc, char *argv[]) {
    FILE *logf;
 
    logf = fopen(argv[1], "r");
    process_ktrace_log(logf);
    fclose(logf);
 
    return 0;
}
 
static void process_ktrace_log(FILE *logf) {
    struct ktr_header ktrhdr;
    struct timeval tv_curr, tv_first, *tvp_first = NULL;
    int ktrlen;
    char *m = NULL;
    int m_size = 0;
 
    FILE *logsc = fopen("sc.log", "w");
    FILE *logcsw = fopen("csw.log", "w");
 
    while (fread(&ktrhdr, sizeof(struct ktr_header), 1, logf) == 1) {
        if ((ktrlen = ktrhdr.ktr_len) < 0)
            errx(1, "bogus length 0x%x", ktrlen);
        if (ktrlen > m_size) {
            m = (void *)realloc(m, ktrlen+1);
            if (m == NULL)
                errx(1, "%s", strerror(ENOMEM));
            m_size = ktrlen;
        }
 
        if (ktrlen && fread(m, ktrlen, 1, logf) == 0)
            errx(1, "data too short");
 
        if (!tvp_first) {
            tv_first = ktrhdr.ktr_time;
            tvp_first = &tv_first;
        }
 
        timersub(&ktrhdr.ktr_time, tvp_first, &tv_curr);
 
        switch (ktrhdr.ktr_type) {
            case KTR_SYSCALL:
                {
                    struct ktr_syscall *ktrsc = (struct ktr_syscall *)m;
                    fprintf(logsc, "%16lld %d\n", 
                            (uint64_t) tv_curr.tv_sec * 1000000L +
                                       tv_curr.tv_usec,
                            ktrsc->ktr_code);
                    syscalls[ktrsc->ktr_code]++;
                }
                break;
            case KTR_CSW:
                {
                    struct ktr_csw *ktrcsw = (struct ktr_csw *)m;
                }
                break;
            default:
                break;
        }
    }
 
    fclose(logsc);
    fclose(logcsw);
 
    {
        FILE *schistlog = fopen("schist.log", "w");
        int i;
 
        for(i = 0; i < 512; i++) {
            if (syscalls[i]) fprintf(schistlog, "%d %lld\n", i, syscalls[i]);
        }
 
        fclose(schistlog);
    }
}

Then I used this gnuplot input to generate a quick plot:

set terminal png
set output 'schist-1m.png'
set xrange [0:60000000]
plot "sc.log" using 1:2 with dots

Finally, I used this little python script (I’m guessing some awk/sed genius could do it on the command line, but I can’t):

#!/usr/pkg/bin/python2.4
 
import sys
import re
 
sc = open("/usr/include/sys/syscall.h")
scdict = {}
for line in sc.readlines():
    mo = re.match("^#define\s+SYS_(\S+)\s+(\d+)\s*$", line)
    if mo is not None:
        scdict[mo.group(2)] = mo.group(1)
sc.close()
 
dpair_re = re.compile("^\s*(\d+) (\d+)$")
for line in sys.stdin.readlines():
    mo = dpair_re.match(line)
    if mo is not None:
        print '%15s %3s %s' % (mo.group(2), mo.group(1), scdict[mo.group(1)])

Then I sorted it on the command line:
% ./schist.py < schist.log | sort -rn > schist-chew.log

And the top 15 are: (full results)

        1047837 197 mmap
         828677   5 open
         412613   3 read
         355321   6 close
         343725 476 fstat
         287935  73 munmap
         278365 475 stat
         114136   4 write
         108059 342 sigaction
          88929 199 lseek
          64747 477 lstat
          42090  92 fcntl
          40985 472 set_tls_area
          29434 253 issetugid
          27946  59 execve

[EDIT] Added the graph and final results.

2 Responses to “DFLY: syscall frequency”

  1. Jonathan Says:

    Please include links to the ouput you generated, thanks!

  2. dionthegod Says:

    Added the graph and some of the results (with link to the full results).

    More data may pop up here.

Leave a Reply