Added builtin performance metrics. Add REPORT=true to one of your disco dance runs to print the report at the end, or use 'disco report' to produce a report on the last disco dance; reports are cleared at the beginning of every disco dance.

_internal diff is for the time taken to produce the filesystem diff
_internal fetch_params is for how long it took to fetch all the client parameters

Currently these performance numbers only account for about 50-70% of disco's activity, not sure how to report on the rest yet.

Example output:

report: _internal: diff
report:    time_real 1.15 : time_user 0.21 : time_sys 0.92
report:    mem_avg 0 : mem_max 4816 : mem_faults_major 0 : mem_faults_minor 25400
report:    io_fsin 0 : io_fsout 16 : io_sockin 0 : io_sockout 0 : io_signals 0
report:    exit: 0
report: _internal: fetch_params
report:    time_real 1.14 : time_user 0.03 : time_sys 0.07
report:    mem_avg 0 : mem_max 11152 : mem_faults_major 0 : mem_faults_minor 1674
report:    io_fsin 0 : io_fsout 0 : io_sockin 0 : io_sockout 0 : io_signals 0
report:    exit: 0
report: othermodule-3.2: fetch
report:    time_real 2.27 : time_user 0.06 : time_sys 0.13
report:    mem_avg 0 : mem_max 11136 : mem_faults_major 0 : mem_faults_minor 2842
report:    io_fsin 0 : io_fsout 24 : io_sockin 0 : io_sockout 0 : io_signals 0
report:    exit: 0
report: othermodule-3.2: template
report:    etc/othermodule/stuff.cfg :
report:        time_real 0.53 : time_user 0.03 : time_sys 0.35
report:        mem_avg 0 : mem_max 4656 : mem_faults_major 119 : mem_faults_minor 5086
report:        io_fsin 25408 : io_fsout 16 : io_sockin 0 : io_sockout 0 : io_signals 0
report:        exit: 0
report: testmodule-1.0: exec
report:    00-hello.sh :
report:        time_real 0.29 : time_user 0.03 : time_sys 0.20
report:        mem_avg 0 : mem_max 4592 : mem_faults_major 54 : mem_faults_minor 3871
report:        io_fsin 10992 : io_fsout 8 : io_sockin 0 : io_sockout 0 : io_signals 0
report:        exit: 0
report:    10-service_stop.sh :
report:        time_real 0.46 : time_user 0.03 : time_sys 0.32
report:        mem_avg 0 : mem_max 4592 : mem_faults_major 110 : mem_faults_minor 4564
report:        io_fsin 22328 : io_fsout 8 : io_sockin 0 : io_sockout 0 : io_signals 0
report:        exit: 0
report: testmodule-1.0: fetch
report:    time_real 2.24 : time_user 0.05 : time_sys 0.13
report:    mem_avg 0 : mem_max 11152 : mem_faults_major 0 : mem_faults_minor 2894
report:    io_fsin 0 : io_fsout 24 : io_sockin 0 : io_sockout 0 : io_signals 0
report:    exit: 0

client/bin/disco

@@ -1,5 +1,6 @@
 #!/bin/bash
 
+TIME="time_real %e : time_user %U : time_sys %S\nmem_avg %K : mem_max %M : mem_faults_major %F : mem_faults_minor %R\nio_fsin %I : io_fsout %O : io_sockin %r : io_sockout %s : io_signals %k\nexit: %x"
 DISCOCFG=/etc/disco
 if [ "$NOOP" != "" ]; then
     DISCOROOT=/var/disco/testfs/noop
@@ -15,8 +16,19 @@ function colorize() {
         sed s/"^error: \(.*\)"/"${COLOR_RED}error: \1${COLOR_NORMAL}"/g
 }
 
-function dance() {
+function report() {
+    for module in $(ls /var/disco/reports/)
+    do
+	BASE="report: $module:"
+	for file in $(ls /var/disco/reports/${module})
+	do
+	    echo $BASE $file
+	    cat /var/disco/reports/${module}/$file | sed s/"^"/"report:    "/g
+	done
+    done
+}
 
+function dance() {
     mount | grep $DISCOROOT >/dev/null 2>&1
     if [ $? -ne 0 ]; then
 	echo "error: disco filesystem does not appear to be mounted, please exec disco-fs-init, disco-fs-mount, and try again."
@@ -40,7 +52,7 @@ function dance() {
     do
 	echo "info: Processing ${module}"
 	NOOP="true" disco-ball template $module
-	disco-fs-diff
+	/usr/bin/time -f "$TIME" -o /var/disco/reports/_internal/diff disco-fs-diff
 	if [ "$NOOP" == "" ]; then
 	    rsync -aWH /var/disco/testfs/noop/* /
 	fi
@@ -51,6 +63,11 @@ function dance() {
 	    echo "error: Failed to apply $module."
 	fi
     done
+
+    if [ "$REPORT" != "" ]; then
+	report
+    fi
+
 }
 
 $1 "$2" "$3" "$4" "$5" "$6" "$7" "$8" "$9"

client/bin/disco-fs-diff

@@ -29,7 +29,8 @@ rsync --checksum --times --perms --owner --group -ani ./scratchfs/ ./rootfs/ |\
 while read LINE
 do
     FNAME=$(echo $LINE | cut -d : -f 4 | sed s/"^ *"/""/ | sed s/" *$"/""/)
-    NEWSTR=""
+
+    # ----- File modification/creation data
     MODSTR=""
     MD5_NEW=$(md5sum ${DISCOROOT}/scratchfs/${FNAME} 2>/dev/null| cut -d " " -f 1)
     MD5_OLD=$(md5sum /${FNAME} 2>/dev/null| cut -d " " -f 1)
@@ -61,13 +62,16 @@ do
     if [ "$DEVICE_NEW" != "$DEVICE_OLD" ]; then
 	MODSTR="$MODSTR device=[$DEVICE_OLD => $DEVICE_NEW]"
     fi
-
     if [ ! -d /${FNAME} ] && [ ! -d ${DISCOROOT}/scratchfs/${FNAME} ]; then 
 	diff -N /${FNAME} ${DISCOROOT}/scratchfs/${FNAME} 2>/dev/null > /tmp/$$.diff
     fi
+
+    # ------
+
     echo $LINE |\
-        sed -e s/"Created$"/"Created : type=[${TYPE_NEW}] device=[${DEVICE_NEW}] mode=[${RAWMODE_NEW}] selinux=[${SELINUX_NEW}] md5=[${MD5_NEW}] perms=[${PERMS_NEW}]OB"/ |\
+        sed -e s/"Created$"/"Created : type=[${TYPE_NEW}] device=[${DEVICE_NEW}] mode=[${RAWMODE_NEW}] selinux=[${SELINUX_NEW}] md5=[${MD5_NEW}] perms=[${PERMS_NEW}]"/ |\
-        sed -e s/"Modified$"/"Modified : ${MODSTR}"/
+        sed -e s/"Modified$"/"Modified :${MODSTR}"/ |\
+        sed s/"^\([a-z]*\): File: \([a-z]*\): "/"\1: File: \2: \/"/
     if [ -f /tmp/$$.diff ]; then
 	cat /tmp/$$.diff
     fi

universe/bin/disco-ball

@@ -1,10 +1,12 @@
 #!/bin/bash
 
+TIME="time_real %e : time_user %U : time_sys %S\nmem_avg %K : mem_max %M : mem_faults_major %F : mem_faults_minor %R\nio_fsin %I : io_fsout %O : io_sockin %r : io_sockout %s : io_signals %k\nexit: %x"
 DISCOROOT=/var/disco
 RSYNC=$(disco-param get disco/client/cmds/rsync || exit 1)
 SERVERURI=$(disco-param get disco/server/uri || exit 1)
 STORAGE=$(disco-param get disco/client/storage 2>/dev/null || echo "/var/disco/localstore")
 mkdir -p ${STORAGE}
+mkdir -p ${DISCOROOT}/reports/_internal
 
 function init() {
     if [ "$1" == "" ]; then
@@ -23,7 +25,7 @@ function fetch_params() {
     # the command line; so we wrap it in a little bash script, and everyone's happy.
     echo ${RSYNC} --delete ${SERVERURI}::parameters/$(hostname)/* ${DISCOROOT}/parameters/$(hostname)/ > /tmp/$$.sh
     echo 'exit $?' >> /tmp/$$.sh
-    /bin/bash /tmp/$$.sh
+    /usr/bin/time -f "$TIME" -o ${DISCOROOT}/reports/_internal/fetch_params /bin/bash /tmp/$$.sh
     RETVAL=$?
     rm -f /tmp/$$.sh
     exit $RETVAL
@@ -35,12 +37,14 @@ function fetch() {
 	exit 1
     fi
     rm -rf ${STORAGE}/${1}
+    mkdir -p ${DISCOROOT}/reports/$1
+    rm -f ${DISCOROOT}/reports/${1}/fetch
     # Sometimes there's some shell escaping voodoo and rsync doesn't like the command args some people will pass it straight on
     # the command line; so we wrap it in a little bash script, and everyone's happy.
     echo ${RSYNC} ${SERVERURI}::${1}/files/* / > /tmp/$$.sh
     echo ${RSYNC} --delete ${SERVERURI}::${1}/requires ${SERVERURI}::${1}/scripts ${SERVERURI}::${1}/parameters ${SERVERURI}::${1}/templates ${STORAGE}/${1} >> /tmp/$$.sh
     echo 'exit $?' >> /tmp/$$.sh
-    /bin/bash /tmp/$$.sh 2>/tmp/$$.errors | sed s/"^"/"info: ${1}: "/g
+    /usr/bin/time -f "$TIME" -o ${DISCOROOT}/reports/${1}/fetch /bin/bash /tmp/$$.sh 2>/tmp/$$.errors | sed s/"^"/"info: ${1}: "/g
     cat /tmp/$$.errors | grep -v "some files/attrs were not transferred" | sed s/"^"/"error: ${1}: "/g
     RETVAL=$?
     rm -f /tmp/$$.sh
@@ -58,11 +62,18 @@ function requires()
 
 function exec() {
     RETVAL=0
+    mkdir -p ${DISCOROOT}/reports/$1
+    rm -f ${DISCOROOT}/reports/${1}/exec
     for file in $(find ${STORAGE}/${1}/scripts/ -type f | sort -u)
     do
-	NOOP="$NOOP" disco-sh-exec $file /tmp/${1}-$(basename $file)
+	NOOP="$NOOP" /usr/bin/time -f "$TIME" -o /tmp/$$.exec.time disco-sh-exec $file /tmp/${1}-$(basename $file)
 	RETVAL=$(expr $RETVAL + $?)
+	SNAME=$(basename $file)
+	echo "$SNAME : " >> ${DISCOROOT}/reports/${1}/exec
+	cat /tmp/$$.exec.time | sed s/"^"/"    "/g >> ${DISCOROOT}/reports/${1}/exec
     done
+    rm -f /tmp/$$.exec.time
+    exit $RETVAL
 }
 
 function template() {
@@ -70,23 +81,29 @@ function template() {
 	echo "Must pass a module name to template"
 	exit 1
     fi
+    mkdir -p ${DISCOROOT}/reports/$1
+    rm -f ${DISCOROOT}/reports/${1}/template
     DESTROOT=""
     if [ "$NOOP" != "" ]; then
 	DESTROOT=/var/disco/testfs/noop/scratchfs
     fi
     cd ${STORAGE}/${1}/templates
+    RETVAL=0
     for file in $(find . -type f | sed s/"^\.\/"//g)
     do
-	NOOP=true disco-sh-exec $(pwd)/$file /$file >/tmp/$$.tmpl
+	NOOP=true /usr/bin/time -f "$TIME" -o /tmp/$$.template.time disco-sh-exec $(pwd)/$file /$file >/tmp/$$.tmpl
+	echo "$file : " >> ${DISCOROOT}/reports/${1}/template
+	cat /tmp/$$.template.time | sed s/"^"/"    "/g >> ${DISCOROOT}/reports/${1}/template
 	if [ $? -eq 0 ]; then
 	    mkdir -p $(dirname ${DESTROOT}/$file)
 	    mv /tmp/$$.tmpl ${DESTROOT}/$file
 	else
 	    echo "error: template ${1}/templates/$file failed, not replacing /$file"
-	    exit 1
+	    RETVAL=1
 	fi
     done
-    exit 0
+    rm -f /tmp/$$.template.time
+    exit $RETVAL
 }
 
 $1 $2