Log profile.ps1 invocation time (#361)

Log profile.ps1 invocation time

Author: AnatoliB

src/PowerShell/PowerShellManager.cs

@@ -7,6 +7,7 @@
 using System.Collections;
 using System.Collections.Generic;
 using System.Collections.ObjectModel;
+using System.Diagnostics;
 using System.Reflection;
 using System.Threading;
 using Microsoft.Azure.Functions.PowerShellWorker.Durable;
@@ -163,6 +164,9 @@ internal void InvokeProfile(string profilePath)
 
             try
             {
+                var stopwatch = new Stopwatch();
+                stopwatch.Start();
+
                 // Import-Module on a .ps1 file will evaluate the script in the global scope.
                 _pwsh.AddCommand(Utils.ImportModuleCmdletInfo)
                         .AddParameter("Name", profilePath)
@@ -171,6 +175,8 @@ internal void InvokeProfile(string profilePath)
                         .AddParameter("Force", Utils.BoxedTrue)
                         .AddParameter("ErrorAction", "SilentlyContinue")
                      .InvokeAndClearCommands();
+
+                Logger.Log(isUserOnlyLog: false, LogLevel.Trace, string.Format(PowerShellWorkerStrings.ProfileInvocationCompleted, stopwatch.ElapsedMilliseconds));
             }
             catch (Exception e)
             {

src/resources/PowerShellWorkerStrings.resx

@@ -289,6 +289,9 @@
   <data name="FirstFunctionLoadCompleted" xml:space="preserve">
     <value>First function load request completed in {0} ms.</value>
   </data>
+  <data name="ProfileInvocationCompleted" xml:space="preserve">
+    <value>Profile invocation completed in {0} ms.</value>
+  </data>
   <data name="FunctionInvocationStarting" xml:space="preserve">
     <value>Invoking function '{0}' code {1} ms after receiving request. Invocation performance details: {2}</value>
   </data>

test/Unit/PowerShell/PowerShellManagerTests.cs

@@ -15,6 +15,7 @@
 
 namespace Microsoft.Azure.Functions.PowerShellWorker.Test
 {
+    using System.Collections.ObjectModel;
     using System.Management.Automation;
 
     internal class TestUtils
@@ -285,8 +286,23 @@ public void ProfileShouldWork()
             s_testLogger.FullLog.Clear();
             testManager.InvokeProfile(profilePath);
 
-            Assert.Single(s_testLogger.FullLog);
-            Assert.Equal("Information: INFORMATION: Hello PROFILE", s_testLogger.FullLog[0]);
+            var relevantLogs = s_testLogger.FullLog.Where(message => !message.StartsWith("Trace:")).ToList();
+            Assert.Single(relevantLogs);
+            Assert.Equal("Information: INFORMATION: Hello PROFILE", relevantLogs[0]);
+        }
+
+        [Fact]
+        public void ProfileExecutionTimeShouldBeLogged()
+        {
+            var profilePath = Path.Join(s_funcDirectory, "ProfileBasic", "profile.ps1");
+            var testManager = NewTestPowerShellManager(s_testLogger);
+            
+            s_testLogger.FullLog.Clear();
+            testManager.InvokeProfile(profilePath);
+
+            Assert.Equal(1, s_testLogger.FullLog.Count(
+                                message => message.StartsWith("Trace")
+                                           && message.Contains("Profile invocation completed in")));
         }
 
         [Fact]
@@ -299,8 +315,9 @@ public void ProfileWithTerminatingError()
             s_testLogger.FullLog.Clear();
 
             Assert.Throws<CmdletInvocationException>(() => testManager.InvokeProfile(profilePath));
-            Assert.Single(s_testLogger.FullLog);
-            Assert.Matches("Error: Failed to run profile.ps1. See logs for detailed errors. Profile location: ", s_testLogger.FullLog[0]);
+            var relevantLogs = s_testLogger.FullLog.Where(message => !message.StartsWith("Trace:")).ToList();
+            Assert.Single(relevantLogs);
+            Assert.Matches("Error: Failed to run profile.ps1. See logs for detailed errors. Profile location: ", relevantLogs[0]);
         }
 
         [Fact]
@@ -313,10 +330,11 @@ public void ProfileWithNonTerminatingError()
             s_testLogger.FullLog.Clear();
             testManager.InvokeProfile(profilePath);
 
-            Assert.Equal(2, s_testLogger.FullLog.Count);
-            Assert.StartsWith("Error: ERROR: ", s_testLogger.FullLog[0]);
-            Assert.Contains("help me!", s_testLogger.FullLog[0]);
-            Assert.Matches("Error: Failed to run profile.ps1. See logs for detailed errors. Profile location: ", s_testLogger.FullLog[1]);
+            var relevantLogs = s_testLogger.FullLog.Where(message => !message.StartsWith("Trace:")).ToList();
+            Assert.Equal(2, relevantLogs.Count);
+            Assert.StartsWith("Error: ERROR: ", relevantLogs[0]);
+            Assert.Contains("help me!", relevantLogs[0]);
+            Assert.Matches("Error: Failed to run profile.ps1. See logs for detailed errors. Profile location: ", relevantLogs[1]);
         }
 
         [Fact]