[sclug] Performance tuning

[David Kerrawn sclug]

> -----Original Message-----
> From: sclug-bounces at sclug.org.uk [mailto:sclug-bounces at sclug.org.uk]On
> Behalf Of Derek M Jones
> Sent: 16 November 2005 23:01
> To: sclug
> Subject: [sclug] Performance tuning
> 
> 
> All,
> 
> I am running some scripts that take a cpu day or
> three to complete.  The scripts call a number of
> programs.  None take very long to execute (the scripts
> loop over a couple of million files performing various
> operations).
> 
> Tuning is a problem because I cannot find a way of summing
> the time spent executing various scripts or programs.
> 
> What I really need is a bash option that will sum the total
> time taken by all the scripts and programs that are executed
> by it and its child processes (and print these value out when
> the top level shell terminates).
> 
> Short of editing the source of bash I cannot think of
> any way of obtaining the information I am after.  Does anybody
> have any ideas?  An accuracy of +/-10% would be good enough.
> 
> -- 
> Derek M. Jones 

Derek,

I've knocked something up using LD_PRELOAD to overload the standard execve and waitpid functions. It outputs a timestamp, pid and filename and can send this to a file specified by an environment variable (PROFILE) or stdout if PROFILE is not set. You won't have to change any script code. Once you have the raw times you should be able to knock up some code to get the times you require.

eg: (stdout sent to /dev/null for clarity)
export PROFILE=./output; rm $PROFILE; LD_PRELOAD=./libmylibc.so.1.0.1 ./myscript > /dev/null
cat $PROFILE;
1132199819 2479 Starting: "./myscript2", "./myscript2"
1132199819 2480 Starting: "./myscript3", "./myscript3"
1132199819 2481 Starting: "/bin/ls", "ls"
1132199819 2481 Exited
1132199819 2480 Starting: "/home/davek/src/LD_PRELOAD/mytest", "./mytest"
1132199819 2480 Exited
1132199819 2482 Starting: "/bin/sleep", "sleep", "1"
1132199820 2482 Exited
1132199820 2483 Starting: "/bin/ls", "ls"
1132199820 2483 Exited
1132199820 2479 Exited

Column 1 is seconds since 01 Jan 1970, Column 2 is the Process ID (PID), column 3 whether the process is starting or has exited, followed by the name of the process and the contents of argv. Unfortunately the Starting and Exited lines are output by child and parent processes respectively and it's too late at night for me to work out how to get the start and end times in the same space so I can subtract them.

Where there are multiple lines with the same PID (2480) and both "Starting" it's because I did an "exec ./mytest" and exec re-uses the PID, and so there are 2 starts and 1 exit. 

Scripts: (/bin/sh is sym-linked to /bin/bash on our system)
==> myscript <==
#!/bin/sh
./myscript2

==> myscript2 <==
#!/bin/sh
echo $$
./myscript3
sleep 1
ls

==> myscript3 <==
#!/bin/sh
echo $$
ls
exec ./mytest

Code posted on request. (It's a bit less than 3KB)

Credits:
Idea: LD_PRELOAD: A little gem put in my head by Diccon Hood at a Sclug meet.
Sample Code: http://uberhip.com/godber/interception/html/slide_4.html

Regards
Davek.