UnrealEngineUWP/Engine/Source/Programs/UnrealBuildTool/System/LocalExecutor.cs

// Copyright 1998-2014 Epic Games, Inc. All Rights Reserved.

using System;
using System.Collections.Generic;
using System.Text;
using System.Text.RegularExpressions;
using System.Diagnostics;
using System.IO;
using System.Reflection;
using System.Threading;
using System.Linq;

namespace UnrealBuildTool
{
	class ActionThread
	{
		/** Cache the exit code from the command so that the executor can report errors */
		public int ExitCode = 0;
		/** Set to true only when the local or RPC action is complete */
		public bool bComplete = false;
		/** Cache the action that this thread is managing */
		Action Action;
        /** For reporting status to the user */
        int JobNumber;
        int TotalJobs;

		/** Regex that matches environment variables in $(Variable) format. */
		static Regex EnvironmentVariableRegex = new Regex("\\$\\(([\\d\\w]+)\\)");

		/** Replaces the environment variables references in a string with their values. */
		public static string ExpandEnvironmentVariables(string Text)
		{
			foreach (Match EnvironmentVariableMatch in EnvironmentVariableRegex.Matches(Text))
			{
				string VariableValue = Environment.GetEnvironmentVariable(EnvironmentVariableMatch.Groups[1].Value);
				Text = Text.Replace(EnvironmentVariableMatch.Value, VariableValue);
			}
			return Text;
		}

		/**
		 * Constructor, takes the action to process
		 */
        public ActionThread(Action InAction, int InJobNumber, int InTotalJobs)
		{
			Action = InAction;
            JobNumber = InJobNumber;
            TotalJobs = InTotalJobs;
		}

		/**
		 * Sends a string to an action's OutputEventHandler
		 */
		private static void SendOutputToEventHandler(Action Action, string Output)
		{
			// Output status description (file name) when no output is returned
			if (string.IsNullOrEmpty(Output))
			{
				Output = Action.StatusDescription;
			}

			// pass the output to any handler requested
			if (Action.OutputEventHandler != null)
			{
				// NOTE: This is a pretty nasty hack with C# reflection, however it saves us from having to replace all the
				// handlers in various Toolchains with a wrapper handler that takes a string - it is certainly doable, but 
				// touches code outside of this class that I don't want to touch right now

				// DataReceivedEventArgs is not normally constructable, so work around it with creating a scratch Args object
				DataReceivedEventArgs EventArgs = (DataReceivedEventArgs)System.Runtime.Serialization.FormatterServices.GetUninitializedObject(typeof(DataReceivedEventArgs));

				// now we need to set the Data field using reflection, since it is read only
				FieldInfo[] ArgFields = typeof(DataReceivedEventArgs).GetFields(BindingFlags.NonPublic | BindingFlags.Instance | BindingFlags.DeclaredOnly);

				// call the handler once per line
				string[] Lines = Output.Split("\r\n".ToCharArray());
				foreach (string Line in Lines)
				{
				    // set the Data field
				    ArgFields[0].SetValue(EventArgs, Line);

				    // finally call the handler with this faked object
				    Action.OutputEventHandler(Action, EventArgs);
				}
			}
			else
			{
				// if no handler, print it out!
				Log.TraceInformation(Output);
			}
		}

		/**
		 * The actual function to run in a thread. This is potentially long and blocking
		 */
		private void ThreadFunc()
		{
			// thread start time
			Action.StartTime = DateTimeOffset.Now;
			
			if (Action.ActionHandler != null)
			{
				// call the function and get the ExitCode and an output string
				string Output;
				Action.ActionHandler(Action, out ExitCode, out Output);
				SendOutputToEventHandler(Action, Output);
			}
			else
			{
				// batch files (.bat, .cmd) need to be run via or cmd /c or shellexecute, 
				// the latter which we can't use because we want to redirect input/output
				bool bLaunchViaCmdExe = !Utils.IsRunningOnMono && !Path.GetExtension(Action.CommandPath).ToLower().EndsWith("exe");

				// Create the action's process.
				ProcessStartInfo ActionStartInfo = new ProcessStartInfo();
				ActionStartInfo.WorkingDirectory = ExpandEnvironmentVariables(Action.WorkingDirectory);


				string ExpandedCommandPath = ExpandEnvironmentVariables(Action.CommandPath);
				if (bLaunchViaCmdExe)
				{
					ActionStartInfo.FileName = "cmd.exe";
					ActionStartInfo.Arguments = string.Format
					(
						"/c \"{0} {1}\"",
						ExpandEnvironmentVariables(ExpandedCommandPath),
						ExpandEnvironmentVariables(Action.CommandArguments)
					);
				}
				else
				{
					ActionStartInfo.FileName = ExpandedCommandPath;
					ActionStartInfo.Arguments = ExpandEnvironmentVariables(Action.CommandArguments);
				}

				ActionStartInfo.UseShellExecute = false;
				ActionStartInfo.RedirectStandardInput = Action.bShouldBlockStandardInput;
				ActionStartInfo.RedirectStandardOutput = Action.bShouldBlockStandardOutput;
				ActionStartInfo.RedirectStandardError = Action.bShouldBlockStandardOutput;

				// Log command-line used to execute task if debug info printing is enabled.
				if (BuildConfiguration.bPrintDebugInfo)
				{
					Log.TraceVerbose("Executing: {0} {1}", ExpandedCommandPath, ActionStartInfo.Arguments);
				}
				// Log summary if wanted.
				else if (Action.bShouldOutputStatusDescription)
				{
					string CommandDescription = Action.CommandDescription != null ? Action.CommandDescription : Path.GetFileName(ExpandedCommandPath);
					if (string.IsNullOrEmpty(CommandDescription))
					{
						Log.TraceInformation(Action.StatusDescription);
					}
					else
					{
                        Log.TraceInformation("[{0}/{1}] {2} {3}", JobNumber, TotalJobs, CommandDescription, Action.StatusDescription);
					}
				}

				// Try to launch the action's process, and produce a friendly error message if it fails.
				Process ActionProcess = null;
				try
				{
					try
					{
						ActionProcess = new Process();
						ActionProcess.StartInfo = ActionStartInfo;
						bool bShouldRedirectOuput = Action.OutputEventHandler != null;
						if (bShouldRedirectOuput)
						{
							ActionStartInfo.RedirectStandardOutput = true;
							ActionStartInfo.RedirectStandardError = true;
							ActionProcess.EnableRaisingEvents = true;
							ActionProcess.OutputDataReceived += Action.OutputEventHandler;
							ActionProcess.ErrorDataReceived += Action.OutputEventHandler;
						}
						ActionProcess.Start();
						if (bShouldRedirectOuput)
						{
							ActionProcess.BeginOutputReadLine();
							ActionProcess.BeginErrorReadLine();
						}
					}
					catch (Exception ex)
					{
						throw new BuildException(ex, "Failed to start local process for action: {0} {1}\r\n{2}", Action.CommandPath, Action.CommandArguments, ex.ToString());
					}

					// wait for process to start
					// NOTE: this may or may not be necessary; seems to depend on whether the system UBT is running on start the process in a timely manner.
					int checkIterations = 0;
					bool haveConfiguredProcess = false;
					do
					{
						if(ActionProcess.HasExited)
						{
							if(haveConfiguredProcess == false)
								Debug.WriteLine("Process for action exited before able to configure!");
							break;
						}

						Thread.Sleep(100);
						
						if( !haveConfiguredProcess)
						{
							try
							{
								ActionProcess.PriorityClass = ProcessPriorityClass.BelowNormal;
								haveConfiguredProcess = true;
							}
							catch(Exception)
							{
							}
							break;
						}

						checkIterations++;
					} while(checkIterations < 10);
					if(checkIterations == 10)
					{
						throw new BuildException("Failed to configure local process for action: {0} {1}", Action.CommandPath, Action.CommandArguments);
					}

					// block until it's complete
					// @todo iosmerge: UBT had started looking at:	if (Utils.IsValidProcess(Process))
					//    do we need to check that in the thread model?
					while (!ActionProcess.HasExited)
					{
						Thread.Sleep(10);
					}

					// capture exit code
					ExitCode = ActionProcess.ExitCode;
				}
				finally
				{
					// As the process has finished now, free its resources. On non-Windows platforms, processes depend 
					// on POSIX/BSD threading and these are limited per application. Disposing the Process releases 
					// these thread resources.
					if(ActionProcess != null)
						ActionProcess.Close();
				}
			}

			// track how long it took
			Action.EndTime = DateTimeOffset.Now;

			// send telemetry
			{
				// See if the action produced a PCH file (infer from the extension as we no longer have the compile environments used to generate the actions.
				var ActionProducedPCH = Action.ProducedItems.Find(fileItem => new[] { ".PCH", ".GCH" }.Contains(Path.GetExtension(fileItem.AbsolutePath).ToUpperInvariant()));
				if (ActionProducedPCH != null && File.Exists(ActionProducedPCH.AbsolutePath)) // File may not exist if we're building remotely
				{
					// If we had a valid match for a PCH item, send an event.
					Telemetry.SendEvent("PCHTime.2",
						"ExecutorType", "Local",
						// Use status description because on VC tool chains it tells us more details about shared PCHs and their source modules.
						"Filename", Action.StatusDescription,
						// Get the length from the OS instead of the FileItem.Length is really for when the file is used as an input,
						// so the stored length is absent for a new for or out of date at best.
						"FileSize", new FileInfo(ActionProducedPCH.AbsolutePath).Length.ToString(),
						"Duration", Action.Duration.TotalSeconds.ToString("0.00"));
				}
			}

			if (!Utils.IsRunningOnMono)
			{
				// let RPCUtilHelper clean up anything thread related
				RPCUtilHelper.OnThreadComplete();
			}

			// we are done!!
			bComplete = true;
		}

		/**
		 * Starts a thread and runs the action in that thread
		 */
		public void Run()
		{
			Thread T = new Thread(ThreadFunc);
			T.Start();
		}
	};

	public class LocalExecutor
	{
		/**
		 * Executes the specified actions locally.
		 * @return True if all the tasks successfully executed, or false if any of them failed.
		 */
		public static bool ExecuteActions(List<Action> Actions)
		{
			// Time to sleep after each iteration of the loop in order to not busy wait.
			const float LoopSleepTime = 0.1f;

			// Use WMI to figure out physical cores, excluding hyper threading.
			int NumCores = 0;
			if (!Utils.IsRunningOnMono)
			{
				foreach(var Item in new System.Management.ManagementObjectSearcher("Select * from Win32_Processor").Get())
				{
					NumCores += int.Parse(Item["NumberOfCores"].ToString());
				}
			}
			// On some systems this requires a hot fix to work so we fall back to using the (logical) processor count.
			if( NumCores == 0 )
			{
				NumCores = System.Environment.ProcessorCount;
			}
			// The number of actions to execute in parallel is trying to keep the CPU busy enough in presence of I/O stalls.
			int MaxActionsToExecuteInParallel = 0;
			// The CPU has more logical cores than physical ones, aka uses hyper-threading. 
			if( NumCores < System.Environment.ProcessorCount )
			{
				MaxActionsToExecuteInParallel = (int) (NumCores * BuildConfiguration.ProcessorCountMultiplier);
			}
			// No hyper-threading. Only kicking off a task per CPU to keep machine responsive.
			else
			{
				MaxActionsToExecuteInParallel = NumCores;
			}

            if (ExternalExecution.GetRuntimePlatform() == UnrealTargetPlatform.Mac)
			{
				// @todo iosmerge: this should be looking at available memory as well since some of our
				// Macs have a poor memory/CPU ratio
				MaxActionsToExecuteInParallel /= 2;

				string NumUBTBuildTasks = Environment.GetEnvironmentVariable("NumUBTBuildTasks");
				Int32 MaxUBTBuildTasks = MaxActionsToExecuteInParallel;
				if(Int32.TryParse(NumUBTBuildTasks, out MaxUBTBuildTasks))
				{
					MaxActionsToExecuteInParallel = MaxUBTBuildTasks;
				}
			}

            Log.TraceInformation("Performing {0} actions (max {1} parallel jobs)", Actions.Count, MaxActionsToExecuteInParallel);

			Dictionary<Action, ActionThread> ActionThreadDictionary = new Dictionary<Action, ActionThread>();
            int JobNumber = 1;
			while(true)
			{
				// Count the number of pending and still executing actions.
				int NumUnexecutedActions = 0;
				int NumExecutingActions = 0;
				foreach (Action Action in Actions)
				{
					ActionThread ActionThread = null;
					bool bFoundActionProcess = ActionThreadDictionary.TryGetValue(Action, out ActionThread);
					if (bFoundActionProcess == false)
					{
						NumUnexecutedActions++;
					}
					else if (ActionThread != null)
					{
						if (ActionThread.bComplete == false)
						{
							NumUnexecutedActions++;
							NumExecutingActions++;
						}
					}
				}

				// If there aren't any pending actions left, we're done executing.
				if (NumUnexecutedActions == 0)
				{
					break;
				}

				// If there are fewer actions executing than the maximum, look for pending actions that don't have any outdated
				// prerequisites.
				foreach (Action Action in Actions)
				{
					ActionThread ActionProcess = null;
					bool bFoundActionProcess = ActionThreadDictionary.TryGetValue(Action, out ActionProcess);
					if (bFoundActionProcess == false)
					{
						if (NumExecutingActions < Math.Max(1,MaxActionsToExecuteInParallel))
						{
							// Determine whether there are any prerequisites of the action that are outdated.
							bool bHasOutdatedPrerequisites = false;
							bool bHasFailedPrerequisites = false;
							foreach (FileItem PrerequisiteItem in Action.PrerequisiteItems)
							{
								if (PrerequisiteItem.ProducingAction != null && Actions.Contains(PrerequisiteItem.ProducingAction))
								{
									ActionThread PrerequisiteProcess = null;
									bool bFoundPrerequisiteProcess = ActionThreadDictionary.TryGetValue( PrerequisiteItem.ProducingAction, out PrerequisiteProcess );
									if (bFoundPrerequisiteProcess == true)
									{
										if (PrerequisiteProcess == null)
										{
											bHasFailedPrerequisites = true;
										}
										else if (PrerequisiteProcess.bComplete == false)
										{
											bHasOutdatedPrerequisites = true;
										}
										else if (PrerequisiteProcess.ExitCode != 0)
										{
											bHasFailedPrerequisites = true;
										}
									}
									else
									{
										bHasOutdatedPrerequisites = true;
									}
								}
							}

							// If there are any failed prerequisites of this action, don't execute it.
							if (bHasFailedPrerequisites)
							{
								// Add a null entry in the dictionary for this action.
								ActionThreadDictionary.Add( Action, null );
							}
							// If there aren't any outdated prerequisites of this action, execute it.
                            else if (!bHasOutdatedPrerequisites)
                            {
                                ActionThread ActionThread = new ActionThread(Action, JobNumber, Actions.Count);
                                JobNumber++;
								ActionThread.Run();

								ActionThreadDictionary.Add(Action, ActionThread);

								NumExecutingActions++;
                            }
						}
					}
				}

				System.Threading.Thread.Sleep(TimeSpan.FromSeconds(LoopSleepTime));
			}

			Log.WriteLineIf(BuildConfiguration.bLogDetailedActionStats, TraceEventType.Information, "-------- Begin Detailed Action Stats ----------------------------------------------------------");
			Log.WriteLineIf(BuildConfiguration.bLogDetailedActionStats, TraceEventType.Information, "^Action Type^Duration (seconds)^Tool^Task^Using PCH^Description");

			double TotalThreadSeconds = 0;

			// Check whether any of the tasks failed and log action stats if wanted.
			bool bSuccess = true;
			foreach (KeyValuePair<Action, ActionThread> ActionProcess in ActionThreadDictionary)
			{
				Action Action = ActionProcess.Key;
				ActionThread ActionThread = ActionProcess.Value;

				// Check for pending actions, preemptive failure
				if (ActionThread == null)
				{
                    bSuccess = false;
					continue;
				}
				// Check for executed action but general failure
				if (ActionThread.ExitCode != 0)
				{
					bSuccess = false;
				}
                // Log CPU time, tool and task.
				double ThreadSeconds = Action.Duration.TotalSeconds;

				Log.WriteLineIf(BuildConfiguration.bLogDetailedActionStats,
					TraceEventType.Information,
					"^{0}^{1:0.00}^{2}^{3}^{4}^{5}", 
					Action.ActionType.ToString(),
					ThreadSeconds,
					Path.GetFileName(Action.CommandPath), 
                      Action.StatusDescription,
					Action.bIsUsingPCH,
					Action.StatusDetailedDescription);

				// Update statistics
				switch (Action.ActionType)
				{
					case ActionType.BuildProject:
						UnrealBuildTool.TotalBuildProjectTime += ThreadSeconds;
						break;

					case ActionType.Compile:
						UnrealBuildTool.TotalCompileTime += ThreadSeconds;
						break;

					case ActionType.CreateAppBundle:
						UnrealBuildTool.TotalCreateAppBundleTime += ThreadSeconds;
						break;

					case ActionType.GenerateDebugInfo:
						UnrealBuildTool.TotalGenerateDebugInfoTime += ThreadSeconds;
						break;

					case ActionType.Link:
						UnrealBuildTool.TotalLinkTime += ThreadSeconds;
						break;

					default:
						UnrealBuildTool.TotalOtherActionsTime += ThreadSeconds;
						break;
				}

				// Keep track of total thread seconds spent on tasks.
				TotalThreadSeconds += ThreadSeconds;
			}

			Log.TraceInformation("-------- End Detailed Actions Stats -----------------------------------------------------------");

			// Log total CPU seconds and numbers of processors involved in tasks.
			Log.WriteLineIf(BuildConfiguration.bLogDetailedActionStats || BuildConfiguration.bPrintDebugInfo, 
				TraceEventType.Information, "Cumulative thread seconds ({0} processors): {1:0.00}", System.Environment.ProcessorCount, TotalThreadSeconds);

			return bSuccess;
		}
	};
}