[Pm-utils] Cutting down on unnecessary hooks

[Victor Lowther]

On Wed, 2008-11-26 at 17:45 -0600, Victor Lowther wrote:
> On Wed, 2008-11-26 at 11:31 -0800, Dan Nicholson wrote:
> > Recently I was debugging some suspend issue and was using bare `echo
> > mem > /sys/power/state'. Turns out, it was much faster than using
> > pm-suspend. That got me thinking that the pm-utils hooks must be
> > taking a long time. Looking at the current default hooks, it seems
> > that some are useless or less than optimal.
> 
> I use this tiny little patch for profiling:
> 
> 
> diff --git a/pm/pm-functions.in b/pm/pm-functions.in
> index f5cc400..80797ee 100644
> --- a/pm/pm-functions.in
> +++ b/pm/pm-functions.in
> @@ -92,7 +92,7 @@ log()
>         [ $LOGGING ] || return 0;
>         local fmt='%s\n'
>         [ "$1" = "-n" ] && { fmt='%s'; shift; }
> -       printf "$fmt" "$*"
> +       printf "%s: $fmt" "$(date "+%F %T.%N")" "$*"
>  }
>  
>  add_before_hooks() {
> 
> It is useful in identifying which hook takes so long.

And some general stats (S3 suspend/resume, Dell Latitude D820,nvidia
binary drivers, 2.0 GHz core duo, fedora core 10):

suspend hook:		  start        end          time in hook 
00auto-quirk              40.339370514 40.350010426 0.011
00logging 	          40.352155674 40.364101480 0.012
00powersave		  40.366294498 40.434675127 0.068
01grub 		    	  40.437567677 40.444537635 0.007
49bluetooth 	 	  40.447382833 40.457235633 0.010
50ntpd 	 	    	  40.460066303 40.592670183 0.132
55NetworkManager 	  40.594856357 40.611942627 0.017
55battery 		  40.614916542 40.624929418 0.010
65alsa 		    	  40.627695276 40.648029867 0.021
75modules 		  40.650934569 40.661996044 0.011
90chvt 		    	  40.665565985 40.824782147 0.159
90clock 		  40.826357838 42.502749116 1.676
94cpufreq 		  42.504224306 42.512767929 0.008
95led 		    	  42.514227823 42.517398761 0.003
95packagekit 		  42.518773378 42.521972043 0.003
98smart-kernel-video 	  42.523341772 42.532503352 0.009
99hd-apm-restore.hook     42.536146556 42.573399170 0.037
99video		    	  42.574847330 42.582434337 0.008

resume hook:   		  start        end          time in hook
99video		    	  55.499660285 55.515182039 0.016
99hd-apm-restore.hook	  55.516651501 55.559604217 0.043
98smart-kernel-video	  55.561215736 55.567155674 0.006
95packagekit		  55.568673467 55.669119939 0.101
95led			  55.670902780 55.692397157 0.022
94cpufreq		  55.693867597 55.701003289 0.008
90clock		    	  55.702400535 56.002209641 0.300
90chvt		    	  56.006952498 56.171272247 0.165
75modules		  56.177872326 57.533091472 1.356
65alsa		    	  57.534858109 57.579706809 0.045
55battery		  57.581576462 57.623622218 0.042
55NetworkManager	  57.625224658 57.639614144 0.014
50ntpd		    	  57.641936508 57.731196910 0.090
49bluetooth		  57.759816363 57.783757144 0.024
01grub		    	  57.785695591 57.798232185 0.013
00powersave		  57.805749350 57.909236227 0.104
00logging		  57.917043583 57.923013203 0.006
00auto-quirk		  57.924773974 57.932675826 0.008


It takes 0.002 - 0.003 seconds to move from hook to hook.
Most hooks have approx. 0.010 - 0.015 seconds runtime before we run
94cpufreq, and 0.003 - 0.007 seconds after it.
The outliers on the suspend side are:

50ntpd, which takes 0.132 seconds to run,
90chvt, which takes 0.159 seconds to run, and
90clock, which takes 1.676 seconds to run.

On the resume side, the major outliers are:
95packagekit, which takes 0.101 seconds to run,
90clock, which takes 0.300 seconds to run,
90chvt, which takes 0.165 seconds to run,
75modules, which takes 1.356 seconds to run,
and 00powersave, which takes 0.104 seconds to run.


Looks like we could get a big speed boost in the overall suspend/resume
process by ditching 90clock (or making it not run by default),
eliminating the chvt on gpus that do not require it, and figuring out
why 75modules takes so long to resume even when it has nothing to do.

Fedora is also violating the hook ordering conventions with
95packagekit.  Packagekit should be in the 00 - 49 range, and it should
probably listen for NetworkManager to rejoin a network after a sucessful
resume rather than use a hook -- right now, it is doing the same sort of
stuff that the 50ntpd hook does. 

Also, as another general guideline, I consider everything before we chvt
back to the original VT to be a fast path -- minimizing the amount of
time away from the VT the user was originally helps reduce the percieved
amount of time it takes to suspend/resume the  box, so if you have
something to do that takes alot of time, try to do it on the resume side
after the chvt.

-- 
Victor Lowther
RHCE# 805008539634727
LPIC-2# LPI000140019