Strace reads and writes analyzer

README.md

Usage: node strace_log_analyzer.js strace.log /tmp

This scripts parses input file that must contain strace log from a single thread. Then script calculates:

• execution time of read/write syscall for each file descriptor and summarize execution time for each 1 sec period,
• calulates amount of read/write syscalls for each file descriptor

strace log must be collcted with -t -T -f options.

After execution you may find data that is ready for plotting.

You may use the gnuplot script attached.

reads.gnu

reset
set ylabel "Execution time of read calls, summarized in 1 sec, mean by 5 points"
set xlabel "Time"
set xdata time
set timefmt "%H:%M:%S"
set format x "%H:%M:%S"

set datafile missing

samples(x) = $0 > 4 ? 5 : ($0+1)
avg5(x) = (shift5(x), (back1+back2+back3+back4+back5)/samples($0))
shift5(x) = (back5 = back4, back4 = back3, back3 = back2, back2 = back1, back1 = x)

init(x) = (back1 = back2 = back3 = back4 = back5 = sum = 0)

set style line 1  lc rgb '#696969' lt 1 lw 1 pt 5 ps 0.5
set style line 2  lc rgb '#D2691E' lt 1 lw 1 pt 5 ps 0.5

plot sum = init(0), 'read_20197_129.log' using 1:(avg5($2)) title "fd=129" w linespoints ls 1, \
     sum = init(0), 'read_20197_131.log' using 1:(avg5($2)) title "fd=131" w linespoints ls 2

strace_log_analyzer.js

const readline = require('readline');
const fs = require('fs');

const argv = process.argv.slice(2);
if (argv.length !== 2) {
    console.error('Invalid arguments');
    process.exit(1);
}

const inputFile = argv[0];
const outputDir = argv[1];

const READ_MARKER = 'read(';
const WRITE_MARKER = 'write(';
const READ_CALL_NAME = 'read';
const WRITE_CALL_NAME = 'write';
const UNFINISHED_OP_MARKER = ' <unfinished ...>';
const RESUMED_OP_MARKER = 'resumed>';
const EAGAIN_MARKER = 'EAGAIN (Resource temporarily unavailable)';
const RETURN_CODE_AND_EXEC_TIME_REGEXP = new RegExp(/\s(-?\d+)\s<([\d\.]+)>/);

const lineReader = readline.createInterface({
    input: fs.createReadStream(inputFile)
});

const operations = {
    read: {},
    write: {},
};

let callName;
let unfinishedLine;
let callPos;

lineReader.on('line', line => {
    if (!unfinishedLine) {
        callPos = line.indexOf(WRITE_MARKER);
        if (callPos < 0) {
            callPos = line.indexOf(READ_MARKER);
            if (callPos < 0) {
                return;
            } else {
                callName = READ_CALL_NAME;
            }
        } else {
            callName = WRITE_CALL_NAME;
        }

        const unfinishedPos = line.indexOf(UNFINISHED_OP_MARKER);
        if (unfinishedPos > 0) {
            // Remember this line and skip processing.
            // Processing will continue on the next function call.
            unfinishedLine = line.substr(0, unfinishedPos);
            return;
        }
    } else {
        const resumedPos = line.indexOf(RESUMED_OP_MARKER);
        if (resumedPos > 0) {
            line = unfinishedLine + line.substr(resumedPos + RESUMED_OP_MARKER.length + 1);
            unfinishedLine = undefined;
        } else {
            process.stderr.write('Resume operation was not found\n');
            process.stderr.write(`Unfinished line: ${unfinishedLine}\n`);
            process.stderr.write(`Current line: ${line}\n`);
            process.stderr.write('Execution is stopping...\n');
            process.exit();
        }
    }

    if (line.indexOf(EAGAIN_MARKER) > 0) {
        // EAGAIN indicates that no data available at the moment, it's normal behaviour for non blocking ops
        return;
    }

    const pidPos = line.indexOf(' ');
    if (pidPos < 0) {
        process.stderr.write('pid marker was not found.\n');
        process.stderr.write(`Current line: ${line}\n`);
    }

    const pid = line.substr(0, pidPos);

    const time = line.substr(6, 8);

    if (callPos > 0) {
        const endOfFdPos = line.indexOf(',', callPos);
        const fd = line.substr(callPos + callName.length + 1, endOfFdPos - callPos - callName.length - 1);
        const returnCodeDelimPos = line.lastIndexOf('=');
        if (returnCodeDelimPos < 0) {
            process.stderr.write('Delimiter for syscall return value was not found.\n');
            process.stderr.write(`Current line: ${line}\n`);
        }

        const returnCodeAndExecTime = line.substr(returnCodeDelimPos + 1);
        const matches = returnCodeAndExecTime.match(RETURN_CODE_AND_EXEC_TIME_REGEXP);
        if (!matches) {
            process.stderr.write('No matches for return code and exec time pattern.\n');
            process.stderr.write(`Current line: ${line}\n`);
            return;
        }

        const returnCode = parseInt(matches[1]);
        const execTime = parseFloat(matches[2]);

        if (returnCode < 0) {
            process.stderr.write(`${callName} returned with error ${returnCode}\n`);
            process.stderr.write(`Current line: ${line}\n`);
        }

        // If returnCode > 0 it indicates amount of bytes transferred.
        if (!operations[callName][pid]) {
            operations[callName][pid] = {};
        }

        if (!operations[callName][pid][fd]) {
            operations[callName][pid][fd] = {};
        }

        if (!operations[callName][pid][fd][time]) {
            operations[callName][pid][fd][time] = {
                execTime: execTime,
                bytesTransferred: returnCode,
                calls: 0
            };
        } else {
            operations[callName][pid][fd][time].execTime += execTime;
            operations[callName][pid][fd][time].bytesTransferred += returnCode;
            operations[callName][pid][fd][time].calls++;
        }
    }
});


lineReader.on('close', () => {
    let bytesPerCall = 0;

    for (let op in operations) {
        for (let pid in operations[op]) {
            for (let fd in operations[op][pid]) {
                let fileContent = '# TIME EXEC_TIME BYTES_TRANSFERRED BYTES_PER_CALL\n';
                for (let time in operations[op][pid][fd]) {
                    bytesPerCall = Math.floor(
                        operations[op][pid][fd][time].bytesTransferred / operations[op][pid][fd][time].calls
                    );

                    fileContent +=
                        `${time} ${operations[op][pid][fd][time].execTime} ` +
                        `${operations[op][pid][fd][time].bytesTransferred} ${bytesPerCall}\n`;
                }

                const fileName = `${outputDir}/${op}_${pid}_${fd}.log`;

                fs.writeFile(fileName, fileContent, err => {
                    if (err) {
                        process.stderr.write(`Error on writing to ${fileName}: ${err}\n`);
                    }
                });
            }
        }
    }
});