Add more information when assertion fails in `RoxorVM::pop_current_exception` #54

Merged
merged 2 commits into from Apr 2, 2012

Conversation

Projects
None yet
2 participants
@msabramo
Contributor

msabramo commented Feb 2, 2012

Add more information when assertion ((size_t)pos < current_exceptions.size()) fails in RoxorVM::pop_current_exception

Fixes https://www.macruby.org/trac/ticket/1446

@msabramo

This comment has been minimized.

Show comment Hide comment
@msabramo

msabramo Feb 2, 2012

Contributor

Sample output for an actual crash:

RoxorVM::pop_current_exception (vm.cpp:3607) - Warning: Assertion about to fail: ((size_t)pos < current_exceptions.size()); pos = 1; current_exceptions.size() = 1
current_exceptions[1]: "#<NoMethodError: undefined method `[]' for nil:NilClass>"
Assertion failed: ((size_t)pos < current_exceptions.size()), function pop_current_exception, file vm.cpp, line 3616.
Contributor

msabramo commented Feb 2, 2012

Sample output for an actual crash:

RoxorVM::pop_current_exception (vm.cpp:3607) - Warning: Assertion about to fail: ((size_t)pos < current_exceptions.size()); pos = 1; current_exceptions.size() = 1
current_exceptions[1]: "#<NoMethodError: undefined method `[]' for nil:NilClass>"
Assertion failed: ((size_t)pos < current_exceptions.size()), function pop_current_exception, file vm.cpp, line 3616.
@jballanc

This comment has been minimized.

Show comment Hide comment
@jballanc

jballanc Feb 3, 2012

Owner

This seems more like debugging information than something we would want in final code. If the assertion is failing, then it's a bug we should fix.

If you look at the top of vm.cpp, you'll see that we already have a number of debugging defines. Perhaps you could wrap this code in an #if block using one of these?

Owner

jballanc commented Feb 3, 2012

This seems more like debugging information than something we would want in final code. If the assertion is failing, then it's a bug we should fix.

If you look at the top of vm.cpp, you'll see that we already have a number of debugging defines. Perhaps you could wrap this code in an #if block using one of these?

@msabramo

This comment has been minimized.

Show comment Hide comment
@msabramo

msabramo Feb 7, 2012

Contributor

@jballanc OK, I added some #ifs; hope that's useful.

Contributor

msabramo commented Feb 7, 2012

@jballanc OK, I added some #ifs; hope that's useful.

@jballanc

This comment has been minimized.

Show comment Hide comment
@jballanc

jballanc Feb 8, 2012

Owner

Starting to look good! Just a couple points:

  • You should leave the #define to 0 for the pull request. Anyone interested in doing debugging can change these locally when they compile
  • You still have two printfs that are outside the #if guard. Is there a reason these should normally be compiled in?
  • The diff seems a bit...chatty (just my personal opinion). I get that you want to have a trail of when exceptions are pushed/poped to try and understand why our assertions are failing, and I think this could be really useful. I just wonder if copious logging is the best way.

My recommendation would be to try and narrow down the number of places that you need to modify for logging. For example, you are constantly logging after RoxorVM::current_exception. Why not put the logging inside that method instead?

If you're feeling really ambitious, what would be really really useful would be to have the ability to log everything about an exception in a structured manner. You can look at MallocStackLogging (some info here) for inspiration. That way, we could build tools around the info... but that's just my crazy idea. For now, I think what you have is a good start.

Owner

jballanc commented Feb 8, 2012

Starting to look good! Just a couple points:

  • You should leave the #define to 0 for the pull request. Anyone interested in doing debugging can change these locally when they compile
  • You still have two printfs that are outside the #if guard. Is there a reason these should normally be compiled in?
  • The diff seems a bit...chatty (just my personal opinion). I get that you want to have a trail of when exceptions are pushed/poped to try and understand why our assertions are failing, and I think this could be really useful. I just wonder if copious logging is the best way.

My recommendation would be to try and narrow down the number of places that you need to modify for logging. For example, you are constantly logging after RoxorVM::current_exception. Why not put the logging inside that method instead?

If you're feeling really ambitious, what would be really really useful would be to have the ability to log everything about an exception in a structured manner. You can look at MallocStackLogging (some info here) for inspiration. That way, we could build tools around the info... but that's just my crazy idea. For now, I think what you have is a good start.

@jballanc jballanc closed this Feb 8, 2012

@jballanc jballanc reopened this Feb 8, 2012

@jballanc

This comment has been minimized.

Show comment Hide comment
@jballanc

jballanc Feb 8, 2012

Owner

(sorry...clicked the wrong button...)

Owner

jballanc commented Feb 8, 2012

(sorry...clicked the wrong button...)

@msabramo

This comment has been minimized.

Show comment Hide comment
@msabramo

msabramo Feb 20, 2012

Contributor

@jballanc OK, I switched the #defines off and got rid of one of the printfs in compiler.cpp. I did play a bit with putting the logging in RoxorVM::current_exception, but I didn't commit it for now, as it the output is not as useful for debugging, because it tells you the __FILE__ and __LINE__ of the code in vm.h instead of the relevant line in vm.cpp which seems more useful.

I agree with you that sprinkling the code with printfs is pretty ugly and probably not the best way to debug. Along the lines of your suggestion of having structured exception logging, I wonder if DTrace could be leveraged more effectively for this sort of debugging. Here's a start:

$ sudo dtrace -n ':*ruby*::raise { printf("%s", copyinstr(arg0)) }' -c 'macruby -e nil[]'                           
dtrace: description ':*ruby*::raise ' matched 3 probes
-e:1:in `[]': undefined method `[]' for nil:NilClass (NoMethodError)
dtrace: pid 71519 has exited
CPU     ID                    FUNCTION:NAME
  0 119858           _ZL10__vm_raisev:raise NoMethodError
Contributor

msabramo commented Feb 20, 2012

@jballanc OK, I switched the #defines off and got rid of one of the printfs in compiler.cpp. I did play a bit with putting the logging in RoxorVM::current_exception, but I didn't commit it for now, as it the output is not as useful for debugging, because it tells you the __FILE__ and __LINE__ of the code in vm.h instead of the relevant line in vm.cpp which seems more useful.

I agree with you that sprinkling the code with printfs is pretty ugly and probably not the best way to debug. Along the lines of your suggestion of having structured exception logging, I wonder if DTrace could be leveraged more effectively for this sort of debugging. Here's a start:

$ sudo dtrace -n ':*ruby*::raise { printf("%s", copyinstr(arg0)) }' -c 'macruby -e nil[]'                           
dtrace: description ':*ruby*::raise ' matched 3 probes
-e:1:in `[]': undefined method `[]' for nil:NilClass (NoMethodError)
dtrace: pid 71519 has exited
CPU     ID                    FUNCTION:NAME
  0 119858           _ZL10__vm_raisev:raise NoMethodError
@msabramo

This comment has been minimized.

Show comment Hide comment
@msabramo

msabramo Feb 26, 2012

Contributor

ping

Contributor

msabramo commented Feb 26, 2012

ping

@jballanc

This comment has been minimized.

Show comment Hide comment
@jballanc

jballanc Mar 1, 2012

Owner

Looking good...give me to the weekend to play with this in some depth...

Owner

jballanc commented Mar 1, 2012

Looking good...give me to the weekend to play with this in some depth...

@msabramo

This comment has been minimized.

Show comment Hide comment
@msabramo

msabramo Apr 1, 2012

Contributor

Bump

Contributor

msabramo commented Apr 1, 2012

Bump

jballanc added a commit that referenced this pull request Apr 2, 2012

Merge pull request #54 from msabramo/issue_1446
Add more information when assertion fails in `RoxorVM::pop_current_exception`

@jballanc jballanc merged commit ca3efd0 into MacRuby:master Apr 2, 2012

@jballanc

This comment has been minimized.

Show comment Hide comment
@jballanc

jballanc Apr 2, 2012

Owner

Hmm...that was a rather long weekend ;)

Looks good! Branch passes spec:language and spec:library, and I really like the added exception logging.

Thanks for the hard work!

Owner

jballanc commented Apr 2, 2012

Hmm...that was a rather long weekend ;)

Looks good! Branch passes spec:language and spec:library, and I really like the added exception logging.

Thanks for the hard work!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment