[Pm-utils] [PATCH] Profile time spent in hooks when PM_PROFILE is true

[Dan Nicholson]

Adds a couple functions for calculating time between two points. These
are used to profile the time spent on each hook when the PM_PROFILE
variable is "true".

Signed-off-by: Dan Nicholson <dbn.lists at gmail.com>
---
 Feel free to adapt this to your preference.

 pm/pm-functions.in |   25 ++++++++++++++++++++++++-
 src/pm-action.in   |   12 ++++++++++++
 2 files changed, 36 insertions(+), 1 deletions(-)

diff --git a/pm/pm-functions.in b/pm/pm-functions.in
index f5cc400..142f8b3 100644
--- a/pm/pm-functions.in
+++ b/pm/pm-functions.in
@@ -44,6 +44,7 @@ DROP_PARAMETERS=""
 PARAMETERS="${STORAGEDIR}/parameters"
 INHIBIT="${STORAGEDIR}/inhibit"
 PM_CMDLINE="$*"
+PM_PROFILE=""
 BEFORE_HOOKS=""
 MODULE_HELP=""
 SUSPEND_MODULE=""
@@ -95,6 +96,19 @@ log()
 	printf "$fmt" "$*"
 }
 
+# Get the current time for profiling.
+get_current_time()
+{
+	date '+%s.%N'
+}
+
+# Get time spent between two points.
+get_time_spent()
+{
+	[ -z "$1" ] || [ -z "$2" ] && return 1
+	perl -e "printf \"%.3f\n\", $2 - $1"
+}
+
 add_before_hooks() {
 	[ -z "$BEFORE_HOOKS" ] && BEFORE_HOOKS="$*" || \
 		BEFORE_HOOKS="$BEFORE_HOOKS $*"
@@ -184,6 +198,8 @@ run_hooks() {
 	local sort="sort"
 	local base
 	local hook
+	local status
+	local t1 t2 time
 	local oifs="${IFS}"
 	# the next two lines are not a typo or a formatting error!
 	local nifs="
@@ -208,10 +224,17 @@ run_hooks() {
 			hook="$phooks/$base"
 		fi
 		log -n "${hook} $2: "
+		[ "$PM_PROFILE" = true ] && t1=$(get_current_time)
 		hook_ok "$hook" && "${hook}" $2 
+		status=$?
+		[ "$PM_PROFILE" = true ] && {
+			t2=$(get_current_time)
+			time=$(get_time_spent "$t1" "$t2")
+		}
 		# if the hook exited with an unknown exit code inhibit,
 		# otherwise record this as the last hook that ran.
-		hook_exit_status $? && LAST_HOOK="$base" || inhibit
+		hook_exit_status $status && LAST_HOOK="$base" || inhibit
+		[ "$PM_PROFILE" = true ] && log "$hook $2: $time sec"
 		IFS="${nifs}"
 	done
 	IFS="${oifs}"
diff --git a/src/pm-action.in b/src/pm-action.in
index 88bdb4e..dd71a67 100755
--- a/src/pm-action.in
+++ b/src/pm-action.in
@@ -93,7 +93,13 @@ load_hook_parameters
 
 # run the sleep hooks
 log "$(date): Running hooks for $ACTION."
+[ "$PM_PROFILE" = true ] && t1=$(get_current_time)
 if run_hooks sleep "$ACTION $METHOD"; then
+	[ "$PM_PROFILE" = true ] && {
+		t2=$(get_current_time)
+		time=$(get_time_spent "$t1" "$t2")
+		log "Time for $ACTION hooks: $time sec"
+	}
         # Sleep only if we know how and if a hook did not inhibit us.
 	log "$(date): performing $METHOD"
 	sync
@@ -103,8 +109,14 @@ else
 	log "$(date): Inhibit found, will not perform $METHOD"
 fi
 log "$(date): Running hooks for $REVERSE"
+[ "$PM_PROFILE" = true ] && t1=$(get_current_time)
 # run the sleep hooks in reverse with the wakeup action
 if run_hooks sleep "$REVERSE $METHOD" reverse; then
+	[ "$PM_PROFILE" = true ] && {
+		t2=$(get_current_time)
+		time=$(get_time_spent "$t1" "$t2")
+		log "Time for $REVERSE hooks: $time sec"
+	}
         log "$(date): Finished."
 else 
         exit 1
-- 
1.5.6.5