Skip to content

Instantly share code, notes, and snippets.

@WoZ WoZ/README.md
Last active Dec 2, 2019

Embed
What would you like to do?
Strace reads and writes analyzer

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.

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
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`);
}
});
}
}
}
});
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.