This is the next generation of strace analyzer that uses the elapsed time capability of the strace function. This is more precise than the previous version. There are some other changes to make things a bit easier for managing data and for future upgrades.

Link to versions and source

How to create an strace file

Creating the strace file that is appropriate for the strace analyzer involves just a few options. The required options are:

strace -T -ttt -o strace.out <application>

The "-T" option cause strace to print out the elapsed time at the end of the line in the form, <0.000197>. The option "-ttt" causes microsecond timing but does so in seconds since the epoch (makes life easier for applications that run a long time.

If you want to reduce the amount of output then you can try the following:

strace -T -ttt -e trace=open,close,read,write,lseek,llseek,_llseek,fsync,fstat,fstat64,... -o strace.out

You can add almost any IO function you want to the "trace=..." line. The options that the strace analyzer current recognizes is,

• read
• write
• open
• close
• lseek
• llseek
• __llseek
• stat
• stat64
• fstat
• chmod
• access
• rename
• mkdir
• getdents
• fcntl
• unlink
• fseek
• rewind
• ftell
• fgetpos
• fsetpos
• fclose
• fsync
• creat
• readdir
• opendir
• rewinddir
• scandir
• seekdir
• telldir
• flock
• lockf
  

Other IO operations will be added later (asynchronous IO, fread, fwrite, etc.).

Strace_analyzer Options:

There are several options for the strace analyzer. You an get a listing of the options by using the help option. For example,

$ ./strace_analyzer_ng_0.03.pl -help
Usage: strace-analyze [OPTION]... [FILE]
Analyzes strace output for IO functions. It creates statistics
on IO functions and performance of the read and write functions.
The strace file should have been run with 'strace -tt [PROGRAM]

-d Debug - echo the input lines to stdout and provide debugging information
-debug same as -d
--d same as -d
--debug same as -d
-h Produces help output (this message)
-help same as -h
--h same as -h
--help same as -h
-f [FILE] input a list of file sizes for examining IO functions
The format of the file is:
1024
8192
...
32768
1048576
-file same as -f
--f same as -f
--file same as -f
-dat Produce .dat files for plotting
--dat same as -dat
-s Create simulator code - file is simulator.c
-sim same as -s
--s same as -s
--sim same as -s
-short Short version of output
--short same as -short


The normal options that I use are "-short -dat". It produces much less output than usual and also produces data files fit for plotting using something like Grace.

Example output:

The output from the strace analyzer can either be very long or relatively short. It also produces some comma delimited files (csv) as well as the data files that can be used for plotting.

By default you will get two files: strace.log and whatever file you pipe the output to (stdout). So for example,

strace -short -dat < file.strace > strace.out

will produce strace.log and strace.out files. Here is a quick example of the strace.out file:


Analysis Output
===============

Number of Lines in strace file: 7072

----------------
-- Time Stats --
----------------
Elapsed Time for run: 0.526419 (secs)
Total IO Time: 0.121526 (secs)
Total IO Time Counter: 7025
Percentage of Total Time = 23.085406%

----------------------
-- IO Command Count --
----------------------
Command Count
==============================
stat64 1
open 6
close 7
access 6
lseek 4000
read 4
write 2998

----------------------
-- Write Statistics --
----------------------

-- File sizes for write() function --

IO Size Range Number of Functions
=======================================================
( 1) 0KB < < 1KB 1998
( 2) 1KB < < 8KB 0
( 3) 8KB < < 32KB 1000
( 4) 32KB < < 128KB 0
( 5) 128KB < < 256KB 0
( 6) 256KB < < 512KB 0
( 7) 512KB < < 1000KB 0
( 8) 1000KB < < 10MB 0
( 9) 10MB < < 100MB 0
( 10) 100MB < < 1GB 0
( 11) 1GB < < 10GB 0
( 12) 10GB < < 100GB 0
( 13) 100GB < < 1TB 0
( 14) 1TB < < 10TB 0


-- WRITE SUMMARY --
Total number of Bytes written = 8,011,996 (8.011996 MB)
Number of Write function calls = 2,998

Average (mean) Bytes per call = 2,672.4469646431 (bytes) (0.0026724469646431 MB)
Standard Deviation: 3,771.86653967916 (bytes) (0.00377186653967916 MB)
Mean Absolute Deviation: 3,922.7267533689 (bytes) (0.0039227267533689 MB)
Median Bytes per call = 4 (bytes) (4e-06 MB)
Median Absolute Deviation: 2,668.4469646431 (bytes) (0.0026684469646431 MB)

Time for slowest write function (secs) = 0.000439
Line location in file: 4777

---------------------
-- Read Statistics --
---------------------

-- File sizes for read function() --

IO Size Range Number of Functions
=======================================================
( 1) 0KB < < 1KB 2002
( 2) 1KB < < 8KB 0
( 3) 8KB < < 32KB 1000
( 4) 32KB < < 128KB 0
( 5) 128KB < < 256KB 0
( 6) 256KB < < 512KB 0
( 7) 512KB < < 1000KB 0
( 8) 1000KB < < 10MB 0
( 9) 10MB < < 100MB 0
( 10) 100MB < < 1GB 0
( 11) 1GB < < 10GB 0
( 12) 10GB < < 100GB 0
( 13) 100GB < < 1TB 0
( 14) 1TB < < 10TB 0


-- READ SUMMARY --
Total number of Bytes read = 2,048 (0.002048 MB)
Number of Read function calls = 4

Average (mean) Bytes per call = 512 (bytes) (0.000512 MB)
Standard Deviation: 0 (bytes) (0 MB)
Mean Absolute Deviation: 512 (bytes) (0.000512 MB)
Median Bytes per call = 512 (bytes) (0.000512 MB)
Median Absolute Deviation: 0 (bytes) (0 MB)

Time for slowest read function (secs) = 0.000439
Line location in file: 4777


----------------------
-- Close Statistics --
----------------------

-- CLOSE SUMMARY --
Total number of close function calls = 7
Average time for close function calls (secs) = 0.000010
Maximum Time for close function (secs) = 0.000015
Line location in file: 7069


---------------------
-- Open Statistics --
---------------------


-- OPEN SUMMARY --
Total number of open function calls = 6
Average time for open function calls (secs) = 0.000000
Maximum Time for open function (secs) = 0.000042
Line location in file: 66


------------------------------------
-- lseek unit activity Statistics --
------------------------------------

unit Number of lseeks
========================
3 4000

---------------------
-- IOPS Statistics --
---------------------


Maximum Write IOPS = 2998 occured at 1 seconds
Write IOPS = 2998


Maximum Read IOPS = 4 occured at 1 seconds
Read IOPS = 4


Maximum Total IOPS = 7021 occured at 1 seconds
Total IOPS = 3512

*****************
Final IOPS report
Write IOPS = 2998
Read IOPS = 4
Total IOPS = 3512
*****************




-- File Statistics (per file basis) --
Filename Read Bytes Bytes/sec Write Bytes Bytes/sec
=========================================================================================================================================================================
junk.out 2,048 0 8,011,996 0
DONE


Here are example of what you could expect to see if you plot the data files. The first plot is of Read IOPS vs. Time for the simple example (really simple). It is the IOPS for all files although the analyzer will produce data files for each file opened.



Below is a plot of Total IOPS vs. Time for the simple example. It is the Total IOPS for all the files although the analyzer will produce data files for each file opened.



Below is a plot of Write IOPS vs. Time for the simple example. It is the total Write IOPS for all of the files, although the analyzer will produce data files for each file opened.
Below is a plot of Read syscall size vs. time for the simple example. It plots the size of read syscalls as a function of time. As with many other cases, the analyzer will produce data files for each file opened.
GG