Add fault telemetry for (hopefully) all VS APIs

[zivkan]

Bug

Fixes: NuGet/Home#10062
Regression: No

• Last working version:
• How are we preventing it in future:

Fix

Details:

• Created INuGetTelemetryProvider, with MEF implementation, so that this is easily testable.
• Tried to find all implementations of interfaces defined in NuGet.VisualStudio and NuGet.VisualStudio.Contracts, and add try-catch blocks to log faults on public methods, then rethrow exception.

Testing/Validation

Tests Added: No
Reason for not adding tests: Existing tests modified. Also, the telemetry is only supposed to record unexpected faults, not expected faults (tests are configured to fail if they try to report fault).
Validation:

[erdembayar]

Can you make this one same of line 36, just to keep same coding format.
fault.Properties[$"{VSTelemetrySession.VSPropertyNamePrefix}kvp.Key"] = kvp.Value;

[zivkan]

I don't know if the C# compiler is better now, but initially at least interpolated strings ($"... {something}" was just syntactic sugar for string.Format, and the book "Writing High Performance .NET Code" discusses how string.Format harms performance since the runtime has to parse the format string, and build up the final string. Their recommendation was to use string concatenation instead. Hence I changed line 36 to do that instead.

[donnie-msft]

Didn't realize string.Format had that perf hit. I think StringBuilder is the most perf and memory efficient, right?
I don't really prefer reading the concatenation, especially inline an indexer like that.

[zivkan]

c#10 (or maybe later) might have const interpolated strings, so in the future this may no longer be necessary. But string.Concat can produce const strings determined at compile time, rather than runtime. And at runtime, string.Concat (which the + operator is syntactic sugar for) remains to be by far the fastest execution at runtime as well.

string.Concat only takes strings as input, anything that is not a string is implicitly run though .ToString() before being passed to string.Concat, meaning that string.Concat can use args.Sum(a => a.Length) to determine the exact length of the final string, do a single memory allocation of the required length, then copy the input strings one by one.

Using a StringBuilder is the next best. It has a small allocation for the StringBuilder object iteself, and it allocates at least one buffer. As you call Append, it copies your string into the buffer, and if the buffer gets full, it needs to allocate more buffers. Finally, when you call StringBuilder.ToString(), it can do the same work as string.Concat, which as previously stated is an additional allocation of the required length. Hence, we can see that StringBuilder cannot possibly be more efficient than string.Concat, since it does everything that string.Concat does, plus more.

string.Format (which is what interpolated strings are, and also what StringBuilder's AppendFormat method is) is the least efficient. Internally, it creates a string builder (except in the StringBuilder.AppendFormat case), since it can't figure out what the final string length is going to be from the inputs alone. Therefore it can't possibly be faster than StringBuilder, since it uses a StringBuilder. As previously mentioned, Format also needs to parse the input string to find the {x} placeholders, copy the static parts, then parse the placeholder to see if there are formatting options, then call ToString on the relevant object with the discovered formatting options. string.Format and StringBuilder.AppendFormat are therefore by far the slowest at runtime. My memory is that the Writing High Performance .NET Code book claimed that using StringBuilder with a series of Append calls is faster than string.Format.

So in summary, constStr1 + constStr2 will be evaluated at compile time, so runtime does nothing more than load a const string. This should become available for interpolated const strings in the future, but is not yet available. If the strings are not const at compile time, string concatenation remains the fastest, so if you want to hyper-optimize allocations, this is the best bet. It's always best if all strings you need to concat are in a single call, but even if you use string.Concat a small number of times to generate a single string, it can still be faster than using a StringBuilder. Using (non-const) interpolated strings, or string.Format basically means you don't care about performance. Having said that, while we don't want our tools to be slow, client tools don't have the same concerns or cost savings that web services like Bing or Office web applications have.

[donnie-msft]

string.Concat only takes strings as input

Strings that are already allocated. I thought the whole memory consumption (not perf) problem with concat was in string1 + string2, you allocate 2 strings, then you allocate a result string and garbage collect 1 and 2. StringBuilder's buffering avoided that.
Anyway, thanks for the writeup and book recommendation!

[erdembayar]

I understand your intention we don't add new unit test for this new telemetry exception handler.
But just sake of exception handling can we still add just 1-2 unit test where you intentionally throw some random exception and make sure something is captured in telemetry context? My point is if it doesn't catch intentional/known exception then how it capture unknown one?

[zivkan]

I added a whole bunch of tests now, for everything that is testable.

[kartheekp-ms]

I prefer calling PostFaultAsync method from the same class instead of TelemetryUtility.PostFaultAsync so that there will be a single place to change code if needed in the future.

[zivkan]

This PR is currently blocked on #3776

That PR changes some code related to getting project GUIDs from EnvDTE.Project instances, and I want to re-use that code to enhance reported faults with project information, so we have a better chance of understanding bugs when faults are logged.

[nkolev92]

Ping us when the other PR gets merged and this is ready for review :)

[zivkan]

@NuGet/nuget-client this is ready for review now.

The "Get project GUID from a EnvDTE.Project" helper method needs the VS solution object, and I didn't feel like getting this service in a bunch of classes just for error reporting. So, I propose we merge this as-is, and if we find that there are some VS extensibility APIs that are frequently throwing exceptions, and we want to get more project information, then we can improve it in a future version to add project GUID. For now, knowing which APIs throw exceptions is enough of an improvement.

[nkolev92]

I'm not super thrilled because this implementation is not scalable.

How hard have you thought about alternatives?

[nkolev92]

nit: Probably doesn't need to return Task. It's also a private API, so there's no "maybe in the future" questions :)

[nkolev92]

this time of delegation makes me cringe :D
The problem is that the only other alternative I can suggest is to have a wrapper that uses reflection.

[zivkan]

Another alternative, which I implemented, is to call .ToList() at the end of each. This of course has multiple performance impacts. If the caller does Whatever().First(), then we'll now be evaluating every item in the result set, not just the first. Also, we'll always be doing extra allocations, but it's hard to imagine that these APIs are being used in such critical codepaths where that perf is important.

[zivkan]

I'm not super thrilled because this implementation is not scalable.

How hard have you thought about alternatives?

Not at all, but thinking about it now:

One way to implement this is to use a tool like Fody which "stiches" (modifies/rewrites) MSIL after compilation to modify the implementation without needing to implement by code. I've never actually tried/used this (or Postsharp) on anything, but it should allow us to write a logging implementation once, and just use an attribute on each class that should use it, and the tool will do its magic as part of the build process.

Other alternatives are to use Castle Core, or wrap our "real" objects with DynamicObject. We use TryInvokeMethod to wrap every public method with a try-catch block that posts faults. I have worked on something that used "dynamic proxy" before, and if you do a microbenchmark, it has an enormous performance penalty. Whether or not that perf impact matters in the real world is up for debate, but it's effectively using something like reflection to check if methods exist, and then invoke them

A problem with all of the above solutions is that they try to fit everything they wrap into the same box. You can wrap an entire method in a try catch, but I don't know of a good way to say "ArgumentExceptions caused by input parameters should not be logged, but other ArgumentExceptions, because of buggy service implementation, should be logged". We could choose to ignore all ArgumentExceptions, but then we won't catch certain types of product regressions. It also makes it more difficult to have more semantic logging, where faults for methods that have a project parameter log the project guid as additional fault properties. I'm sure it can be done, but I'm worried it would require more reflection, so not ideal for performance (although perf of propagating unexpected errors is probably not a concern).

We could put the try-catch-postfault code in a helper method FaultReporter.Run(Func<T> func), and change every public service API to call this. It will impact just as many call sites as the current PR, and future APIs, but there should be fewer lines in total. It would allow us to do input validation outside of the delegate passed to the helper method, so input validation errors won't get logged as faults. The API would get more complex if there are other exceptions that are expected and therefore we wouldn't want to log.

Those are all my ideas at the current time.

[donnie-msft]

Didn't realize string.Format had that perf hit. I think StringBuilder is the most perf and memory efficient, right?
I don't really prefer reading the concatenation, especially inline an indexer like that.

[nkolev92]

I don't have a better proposal for what you are trying to do.