A few months ago I wrote about MPGO, a new Microsoft tool that ships with .NET 4.5 and enables profile-guided optimization of managed assemblies. Specifically, MPGO optimizes the layout of native images for managed assemblies, which reduces startup times, working set sizes, and page fault costs.

Shameless plug: Pro .NET Performance has a large section dedicated to improving startup performance, and I’ve written about this before: Using Prefetch to improve startup performance, Rebasing and compression.

Anyway, I was experimenting with MPGO and encountered a strange error when working with some of my assemblies. Specifically:

C:\Temp\mpgo test>mpgo -scenario App.exe -assemblylist App.exe -OutDir .

Error:  Timeout or error when trying to instrument assembly C:\Temp\mpgo test\App.exe (FFFFFFFF)
Profile information will not be collected for this assembly.
This will not prevent information from being collected for other assemblies

Error:  Timeout or Error when trying to remove instrumented assembly C:\Temp\mpgo test\App.exe (FFFFFFFF)
Failed to merge collected profile data into assembly C:\Temp\mpgo test\App.exe:
Unexpected Internal Exception The file "C:\Temp\mpgo test\App.ibc" does not exist

This error struck me as odd, because the application in question was really simple, and I certainly didn’t know what error FFFFFFFF meant. I tried specifying the full path to the executable, and got a different error instead:

C:\Temp\mpgo test>mpgo -scenario "C:\temp\mpgo test\App.exe" -assemblylist "C:\temp\mpgo test\App.exe" -OutDir .

Session executable does not appear to exist.

This produced a somewhat simpler error, although still completely misleading because App.exe exists in the specified directory. However, because the full path changed MPGO’s behavior, I suspected that something in its file access code or command-line parsing has gone awry.

This is where I launched Process Monitor and configured it to watch all events generated by MPGO.EXE. When using the latter command line, I saw very quickly that MPGO was trying (and failing) to access “C:\Temp\mpgo”, which is a directory that doesn’t exist—I explicitly gave it “C:\Temp\mpgo test\App.exe” as a parameter!

At this point I just had to look at the call stack to see what’s going on. MPGO.EXE is a managed application, but Process Monitor can’t give you managed call stacks (yet?), so I had to attach WinDbg and !u the raw addresses to see where the file access was coming from.

0:000> !u 0x600f8b
Normal JIT generated code
MPGO.Harness.PreRunValidation()
Begin 00600e10, size 22d
00600e10 55              push    ebp
00600e11 8bec            mov     ebp,esp
…snipped…
00600f7e 8b4e04          mov     ecx,dword ptr [esi+4]
00600f81 ba01000000      mov     edx,1
00600f86 e8051e7f59      call    mscorlib_ni+0x2f2d90 (59df2d90) (System.IO.File.InternalExistsHelper(System.String, Boolean), mdToken: 06004402)
00600f8b 85c0            test    eax,eax
00600f8d 7541            jne     00600fd0
00600f8f b9fc432a00      mov     ecx,2A43FCh (MT: MPGO.MpgoException)
00600f94 e88310c9ff      call    0029201c (JitHelp: CORINFO_HELP_NEWSFAST)
…snipped…

Next, I turned to the PreRunValidation method in Reflector and discovered that the exception is thrown because MPGO thinks my executable file does not exist, from a line that looks like this:

if (!File.Exists(this.Exe))
{
  MpgoException.Throw("Err_ExeMissing");
}

By inspecting all assignments to this.Exe, I found the following in the Harness class constructor:

Match match = Regex.Match(args[i], "(?<exe>(?:\"[^\"]+\")|[^ ]+)(?: (?<args>.*))?");
if (!match.Success)
{
    Usage.Show("Err_CantParseScenario_0", args[i]);
}
this.Exe = match.Groups["exe"].ToString();
if (this.Exe.StartsWith("\""))
{
    this.Exe = this.Exe.Trim(new char[] { '"' });
}
this.Exe = Path.GetFullPath(this.Exe);
this.Args = match.Groups["args"].ToString();

When applied to a quoted path, such as “C:\temp\mpgo test\App.exe”, this code produces an unquoted executable name and considers everything that follows the space to be the executable’s arguments…

There is a different bug when using the former command line. In that case, I configured Process Monitor to log process (and thread) creation/deletion events, and noticed that MPGO.EXE launches NGEN.EXE with an invalid command line:

The full command line is:

"C:\Windows\Microsoft.NET\Framework\v4.0.30319\ngen.exe" install C:\Temp\mpgo test\App.exe /tuning /ExeConfig:C:\Temp\mpgo test\App.exe

…which confuses NGEN, because it treats “C:\Temp\mpgo” as the application name and the rest is an invalid command line. This time, the problem is that when launching NGEN, MPGO does not bother to quote the application name.

To summarize: the purpose of this post is not to bash MPGO—the bug has been reported to the team responsible and will likely be fixed in the next Visual Studio 11 drop. What I wanted to show is that Process Monitor is quite useful in determining why applications you aren’t familiar with are behaving incorrectly. Also, figuring out proper quoting of command line parameters is really nasty (on Windows).