# HG changeset patch
# User David Scott <dave.scott@xxxxxxxxxxxxx>
# Date 1259942647 0
# Node ID 4da34ecf1254e82d1e783b81395aaf4e4b2a69e6
# Parent  1ee7e0184efe0e259d6abb600b0162a0762c321e
CA-35165: Suppress the periodic logging in the host ballooning daemon. It only says stuff when there is interesting stuff to say. Also improve some of the log strings to make them easier to interpret.

Signed-off-by: David Scott <dave.scott@xxxxxxxxxxxxx>

diff -r 1ee7e0184efe -r 4da34ecf1254 ocaml/xenops/squeeze.ml
--- a/ocaml/xenops/squeeze.ml	Fri Dec 04 16:04:07 2009 +0000
+++ b/ocaml/xenops/squeeze.ml	Fri Dec 04 16:04:07 2009 +0000
@@ -265,7 +265,7 @@
 let range domain = max 0L (domain.dynamic_max_kib -* domain.dynamic_min_kib)
   
 module type POLICY = sig
-  val compute_target_adjustments: ?fistpoints:(fistpoint list) -> host -> int64 -> (domain * int64) list
+  val compute_target_adjustments: ?fistpoints:(fistpoint list) -> bool -> host -> int64 -> (domain * int64) list
 end
 
 (**
@@ -288,22 +288,25 @@
 		set of balloon-target-set actions to divide it up amongst the given VMs
 		so that (target - min) / (max - min) is the same for all VMs.
 	*)
-	let allocate_memory_in_proportion surplus_memory_kib domains =
+	let allocate_memory_in_proportion verbose surplus_memory_kib domains =
 	  (* We allocate surplus memory in proportion to each domain's dynamic_range: *)
 	  let allocate gamma domain = Int64.of_float (gamma *. (Int64.to_float (range domain))) in
 	  (* gamma = the proportion where 0 <= gamma <= 1 *)
-	  let gamma = constrain 0. 1. (Int64.to_float surplus_memory_kib /. (Int64.to_float (sum (List.map range domains)))) in
-	  debug "total surplus memory = %Ld KiB; gamma = %.2f" surplus_memory_kib gamma;
+	  let total_range = Int64.to_float (sum (List.map range domains)) in
+	  let gamma' = Int64.to_float surplus_memory_kib /. total_range in
+	  let gamma = constrain 0. 1. gamma' in
+	  if verbose
+	  then debug "Total additional memory over dynamic_min = %Ld KiB; will set gamma = %.2f (leaving unallocated %Ld KiB)" surplus_memory_kib gamma (Int64.of_float (total_range *. (gamma' -. gamma)));
 
 	  List.map (fun domain -> domain, domain.dynamic_min_kib +* (allocate gamma domain)) domains
 
 
 	(* Given a set of domains and a host free memory target, return balloon target adjustments *)
-	let compute_target_adjustments ?fistpoints (host: host) host_target_kib =
+	let compute_target_adjustments ?fistpoints verbose (host: host) host_target_kib =
 	  (* If all domains balloon down to dynamic_min: *)
 	  let maximum_free_mem_kib = host.free_mem_kib +* (sum (List.map (min_freeable ?fistpoints) host.domains)) in
 	  let surplus_memory_kib = max 0L (maximum_free_mem_kib -* host_target_kib) in
-	  allocate_memory_in_proportion surplus_memory_kib host.domains
+	  allocate_memory_in_proportion verbose surplus_memory_kib host.domains
 end
 
 module Policy = (Proportional: POLICY)
@@ -321,7 +324,7 @@
 		Takes a view of the host state and amount of free memory desired and
 		returns a list of ballooning actions which may help achieve the goal.
 	*)
-	let one_iteration ?(fistpoints=[]) success_condition (x: t) (host: host) host_target_kib (now: float) =
+	let one_iteration ?(fistpoints=[]) verbose success_condition (x: t) (host: host) host_target_kib (now: float) =
 		(* 1. Compute which domains are still considered active *)
 		Stuckness_monitor.update x.stuckness host now;
 		let active_domains = 
@@ -346,10 +349,11 @@
 		let x = { x with non_active_domids = non_active_domids } in
 
 		(* 2. Compute how we would adjust the domain memory targets *)
-		let targets = Policy.compute_target_adjustments ~fistpoints { host with domains = active_domains } host_target_kib in
+		let targets = Policy.compute_target_adjustments ~fistpoints verbose { host with domains = active_domains } host_target_kib in
 
 		let maximum_possible_free_memory_kib = host.free_mem_kib +* (sum (List.map (min_freeable ~fistpoints) active_domains)) in
-		debug "maximum_possible_free_memory_kib = %Ld" maximum_possible_free_memory_kib;
+		if verbose
+		then debug "Maximum possible free memory if all active domains balloon down to dynamic_min = %Ld" maximum_possible_free_memory_kib;
 		(* Xen heap workaround: *)
 		let is_freeing_memory (domain, new_target_kib) = not (has_hit_target domain.inaccuracy_kib domain.memory_actual_kib new_target_kib) && new_target_kib < domain.memory_actual_kib in
 		let freeing, allocating = List.partition is_freeing_memory targets in
@@ -378,7 +382,8 @@
 		let target_too_big = maximum_possible_free_memory_kib < host_target_kib in
 
 		let no_target_changes = List.filter (fun (domain, target) -> domain.target_kib <> target) targets = [] in
-		debug "free_mem = %Ld KiB; target = %Ld KiB; %s; all targets%s reached%s; %s"
+		if verbose
+		then debug "current host free mem = %Ld KiB (aiming for %Ld KiB);%s; all domain targets%s reached%s; %s"
 		  host.free_mem_kib host_target_kib 
 		  (if success then " OK"
 		   else if target_too_big then " cannot free enough"
@@ -457,14 +462,16 @@
 end
 
 type io = {
-  make_host: unit -> string * host;
-  domain_setmaxmem: int -> int64 -> unit;
-  execute_action: action -> unit;
-  wait: float -> unit;
-  gettimeofday: unit -> float;
+	verbose: bool;
 
-  target_host_free_mem_kib: int64;
-  free_memory_tolerance_kib: int64;
+	make_host: unit -> string * host;
+	domain_setmaxmem: int -> int64 -> unit;
+	execute_action: action -> unit;
+	wait: float -> unit;
+	gettimeofday: unit -> float;
+	
+	target_host_free_mem_kib: int64;
+	free_memory_tolerance_kib: int64;
 }
 
 exception Cannot_free_this_much_memory of int64 * int64 (** even if we balloon everyone down we can't free this much *)
@@ -472,7 +479,8 @@
 
 let change_host_free_memory ?fistpoints io required_mem_kib success_condition = 
   (* XXX: debugging *)
-  debug "change_host_free_memory required_mem = %Ld KiB" required_mem_kib;
+  if io.verbose 
+  then debug "change_host_free_memory required_mem = %Ld KiB" required_mem_kib;
 
   let acc = ref (Squeezer.make ()) in
   let finished = ref false in
@@ -480,7 +488,7 @@
     let t = io.gettimeofday () in
     let host_debug_string, host = io.make_host () in
     let acc', declared_active_domids, declared_inactive_domids, result =
-      Squeezer.one_iteration ?fistpoints success_condition !acc host required_mem_kib t in
+      Squeezer.one_iteration ?fistpoints io.verbose success_condition !acc host required_mem_kib t in
     acc := acc';
     
     (* Set the max_mem of a domain as follows:
@@ -539,24 +547,28 @@
     
     begin match result with
     | Success ->
-	debug "Success: Host free memory = %Ld KiB" required_mem_kib;
+		  if io.verbose
+		  then debug "Success: Host free memory = %Ld KiB" required_mem_kib;
 	finished := true
     | Failed [] ->
-	debug "Failed to free %Ld KiB of memory: operation impossible within current dynamic_min limits of balloonable domains" required_mem_kib;
-	raise (Cannot_free_this_much_memory (required_mem_kib, host.free_mem_kib));
+		  if io.verbose
+		  then debug "Failed to free %Ld KiB of memory: operation impossible within current dynamic_min limits of balloonable domains" required_mem_kib;
+		  raise (Cannot_free_this_much_memory (required_mem_kib, host.free_mem_kib));
     | Failed domids ->
-	let s = String.concat ", " (List.map string_of_int domids) in
-	debug "Failed to free %Ld KiB of memory: the following domains have failed to meet their targets: [ %s ]"
-	  required_mem_kib s;
+		  let s = String.concat ", " (List.map string_of_int domids) in
+		  if io.verbose 
+		  then debug "Failed to free %Ld KiB of memory: the following domains have failed to meet their targets: [ %s ]"
+			required_mem_kib s;
 	raise (Domains_refused_to_cooperate domids)
     | AdjustTargets actions ->
-	(* Set all the balloon targets *)
-	List.iter io.execute_action actions;
-	io.wait 1.
+		  (* Set all the balloon targets *)
+		  List.iter io.execute_action actions;
+		  io.wait 1.
     end
   done
 
-let free_memory fistpoints io required_mem_kib = change_host_free_memory ?fistpoints io (required_mem_kib +* io.target_host_free_mem_kib) (fun x -> x >= (required_mem_kib +* io.target_host_free_mem_kib))
+let free_memory fistpoints io required_mem_kib =
+  change_host_free_memory ?fistpoints io (required_mem_kib +* io.target_host_free_mem_kib) (fun x -> x >= (required_mem_kib +* io.target_host_free_mem_kib))
 
 let free_memory_range ?fistpoints io min_kib max_kib =
   (* First compute the 'ideal' amount of free memory based on the proportional allocation policy *)
@@ -570,7 +582,7 @@
 	       } in
   let host = snd(io.make_host ())in
   let host' = { host with domains = domain :: host.domains } in
-  let adjustments = Policy.compute_target_adjustments host' io.target_host_free_mem_kib in
+  let adjustments = Policy.compute_target_adjustments io.verbose host' io.target_host_free_mem_kib in
   let target = 
     if List.mem_assoc domain adjustments
     then List.assoc domain adjustments
@@ -598,7 +610,7 @@
   let domains = List.map (fun d -> d.domid, d) host.domains in
 
   let t = io.gettimeofday () in
-  let _, _, _, result = Squeezer.one_iteration ?fistpoints
+  let _, _, _, result = Squeezer.one_iteration ?fistpoints false
     (is_balanced io) (Squeezer.make ()) host 
     io.target_host_free_mem_kib (io.gettimeofday ()) in
   
diff -r 1ee7e0184efe -r 4da34ecf1254 ocaml/xenops/squeeze_test.ml
--- a/ocaml/xenops/squeeze_test.ml	Fri Dec 04 16:04:07 2009 +0000
+++ b/ocaml/xenops/squeeze_test.ml	Fri Dec 04 16:04:07 2009 +0000
@@ -398,6 +398,7 @@
     Gnuplot.write_row dat_oc (make_host ()) cols t in
   
   let io = {
+	  verbose = true;
     Squeeze.gettimeofday = gettimeofday;
     make_host = (fun () -> Printf.sprintf "F%Ld" !host_free_mem_kib, make_host ());
     domain_setmaxmem = setmaxmem;
diff -r 1ee7e0184efe -r 4da34ecf1254 ocaml/xenops/squeeze_xen.ml
--- a/ocaml/xenops/squeeze_xen.ml	Fri Dec 04 16:04:07 2009 +0000
+++ b/ocaml/xenops/squeeze_xen.ml	Fri Dec 04 16:04:07 2009 +0000
@@ -97,7 +97,6 @@
 	match x with
 	| Some y -> y
 	| None ->
-		  debug "xenstore-read %s%s returned ENOENT" per_domain.path key;
 		  raise Xb.Noent
 
   (** Read a particular domain's key from xenstore, for when we believe the cache is out of date *)
@@ -225,7 +224,7 @@
 		  
 
 (** Best-effort creation of a 'host' structure and a simple debug line showing its derivation *)
-let make_host ~xc ~xs =
+let make_host ~verbose ~xc ~xs =
 	(* Wait for any scrubbing so that we don't end up with no immediately usable pages --
 	   this might cause something else to fail (eg domain builder?) *)
 	while Memory.get_scrub_memory_kib ~xc <> 0L do Unix.select [] [] [] 0.25 done;
@@ -279,7 +278,7 @@
 					    with Xb.Noent ->
 					      let target_kib = Domain.get_target cnx di.Xc.domid in
 					      let offset_kib = memory_actual_kib -* target_kib in
-					      debug "domid %d just exposed feature-balloon; calibrating total_pages offset = %Ld KiB" di.Xc.domid offset_kib;
+					      debug "domid %d just exposed feature-balloon; calibrating memory-offset = %Ld KiB" di.Xc.domid offset_kib;
 					      Domain.set_memory_offset_noexn cnx di.Xc.domid offset_kib;
 					      offset_kib
 					  end in
@@ -341,7 +340,8 @@
 				    (* useful debug message is printed by the Domain.read* functions *)
 				    []
 				|  e ->
-					debug "Skipping domid %d: %s"
+					if verbose 
+					then debug "Skipping domid %d: %s"
 						di.Xc.domid (Printexc.to_string e);
 					[]
 			)
@@ -350,7 +350,8 @@
 
 	(* Sum up the 'reservations' which exist separately from domains *)
 	let non_domain_reservations = Squeezed_state.total_reservations xs Squeezed_rpc._service in
-	debug "Total non-domain reservations = %Ld" non_domain_reservations;
+	if verbose && non_domain_reservations <> 0L
+	then debug "Total non-domain reservations = %Ld" non_domain_reservations;
 	reserved_kib := Int64.add !reserved_kib non_domain_reservations;
 
 	let host = Squeeze.make_host ~domains ~free_mem_kib:(Int64.sub free_mem_kib !reserved_kib) in
@@ -389,9 +390,10 @@
 
 let free_memory_tolerance_kib = 512L (** No need to be too exact *)
 
-let io ~xc ~xs = {
+let io ~xc ~xs ~verbose = {
+	verbose = verbose;
   Squeeze.gettimeofday = Unix.gettimeofday;
-  make_host = (fun () -> make_host ~xc ~xs);
+  make_host = (fun () -> make_host ~verbose ~xc ~xs);
   domain_setmaxmem = (fun domid kib -> execute_action ~xc ~xs { Squeeze.action_domid = domid; new_target_kib = kib });
   wait = (fun delay -> ignore(Unix.select [] [] [] delay));
   execute_action = (fun action -> execute_action ~xc ~xs action);
@@ -400,22 +402,22 @@
 }
 
 let change_host_free_memory ~xc ~xs required_mem_kib success_condition = 
-  Squeeze.change_host_free_memory (io ~xc ~xs) required_mem_kib success_condition
+  Squeeze.change_host_free_memory (io ~verbose:true ~xc ~xs) required_mem_kib success_condition
 
 let free_memory ~xc ~xs required_mem_kib = 
-  let io = io ~xc ~xs in
+  let io = io ~verbose:true ~xc ~xs in
   Squeeze.change_host_free_memory io (required_mem_kib +* io.Squeeze.target_host_free_mem_kib) (fun x -> x >= (required_mem_kib +* io.Squeeze.target_host_free_mem_kib))
 
 let free_memory_range ~xc ~xs min_kib max_kib =
-  let io = io ~xc ~xs in
+  let io = io ~verbose:true ~xc ~xs in
   Squeeze.free_memory_range io min_kib max_kib
 
 let is_balanced x = Int64.sub x target_host_free_mem_kib < free_memory_tolerance_kib
 
 let balance_memory ~xc ~xs = 
-  Squeeze.balance_memory (io ~xc ~xs)
+  Squeeze.balance_memory (io ~verbose:true ~xc ~xs)
 
 (** Return true if the host memory is currently unbalanced and needs rebalancing *)
 let is_host_memory_unbalanced ~xc ~xs = 
-  Squeeze.is_host_memory_unbalanced (io ~xc ~xs)
+  Squeeze.is_host_memory_unbalanced (io ~verbose:false ~xc ~xs)
   
diff -r 1ee7e0184efe -r 4da34ecf1254 ocaml/xenops/squeezed.ml
--- a/ocaml/xenops/squeezed.ml	Fri Dec 04 16:04:07 2009 +0000
+++ b/ocaml/xenops/squeezed.ml	Fri Dec 04 16:04:07 2009 +0000
@@ -13,6 +13,7 @@
  *)
 let default_pidfile = "/var/run/squeezed.pid" 
 let log_file_path = "file:/var/log/squeezed.log" 
+let idle_timeout = 10. (* seconds per balancing check *)
 
 open Pervasiveext 
 open Squeezed_rpc
@@ -220,9 +221,9 @@
   Unixext.mkdir_rec (Filename.dirname !pidfile) 0o755;
   Unixext.pidfile_write !pidfile;
 
-  debug "Starting daemon";
+  debug "Starting daemon listening on %s with idle_timeout = %.0f" _service idle_timeout;
   try
-    with_xc_and_xs (fun xc xs -> Rpc.loop ~xc ~xs ~service:_service ~function_table ~idle_timeout:10. ~idle_callback:(idle_callback ~xc ~xs) () );
+    with_xc_and_xs (fun xc xs -> Rpc.loop ~xc ~xs ~service:_service ~function_table ~idle_timeout ~idle_callback:(idle_callback ~xc ~xs) () );
     debug "Graceful shutdown";
     exit 0
   with e ->
diff -r 1ee7e0184efe -r 4da34ecf1254 ocaml/xenops/squeezed_rpc.ml
--- a/ocaml/xenops/squeezed_rpc.ml	Fri Dec 04 16:04:07 2009 +0000
+++ b/ocaml/xenops/squeezed_rpc.ml	Fri Dec 04 16:04:07 2009 +0000
@@ -191,20 +191,20 @@
     (* list the requests which arrived before our watch was established *)
     process_new_requests ();
     while true do
-      if Xs.has_watchevents xs
-      then begin
-	debug "There are queued watch events";
-	while Xs.has_watchevents xs do
-	  ignore(Xs.get_watchevent xs)
-	done
+      if Xs.has_watchevents xs then begin
+		(* Drain the watch event queue *)
+		while Xs.has_watchevents xs do
+		  ignore(Xs.get_watchevent xs)
+		done
       end else begin
-	debug "Blocking for watch event %s" (if idle_timeout < 0. then "forever" else Printf.sprintf "for up to %.0f s" idle_timeout);
-	let r, _, _ = Unix.select [ Xs.get_fd xs ] [] [] idle_timeout in
-	if r = []
-	then idle_callback ()
-	else ignore(Xs.read_watchevent xs);
+		(* Nothing in the queue, wait for an event on the fd *)
+		let r, _, _ = Unix.select [ Xs.get_fd xs ] [] [] idle_timeout in
+		if r = []
+		then idle_callback ()
+		else ignore(Xs.read_watchevent xs);
       end;
-      process_new_requests ()
+	  (* We think there is some work to do *)
+	  process_new_requests ()
     done
 end