stacktraces can now show custom runtime msgs per frame #13351

timotheecour · 2020-02-07T13:49:54Z

stacktraces can now show custom runtime msgs per frame.

useful in many cases where the stacktrace alone isn't sufficient to debug an issue; in particular for any parser / compiler (such as nim compiler), showing additional runtime info helps showing tracing program along with traced source code (+ arbitrary computed values)
efficient implementation using a fixed string, so there is no allocation cost (amortized cost = O(1)); the only allocations happen if an exception is thrown; for stackframe entries with a nonempty custom msg, a string will be allocated before unwinding the stack so that the custom msg isn't invalidated by further calls to setFrameMsg

example:

say you want to debug an internal compiler error such as #12263 which normally gives a regular stacktrace error (with --stacktrace:on);

if we simply add the following line inside proc semExpr(...) (obviously setFrameMsg can be called in other places as needed)

when defined(nimCompilerStackraceHints):
  setFrameMsg c.config$n.info & " " & $n.kind

it'll show that context in each stackframe corresponding to that (re-entrant) function, which helps showing the progress in the file being compiled:

stacktrace with custom runtime msgs for nim c /pathto/t1015.nim
shows both tracing and traced programs along side:

compiler/nim.nim(118) nim
compiler/nim.nim(95) handleCmdLine
compiler/cmdlinehelper.nim(105) loadConfigsAndRunMainCommand
compiler/main.nim(190) mainCommand
compiler/main.nim(92) commandCompileToC
compiler/modules.nim(143) compileProject
compiler/modules.nim(84) compileModule
compiler/passes.nim(210) processModule
compiler/passes.nim(86) processTopLevelStmt
compiler/sem.nim(600) myProcess
compiler/sem.nim(568) semStmtAndGenerateGenerics
compiler/semstmts.nim(2240) semStmt
compiler/semexprs.nim(986) semExprNoType
compiler/semexprs.nim(2743) semExpr /pathto/t1015.nim(5, 1) nkStmtList
compiler/semstmts.nim(2180) semStmtList
compiler/semexprs.nim(2670) semExpr /pathto/t1015.nim(35, 1) nkWhenStmt
compiler/semexprs.nim(2256) semWhen
compiler/semexprs.nim(2743) semExpr /pathto/t1015.nim(36, 3) nkStmtList
compiler/semstmts.nim(2180) semStmtList
compiler/semexprs.nim(2746) semExpr /pathto/t1015.nim(50, 3) nkLetSection
compiler/semstmts.nim(450) semVarOrLet
compiler/semexprs.nim(64) semExprWithType
compiler/semexprs.nim(2708) semExpr /pathto/t1015.nim(50, 33) nkBracket
compiler/semexprs.nim(557) semArrayConstr
compiler/semexprs.nim(64) semExprWithType
compiler/semexprs.nim(2654) semExpr /pathto/t1015.nim(51, 10) nkPrefix
compiler/semexprs.nim(2248) semMagic
compiler/semexprs.nim(967) semDirectOp
compiler/semexprs.nim(816) semOverloadedCallAnalyseEffects
compiler/semcall.nim(532) semOverloadedCall
compiler/semcall.nim(335) resolveOverloads
compiler/semcall.nim(93) pickBestCandidate
compiler/sigmatch.nim(2522) matches
compiler/sigmatch.nim(2459) matchesAux
compiler/sigmatch.nim(2261) prepareOperand
compiler/semexprs.nim(49) semOperand
compiler/semexprs.nim(2708) semExpr /pathto/t1015.nim(51, 11) nkBracket
compiler/semexprs.nim(557) semArrayConstr
compiler/semexprs.nim(64) semExprWithType
compiler/semexprs.nim(2704) semExpr /pathto/t1015.nim(52, 7) nkPar
compiler/semexprs.nim(2513) semTupleConstr
compiler/semexprs.nim(2435) semTuplePositionsConstr
compiler/semexprs.nim(64) semExprWithType
compiler/semexprs.nim(2615) semExpr /pathto/t1015.nim(52, 54) nkDotExpr
compiler/semexprs.nim(2645) semExpr /pathto/t1015.nim(52, 54) nkCall
compiler/semexprs.nim(272) semConv
compiler/semcall.nim(444) inferWithMetatype
compiler/sigmatch.nim(2171) paramTypesMatch
compiler/sigmatch.nim(2015) paramTypesMatchAux
compiler/sigmatch.nim(1654) typeRel
compiler/sigmatch.nim(1210) typeRel
compiler/types.nim(815) lengthOrd
compiler/types.nim(776) lastOrd
compiler/msgs.nim(565) internalError
compiler/msgs.nim(443) rawMessage
compiler/msgs.nim(440) rawMessage
compiler/msgs.nim(356) handleError
compiler/msgs.nim(346) quit

unrelated changes

added stackframes.procName

lib/system.nim

Varriount · 2020-02-07T15:56:56Z

This is really slick! I can see this being used in things like backend servers to annotate exceptions when something unexpected happens in a request.

timotheecour · 2020-02-11T15:51:15Z

PTAL @Araq, ready for review

timotheecour · 2020-02-28T02:32:43Z

friendly ping @Araq this really helps for debugging, whether you're debugging compiler or debugging user code, making stacktraces a lot more powerful

Varriount · 2020-02-28T10:24:40Z

Do you know if this would be compatible with talk of using libbacktrace?

timotheecour · 2020-02-28T12:34:57Z

Do you know if this would be compatible with talk of using libbacktrace?

this only works with nim's default backtrace which relies on inserting code at begin/end of each function; this can't work with libbacktrace (which you get with -d:nativeStacktrace), unless you added some lowlevel asm code to emulate what I did in this PR, which doesn't sound easy.

lib/system/exceptions.nim

lib/std/stackframes.nim

timotheecour · 2020-03-06T22:41:20Z

PTAL, all comments addressed, and now test works with or without --gc:arc; I'd really like to have this PR merged as it helps a lot when debugging (whether it's user programs or nim compiler itself);
happy to address any further comments

dom96 · 2020-03-07T00:09:53Z

Cool. Looks like a nice feature, up to Araq or someone else knowledgeable with these internals to review though. :)

timotheecour · 2020-03-19T14:58:36Z

PTAL @Araq

https://gitter.im/nim-lang/Nim?at=5e69663a47b42479253f82f5]

From IRC (bridge bot) @FromIRC Mar 11 15:40
how is 'var frameMsgBuf* {.threadvar.}: string' entirely opt-in?
anyhow, can you make it a 'cstring'? constants are fine and with a little care you can ensure the string is from a buffer that is not freed to early

done, see latest commit; frameMsgBuf is now a CstringWrapper which wraps a string-like interface on a c_realloc-allocated growable cstring buffer

timotheecour · 2020-03-20T04:28:50Z

~~this is blocked by #13701 which should be merged first;~~ EDIT: got merged

timotheecour · 2020-03-24T05:17:50Z

friendly ping @Araq

Araq · 2020-03-24T11:07:53Z

Sorry, I was unclear. Can the frameMsg*: string field be a cstring?

timotheecour · 2020-03-24T11:33:05Z

I don't see how that'd work, please explain; the problem with frameMsg: cstring (that would point to some offset in frameMsgBuf) is when you unwind AND you run some other code that could overwrite what frameMsg points to:

proc fun()=setFrameMsg("foo")
try:
  fun()
except Exception as e:
  printf("%s\n", e.frameMsg) # that should be safe even though stack was unwinded
  bar() # this could overwrite what `e.frameMsg` points to, potentially
  printf("%s\n", e.frameMsg) # now we are reading the wrong thing

unless what you mean is for frameMsg to have its own memory (malloc-managed like it did via CstringWrapper, excpect i now also need to care about deallocation), but I really don't see the advantage over string in that case.

note

how about I hide this behind --stacktrace:annotate flag instead?
so it becomes entirely opt-in.

Araq · 2020-03-24T17:49:09Z

how about I hide this behind --stacktrace:annotate flag instead?

Ok.

timotheecour · 2020-03-25T01:44:42Z

done, PTAL

It's now off by default; future PR's may change the default after gather more usage
added tests with --stacktraceMsgs:on/off

timotheecour · 2020-03-30T12:04:44Z

note:
you can use this in your user config:

when defined nimHasStacktraceMsgs: switch("stacktraceMsgs", "on")

which is backward compatible

timotheecour force-pushed the pr_stacktrace_metadata branch from 79f8b88 to e973254 Compare February 7, 2020 13:52

timotheecour changed the title ~~[WIP] stacktraces can now show custom runtime msgs~~ [WIP] stacktraces can now show custom runtime msgs per frame Feb 7, 2020

Clyybber reviewed Feb 7, 2020

View reviewed changes

lib/system.nim Outdated Show resolved Hide resolved

timotheecour force-pushed the pr_stacktrace_metadata branch 3 times, most recently from 6e29493 to 577e95e Compare February 7, 2020 23:42

timotheecour closed this Feb 8, 2020

timotheecour reopened this Feb 8, 2020

timotheecour closed this Feb 8, 2020

timotheecour reopened this Feb 8, 2020

timotheecour closed this Feb 8, 2020

timotheecour reopened this Feb 8, 2020

timotheecour changed the title ~~[WIP] stacktraces can now show custom runtime msgs per frame~~ stacktraces can now show custom runtime msgs per frame Feb 8, 2020

timotheecour marked this pull request as ready for review February 8, 2020 01:58

Araq reviewed Mar 3, 2020

View reviewed changes

lib/system/exceptions.nim Show resolved Hide resolved

Araq reviewed Mar 3, 2020

View reviewed changes

lib/std/stackframes.nim Show resolved Hide resolved

timotheecour mentioned this pull request Mar 4, 2020

combine nim classic stacktrace with C++ backtraces to get full backtrace + other TODO's regarding nimStackTraceOverride timotheecour/Nim#49

Open

5 tasks

timotheecour force-pushed the pr_stacktrace_metadata branch from 577e95e to 0ea91b7 Compare March 6, 2020 22:38

timotheecour force-pushed the pr_stacktrace_metadata branch from 0ea91b7 to 4a6b786 Compare March 19, 2020 14:56

timotheecour mentioned this pull request Mar 20, 2020

fix #13538 sigmatch errors are now sorted #13701

Merged

timotheecour force-pushed the pr_stacktrace_metadata branch from 4a6b786 to 114b91e Compare March 22, 2020 10:02

timotheecour closed this Mar 22, 2020

timotheecour reopened this Mar 22, 2020

timotheecour added 6 commits March 24, 2020 18:39

stacktraces can now show custom runtime msgs

1e85eb0

fixups

ff04e29

improve tests/stdlib/tstackframes.nim

05b1ef4

fix test for --gc:arc

9f7963b

control via --stackTraceMsgs

3e338f6

changelog

350d6f4

timotheecour force-pushed the pr_stacktrace_metadata branch from 114b91e to 350d6f4 Compare March 25, 2020 01:44

timotheecour added 5 commits March 24, 2020 19:08

_

4ee1d51

test --stacktraceMsgs:on and --stacktraceMsgs:off

22fcc68

--stacktracemsgs:off by default

2539955

fix test

1dd219f

fixup

55ac485

Araq merged commit 19cab9f into nim-lang:devel Mar 30, 2020

timotheecour deleted the pr_stacktrace_metadata branch March 31, 2020 00:28

timotheecour mentioned this pull request Apr 7, 2020

"distinct uint64" type corruption on 32-bit, when using {.borrow.} operators #13902

Closed

timotheecour mentioned this pull request Nov 17, 2020

myfuns[runtimeIndex]() gives FieldError when myfuns is a CT array of closures #14340

Closed

timotheecour mentioned this pull request Dec 19, 2020

use -d:nimCompilerStackraceHints in more places #16400

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

stacktraces can now show custom runtime msgs per frame #13351

stacktraces can now show custom runtime msgs per frame #13351

timotheecour commented Feb 7, 2020 •

edited

Loading

Varriount commented Feb 7, 2020

timotheecour commented Feb 11, 2020

timotheecour commented Feb 28, 2020

Varriount commented Feb 28, 2020

timotheecour commented Feb 28, 2020 •

edited

Loading

timotheecour commented Mar 6, 2020 •

edited

Loading

dom96 commented Mar 7, 2020

timotheecour commented Mar 19, 2020 •

edited

Loading

timotheecour commented Mar 20, 2020 •

edited

Loading

timotheecour commented Mar 24, 2020

Araq commented Mar 24, 2020

timotheecour commented Mar 24, 2020

Araq commented Mar 24, 2020

timotheecour commented Mar 25, 2020 •

edited

Loading

timotheecour commented Mar 30, 2020

stacktraces can now show custom runtime msgs per frame #13351

stacktraces can now show custom runtime msgs per frame #13351

Conversation

timotheecour commented Feb 7, 2020 • edited Loading

example:

unrelated changes

Varriount commented Feb 7, 2020

timotheecour commented Feb 11, 2020

timotheecour commented Feb 28, 2020

Varriount commented Feb 28, 2020

timotheecour commented Feb 28, 2020 • edited Loading

timotheecour commented Mar 6, 2020 • edited Loading

dom96 commented Mar 7, 2020

timotheecour commented Mar 19, 2020 • edited Loading

timotheecour commented Mar 20, 2020 • edited Loading

timotheecour commented Mar 24, 2020

Araq commented Mar 24, 2020

timotheecour commented Mar 24, 2020

note

Araq commented Mar 24, 2020

timotheecour commented Mar 25, 2020 • edited Loading

timotheecour commented Mar 30, 2020

timotheecour commented Feb 7, 2020 •

edited

Loading

timotheecour commented Feb 28, 2020 •

edited

Loading

timotheecour commented Mar 6, 2020 •

edited

Loading

timotheecour commented Mar 19, 2020 •

edited

Loading

timotheecour commented Mar 20, 2020 •

edited

Loading

timotheecour commented Mar 25, 2020 •

edited

Loading