227

Environment: Visual Studio 2015 RTM. (I haven't tried older versions.)

Recently, I've been debugging some of my Noda Time code, and I've noticed that when I've got a local variable of type NodaTime.Instant (one of the central struct types in Noda Time), the "Locals" and "Watch" windows don't appear to call its ToString() override. If I call ToString() explicitly in the watch window, I see the appropriate representation, but otherwise I just see:

variableName       {NodaTime.Instant}

which isn't very useful.

If I change the override to return a constant string, the string is displayed in the debugger, so it's clearly able to pick up that it's there - it just doesn't want to use it in its "normal" state.

I decided to reproduce this locally in a little demo app, and here's what I've come up with. (Note that in an early version of this post, DemoStruct was a class and DemoClass didn't exist at all - my fault, but it explains some comments which look odd now...)

using System;
using System.Diagnostics;
using System.Threading;

public struct DemoStruct
{
    public string Name { get; }

    public DemoStruct(string name)
    {
        Name = name;
    }

    public override string ToString()
    {
        Thread.Sleep(1000); // Vary this to see different results
        return $"Struct: {Name}";
    }
}

public class DemoClass
{
    public string Name { get; }

    public DemoClass(string name)
    {
        Name = name;
    }

    public override string ToString()
    {
        Thread.Sleep(1000); // Vary this to see different results
        return $"Class: {Name}";
    }
}

public class Program
{
    static void Main()
    {
        var demoClass = new DemoClass("Foo");
        var demoStruct = new DemoStruct("Bar");
        Debugger.Break();
    }
}

In the debugger, I now see:

demoClass    {DemoClass}
demoStruct   {Struct: Bar}

However, if I reduce the Thread.Sleep call down from 1 second to 900ms, there's still a short pause, but then I see Class: Foo as the value. It doesn't seem to matter how long the Thread.Sleep call is in DemoStruct.ToString(), it's always displayed properly - and the debugger displays the value before the sleep would have completed. (It's as if Thread.Sleep is disabled.)

Now Instant.ToString() in Noda Time does a fair amount of work, but it certainly doesn't take a whole second - so presumably there are more conditions that cause the debugger to give up evaluating a ToString() call. And of course it's a struct anyway.

I've tried recursing to see whether it's a stack limit, but that appears not to be the case.

So, how can I work out what's stopping VS from fully evaluating Instant.ToString()? As noted below, DebuggerDisplayAttribute appears to help, but without knowing why, I'm never going to be entirely confident in when I need it and when I don't.

Update

If I use DebuggerDisplayAttribute, things change:

// For the sample code in the question...
[DebuggerDisplay("{ToString()}")]
public class DemoClass

gives me:

demoClass      Evaluation timed out

Whereas when I apply it in Noda Time:

[DebuggerDisplay("{ToString()}")]
public struct Instant

a simple test app shows me the right result:

instant    "1970-01-01T00:00:00Z"

So presumably the problem in Noda Time is some condition that DebuggerDisplayAttribute does force through - even though it doesn't force through timeouts. (This would be in line with my expectation that Instant.ToString is easily fast enough to avoid a timeout.)

This may be a good enough solution - but I'd still like to know what's going on, and whether I can change the code simply to avoid having to put the attribute on all the various value types in Noda Time.

Curiouser and curiouser

Whatever is confusing the debugger only confuses it sometimes. Let's create a class which holds an Instant and uses it for its own ToString() method:

using NodaTime;
using System.Diagnostics;

public class InstantWrapper
{
    private readonly Instant instant;

    public InstantWrapper(Instant instant)
    {
        this.instant = instant;
    }

    public override string ToString() => instant.ToString();
}

public class Program
{
    static void Main()
    {
        var instant = NodaConstants.UnixEpoch;
        var wrapper = new InstantWrapper(instant);

        Debugger.Break();
    }
}

Now I end up seeing:

instant    {NodaTime.Instant}
wrapper    {1970-01-01T00:00:00Z}

However, at the suggestion of Eren in comments, if I change InstantWrapper to be a struct, I get:

instant    {NodaTime.Instant}
wrapper    {InstantWrapper}

So it can evaluate Instant.ToString() - so long as that's invoked by another ToString method... which is within a class. The class/struct part seems to be important based on the type of the variable being displayed, not what code needs to be executed in order to get the result.

As another example of this, if we use:

object boxed = NodaConstants.UnixEpoch;

... then it works fine, displaying the right value. Colour me confused.

Jon Skeet
  • 1,421,763
  • 867
  • 9,128
  • 9,194
  • `$"Struct: {Name}"` ... what's with the `$`? Is that a new language feature or yet another thing i have never seen before?! – 3-14159265358979323846264 Jul 22 '15 at 12:19
  • 7
    @John same behavior in VS 2013 (I had to remove the c#6 stuff), with an additional message: Name Function evaluation disabled because a previous function evaluation timed out. You must continue execution to reenable function evaluation. string – vc 74 Jul 22 '15 at 12:20
  • 1
    welcome to c# 6.0 @3-14159265358979323846264 – Neel Jul 22 '15 at 12:21
  • 1
    Maybe a `DebuggerDisplayAttribute` would cause it to try a little harder. – Rawling Jul 22 '15 at 12:21
  • @Rawling: But what would I specify for how to format it? The point of overriding ToString is that it's already providing the right format. It's not like I want to select a specific property... – Jon Skeet Jul 22 '15 at 12:24
  • @JonSkeet Just wondered if pointing the attribute at `ToString` would trick it into waiting a little longer. (Or make it avoid the new "fall back to default `ToString`" behaviour and fail differently?) – Rawling Jul 22 '15 at 12:26
  • @Rawling: Trying `[DebuggerDisplay("{ToString()}")]` with my sample code changes it to "Evaluation timed out" :0 – Jon Skeet Jul 22 '15 at 12:26
  • Same behaviour on VS2010 Professional – MakePeaceGreatAgain Jul 22 '15 at 12:29
  • @Rawling: Ooh - trying that in Noda Time *does* work, for some reason. Will update the post with that when I get a chance - thanks! Would still like to know why it's needed though - seems odd... – Jon Skeet Jul 22 '15 at 12:30
  • 1
    You can change the timeout in the registry ... http://stackoverflow.com/a/1212068/5040941. (And thanks @Neel)! – 3-14159265358979323846264 Jul 22 '15 at 12:37
  • I created "NormalEvalTimeout" and set it to 2000 (hex, became 8192), and it still times out as described in the question. The timeout value was not present in the registry so it may not apply to 2015. – Lasse V. Karlsen Jul 22 '15 at 12:42
  • 1
    I also noticed that if I create a timeout parameter to the struct, and construct first one with 900 and then one with 1000 (before and after breakpoint), the one with 1000 shows the type but the one with 900 shows the ToString value. *However*, if I switch them around, both will show the type. In other words it seems the locals window / evaulation engine remembers the previous problem with ToString and bumps back to the type when it thinks this is just too slow. – Lasse V. Karlsen Jul 22 '15 at 12:43
  • @LasseV.Karlsen: Right. That wouldn't surprise me - good to know though. – Jon Skeet Jul 22 '15 at 12:45
  • I also noticed something else. I created three variables, one before breakpoint and two after. These had timeouts of 800, 1000, 800 respectively. When I step through this it shows Struct:Bar, null, null, then Struct:Bar, DemoStruct, null, then DemoStruct, DemoStruct, DemoStruct. It seems when it discovered that ToString took too much time, at some point it re-evaluates the contents and then just defaults back to the type. – Lasse V. Karlsen Jul 22 '15 at 12:45
  • Note that I see the exact same problems you have described and the ones I tested in my previous comments even if I switch to plain old String.Format. String interpolation is a red herring (or maybe I just didn't understand the bulletpoints at the bottom of your question) – Lasse V. Karlsen Jul 22 '15 at 12:49
  • If you mean whether DebuggerDisplay uses string interpolation, then no. This syntax has been allowed quite a while so it should work just fine on older .NET versions and Visual Studio versions. I tested this in 2012 and it actually works identical to 2015 in terms of how it displays just ToString (like I've described in my comments as well). ToString works with the syntax you've shown. – Lasse V. Karlsen Jul 22 '15 at 12:50
  • @LasseV.Karlsen: Thanks - have removed the bit around C# 6 as a red herring. – Jon Skeet Jul 22 '15 at 12:54
  • With my 3 structs and 800,1000,800 timeouts I got this using DebuggerDisplay in 2012: Struct:Bar, Function evaluation timed out, Function evaluation disabled because a previous function evaluation timed out. You must continue execution to reenable function evaluation. – Lasse V. Karlsen Jul 22 '15 at 12:55
  • 2015 actually worked better with DebuggerDisplay. Where 2012 flagged the type as "cannot use DebuggerDisplay, give 'has been disabled' error message", 2015 did re-evaluate DebuggerDisplay for my 3rd instance. 2015 gave me Struct:Bar, Evaluation timed out, Struct:Bar. – Lasse V. Karlsen Jul 22 '15 at 12:57
  • The question I have is why Instance would trigger this. Surely the ToString method of that doesn't take long to evaluate. In other words, there must be other reasons than just "1 second timeout" that triggers this behavior of reverting to type. I guess that is why you posted this :) Could it be that the *sum* of all locals cannot exceed 1 second? Testing... – Lasse V. Karlsen Jul 22 '15 at 12:59
  • @LasseV.Karlsen: Exactly - it's definitely not just a timeout. (Note how the attribute makes the two behave differently.) I thought briefly that it might have been due to evaluation using a lock, but that doesn't seem to be it. (The sum of all locals would still be tiny in the case I'm looking at.) – Jon Skeet Jul 22 '15 at 13:00
  • Sum is not the case. 3 instances each with a timeout of 800 evaluated all just fine if I stepped past all of them (breakpoint before all and after all). Upping the timeout of the middle one to 1200 gave me Struct:Bar, DemoStruct, DemoStruct. – Lasse V. Karlsen Jul 22 '15 at 13:02
  • I tried allocating 86000 bytes a thousand times with and without a GC.Collect between each to see if it tracked memory usage or garbage collections but that did not change anything. – Lasse V. Karlsen Jul 22 '15 at 13:06
  • Hmm. I'm quietly going insane on this one. I've modified the `Thread.Sleep` to be 60000 and yet running the debugger, it hits the Break line far quicker than a minute and *always* shows the custom value that `ToString` should return. – Damien_The_Unbeliever Jul 22 '15 at 13:07
  • Hmm, discovered something. If an exception is thrown in ToString, the display in locals is the type, even without a sleep at all. Could this be it? Note that if you enable code analysis, it will explicitly call out exceptions being thrown in ToString as *DemoStruct.ToString()' creates an exception of type 'Exception'. Exceptions should not be raised in this type of method. If this exception instance might be raised, change this method's logic so it no longer raises an exception.* This is [CA1065](https://msdn.microsoft.com/en-us/library/bb386039.aspx). – Lasse V. Karlsen Jul 22 '15 at 13:08
  • Trying to debug the Visual Studio debugger as a black box is surely an interesting exercise, but is it really a productive use of your time? Anyone with the source code could quickly give you a definitive answer to your question, and maybe also fix the problem. Consider giving up and using one of the workarounds suggested here, or (even) adding some logging code to accomplish the same goal. – Diomidis Spinellis Jul 22 '15 at 13:12
  • @LasseV.Karlsen: No exceptions - and it's just got odder. See my update ("curiouser and curiouser"). – Jon Skeet Jul 22 '15 at 13:13
  • 5
    @DiomidisSpinellis: Well I've asked it here so that a) someone who's either seen the same thing before or knows the inside of VS can answer; b) anyone running into the same issue in the future can get the answer quickly. – Jon Skeet Jul 22 '15 at 13:14
  • With my 3 instances having a timeout of 800,1200,800 + 3 wrappers, one for each (using the exact same tostring with the exact same timeout) shows Struct:Bar, 2x type, 3x Struct:Bar. So yes, curiouser and curiouser. – Lasse V. Karlsen Jul 22 '15 at 13:18
  • @JonSkeet Good point! Or even c) find out that this is a known bug with no good answer. – Diomidis Spinellis Jul 22 '15 at 13:27
  • @JonSkeet `InstantWrapper` is a class and `Instant` is a struct. Maybe it evaluates classes and structs differently? You might try changing `InstanceWrapper` to be a struct as well. – Eren Ersönmez Jul 22 '15 at 14:21
  • @ErenErsönmez: Ooh, well spotted. Yes, that changes things. Updating. – Jon Skeet Jul 22 '15 at 14:24
  • @jon So many comments I can't get through them all. Did you try to see if the limit on evaluation is actually method size? Similar to the limit imposed when method in-lining is being considered? Also, could the difference between a struct and class have to do with the method call IL? Not sure what it looks like off-hand, I'd assume it's the same, but maybe the compiler is doing something extra to get the value type back into an `object`. – Adam Houldsworth Jul 22 '15 at 14:31
  • @AdamHouldsworth: I didn't look, but the body of the `Instant.ToString` method is just a single method call, so I very much doubt that that's relevant. (Good thought though.) – Jon Skeet Jul 22 '15 at 14:34
  • Actually, my observations have all been done where DemoStruct is a class, since it was that in the first version of this question. I did at some point think it odd you named a class DemoStruct but thought it was just an artifact of heavy experimentation, did not notice that you edited the question and changed that. So my comments above about timeouts and 3 instances and wrappers and such, everything is classes. – Lasse V. Karlsen Jul 22 '15 at 14:34
  • @LasseV.Karlsen: Whoops - yes, I noticed and fixed that, but didn't raise it... are you easily able to check whether the observations do actually still hold? – Jon Skeet Jul 22 '15 at 14:35
  • @Jon Unless the compiled method features in-lined content from the method call? Maybe the IL is larger than the C# you can see. Clutching at straws really, can't wait to see a VS dev answer this one :-) – Adam Houldsworth Jul 22 '15 at 14:35
  • It changes. With classes, 3 instances + 3 wrappers (in that order), with timeouts 800, 1200, 800: tostring+2x type+3x tostring. Changing inner class to struct: 4x tostring + 2x type. Changing wrapper to struct as well: 6x tostring. This is code that just constructs all 6 instances (3 inner, then 3 wrappers) then hit a breakpoint. So it seems the rule is that if it's a struct, we're going to evaluate it no matter what, but for classes there is a timeout. Well, except for the wrapper, which behaves oddly :) I'm voting on random. This is `new Random()` in a new disguise :) – Lasse V. Karlsen Jul 22 '15 at 14:39
  • @LasseV.Karlsen That rule sounds like it might be based on the predictable inheritance chain of `struct` types (ie none) vs classes, which could be very complicated and costly. I wonder if it relates to walking too much code, or code across libraries or something. – Adam Houldsworth Jul 22 '15 at 14:41
  • There could also be an expectancy that structs are supposed to be light-weight values, whereas classes tend to be more complex. – Lasse V. Karlsen Jul 22 '15 at 14:42
  • @Jon On a more serious note, the SO devs need to fix the UI. Your badge counts are cropped on the user tile... – Adam Houldsworth Jul 22 '15 at 14:43
  • @LasseV.Karlsen: That's odd - and doesn't fit with Instant being a struct. I've just found it getting even weirder though - if I have a 10 second sleep in ToString, it seems to be ignored while evaluating it. Do you think it's worth me changing this back to being a class, to make the question more consistent? – Jon Skeet Jul 22 '15 at 14:43
  • @LasseV.Karlsen: Have updated the first repro app to have both a struct and a class. Annoyingly, this morning (when I first tried to repro this) I already had `DemoStruct` and `DemoClass`, but `DemoStruct` was always a class. Humbug. I suck. – Jon Skeet Jul 22 '15 at 14:49
  • @JonSkeet - the `Thread.Sleep` seeming to have no effect is what I was reporting, way up there ^^^^^^^. – Damien_The_Unbeliever Jul 22 '15 at 14:49
  • @Damien_The_Unbeliever: Right - and presumably you correctly had it as a struct? It does make a difference when it's a class. – Jon Skeet Jul 22 '15 at 14:50
  • I have the same in VS2012 and never found a solution. – magicandre1981 Jul 22 '15 at 16:08

1 Answers1

195

Update:

This bug has been fixed in Visual Studio 2015 Update 2. Let me know if you are still running into problems evaluating ToString on struct values using Update 2 or later.

Original Answer:

You are running into a known bug/design limitation with Visual Studio 2015 and calling ToString on struct types. This can also be observed when dealing with System.DateTimeSpan. System.DateTimeSpan.ToString() works in the evaluation windows with Visual Studio 2013, but does not always work in 2015.

If you are interested in the low level details, here's what's going on:

To evaluate ToString, the debugger does what's known as "function evaluation". In greatly simplified terms, the debugger suspends all threads in the process except the current thread, changes the context of the current thread to the ToString function, sets a hidden guard breakpoint, then allows the process to continue. When the guard breakpoint is hit, the debugger restores the process to its previous state and the return value of the function is used to populate the window.

To support lambda expressions, we had to completely rewrite the CLR Expression Evaluator in Visual Studio 2015. At a high level, the implementation is:

  1. Roslyn generates MSIL code for expressions/local variables to get the values to be displayed in the various inspection windows.
  2. The debugger interprets the IL to get the result.
  3. If there are any "call" instructions, the debugger executes a function evaluation as described above.
  4. The debugger/roslyn takes this result and formats it into the tree-like view that's shown to the user.

Because of the execution of IL, the debugger is always dealing with a complicated mix of "real" and "fake" values. Real values actually exist in the process being debugged. Fake values only exist in the debugger process. To implement proper struct semantics, the debugger always needs to make a copy of the value when pushing a struct value to the IL stack. The copied value is no longer a "real" value and now only exists in the debugger process. That means if we later need to perform function evaluation of ToString, we can't because the value doesn't exist in the process. To try and get the value we need to emulate execution of the ToString method. While we can emulate some things, there are many limitations. For example, we can't emulate native code and we can't execute calls to "real" delegate values or calls on reflection values.

With all of that in mind, here is what's causing the various behaviors you are seeing:

  1. The debugger isn't evaluating NodaTime.Instant.ToString -> This is because it is struct type and the implementation of ToString can't be emulated by the debugger as described above.
  2. Thread.Sleep seems to take zero time when called by ToString on a struct -> This is because the emulator is executing ToString. Thread.Sleep is a native method, but the emulator is aware of it and just ignores the call. We do this to try and get a value to show to the user. A delay wouldn't be helpful in this case.
  3. DisplayAttibute("ToString()") works. -> That is confusing. The only difference between the implicit calling of ToString and DebuggerDisplay is that any time-outs of the implicit ToString evaluation will disable all implicit ToString evaluations for that type until the next debug session. You may be observing that behavior.

In terms of the design problem/bug, this is something we are planning to address in a future release of Visual Studio.

Hopefully that clears things up. Let me know if you have more questions. :-)

Community
  • 1
  • 1
Patrick Nelson - MSFT
  • 3,182
  • 1
  • 14
  • 13
  • 1
    Any idea how Instant.ToString works if the implementation is just "return a string literal"? It sounds like there are some complexities still unaccounted for :) I'll check that I really can reproduce that behaviour... – Jon Skeet Jul 22 '15 at 17:17
  • 1
    @Jon, I'm not sure what you're asking. The debugger is agnostic of the implementation when doing real function evaluation and it always tries this first. The debugger only cares about the implementation when it needs to emulate the call - Returning a string literal is the most simple case to emulate. – Patrick Nelson - MSFT Jul 22 '15 at 17:38
  • 1
    I'm way over my head, but aren't string literals set somewhere hard coded by the compiler? In which case maybe the debugging engine knows that there is no evaluation to be done, and just grabs the string from wherever it is stored – Mord Zuber Jul 22 '15 at 17:41
  • @PatrickNelson-MSFT: If I replace the implementation of `ToString()` with `return "Hello";` then the debugger shows it. I thought it would be a case of the debugger emulating a call to `ToString()` - if it's actually emulating the *contents* of `ToString()`, I guess that could be different... – Jon Skeet Jul 22 '15 at 17:44
  • 8
    Ideally we want the CLR to execute everything. This provides the most accurate and reliable results. That's why we do real function evaluation for ToString calls. When this isn't possible, we fall back to emulating the call. That means the debugger pretends to be the CLR executing the method. Clearly if the implementation is return "Hello", this is easy to do. If the implementation does a P-Invoke it's more difficult or impossible. – Patrick Nelson - MSFT Jul 22 '15 at 18:01
  • 1
    Hmmm, regarding Thread.Sleep: silly example maybe, but what about something like this- `while (innerResult == null) Thread.Sleep(10); return innerResult.ToString();`. Does the emulator know that Thread.Sleep should not be ignored in that scenario? – tzachs Jul 23 '15 at 18:06
  • 3
    @tzachs, The emulator is completely single threaded. If `innerResult` starts off as null, the loop will never terminate and eventually the evaluation will time out. In fact, evaluations only allow a single thread in the process to run by default, so you'll see the same behavior regardless of if the emulator is used or not. – Patrick Nelson - MSFT Jul 23 '15 at 18:22
  • 2
    BTW, if you know your evaluations require multiple threads, take a look at [Debugger.NotifyOfCrossThreadDependency](https://msdn.microsoft.com/en-us/library/system.diagnostics.debugger.notifyofcrossthreaddependency(v=vs.110).aspx). Calling this method will abort the evaluation with a message stating the evaluation requires all threads to run and the debugger will provide a button the user can push to force the evaluation. The disadvantage is any breakpoints hit on other threads during the evaluation will be ignored. – Patrick Nelson - MSFT Jul 23 '15 at 18:29
  • @PatrickNelson-MSFT Could you please explain what you mean by `"real" delegate values` and `calls on reflection values` mentioned above? Does the latter refer to objects created with Activator.CreateInstance? – Omer Raviv Jul 25 '15 at 05:24
  • 1
    Real values exist in the process being debugged. Fake values do not. For example, if you evaluate something like `F(() => new A()) + b`. The result of `new A()` would be a fake value because the emulator creates it. If "b" is a local variable, it's a real value. Reflection values are objects of types that live in `System.Reflection` and the class `System.Type`. – Patrick Nelson - MSFT Jul 27 '15 at 16:49
  • @PatrickNelson-MSFT, does the code emulation occur in a different instance of the CLR? Or is the emulator purely native? – Ethan Reesor Sep 30 '15 at 18:26
  • 1
    Could the debugger take advantage of the Fact that `NodaTime.Instant` is immutable? – Matt Johnson-Pint Oct 15 '15 at 20:00
  • This issue is going down in VS 2017. I have 15.5.2 – P.Brian.Mackey Feb 20 '18 at 17:06