9 ms·

Show HN: Dlg – Zero-cost printf-style debugging for Go

64 points by 0xFEE1DEAD 1y ago

Hey HN, I tend to use printf-style debugging as my primary troubleshooting method and only resort to gdb as a last resort. While I like its ease of use printf debugging isn't without its annoyances, namely removing the print statements once you're done. I used to use trace-level logging from proper logging libraries but adding trace calls in every corner quickly gets out of control and results in an overwhelming amount of output. To scratch my own itch I created dlg - a minimal debugging library that disappears completely from production builds. Its API exposes just a single function, Printf [1]. dlg is optimized for performance in debug builds and, most importantly, when compiled without the dlg build tag, all calls are eliminated by the Go linker as if dlg was never imported. For debug builds it adds optional stack trace generation configurable via environment variables or linker flags. GitHub: https://github.com/vvvvv/dlg https://github.com/vvvvv/dlg Any feedback is much appreciated. [1]: Actually two functions - there's also SetOutput.

kitd 1y ago
Very cool! Just one thought: I don't think your stack traces need to include the lines inside Printf itself and it adds to the noise a bit. Maybe just go up to the line where the call to Printf is made?
- 0xFEE1DEAD 1y ago
  Thank you! You're absolutely right, it annoys me as well. It's a bit finicky to do so, but I'm currently in an exploratory phase of providing an even more fine grained stack tracing feature and filtering out dlg itself is definitly on my todo list.
smcameron 1y ago
> printf debugging isn't without its annoyances, namely removing the print statements once you're done. Use something like stacked git[1], and then it's just one "stg pop" and poof, they're gone. [1] https://stacked-git.github.io/ https://stacked-git.github.io/
- BobbyTables2 1y ago
  I’ve been doing this (manually) for about 10+ years. I rarely use branches, my local work area is about 50-100 commits on top of master. I pick/reorder/edit with “git rebase -i” I’ll prefix the commit summary with a word that helps me keep straight debug changes from ones that will go toward a MR.
- shayief 1y ago
  I usually leave them as uncommitted changes, then git checkout to undo them. And using something like `git add -p` to skip Printfs if I need to commit other changes.
sethammons 1y ago
In extreme processing needs, I suppose the elimination of a check that would happen with a level logger is a solid trade off. My favored approach is a context aware level logger with structured logs going to an aggregator like Splunk. Because it is context aware, custom filtering logic is available in a middleware.
- jerf 1y ago
  See the standard library "slog" package: https://pkg.go.dev/log/slog https://pkg.go.dev/log/slog Which is a relatively recent addition to the Go standard library, based on the collective experience with logging over the years. Compare with the original log standard library: https://pkg.go.dev/log https://pkg.go.dev/log and you can see the changes in even just the time since Go was developed in logging best practices. Slog, once you understand the interfaces involved in stuff, has performed most every trick I could desire, up to and including things like subloggers with their own priorities for outputs that override the global settings. I'd like to see some slog integration in this package, though I say that without a design in mind. As it stands, this is exactly what it says on the tin; debugging-only output that you fully intend to just disappear out of the production binary. The trick it uses is a fairly straightforward use of Go's tag-based compilation features, which I do not mean as a criticism, but to point out that any Go programmer who likes the looks of this but wants to adapt it to their own task will find it easy to simply take the technique directly and adapt it in not very many lines of code.
negrel 1y ago
Cool lib! I took the same approach for my zero cost debugging assertion Go library https://github.com/negrel/assert https://github.com/negrel/assert
mdaniel 1y ago
How does the dead code elimination work when using args to Printf? If static strings are fed into an empty function, I can imagine it does nothing. However, this I have less of a firm grip upon dlg.Printf("the thing.Something is %+v", thing.Something()) since surely golang will still call Something, and still call Printf And don't misunderstand me: it's a grave pet peeve of mine to do action inside the args to Printf but I can tell you it's a very common [anti-]pattern so I'd presume your users will want a story for how that interacts with the "disappears completely" claim
- llimllib 1y ago
  It's easy to show that you're right and that code isn't dead so it can't be eliminated: package main import ( "fmt" "github.com/vvvvv/dlg" ) func risky() error { _, err := fmt.Printf("unexpected error\n") return err } func main() { dlg.Printf("something failed: %s", risky()) risky() } prints "unexpected error" twice
  - deleted 1y ago
    [deleted]
- exasperaited 1y ago
  This is a thing I had a little "are you sure?" itch in my brain about, but you've expressed so clearly in four lines of comment, and this is me showing gratitude for the comment and the untangling of my brain. ETA: Presumably if there was at least an option for passing a closure that would provide a way to address this? Since the closure will only uselessly compile, and not actually uselessly run?
- 0xFEE1DEAD 1y ago
  In short: You're right - Go will still evaluate argument expressions. In hindsight, I should've made that more obvious, not calling this out initially was an expert blind spot on my part, not an intent to mislead. If we consider this example: func risky() error { return fmt.Errorf("unexpected error") } func risky2() error{ return fmt.Errorf("also an error") } func main() { fmt.Printf("something failed: %v", risky()) dlg.Printf("something failed: %v", risky2()) } And look at the disassembly: 0x10009f354 d503201f NOOP ; Dead code of dlg.Printf 0x10009f358 b0000000 ADRP 4096(PC), R0 ; Load "also an error" string address 0x10009f35c 9124ec00 ADD $2363, R0, R0 ; Calculate exact string address 0x10009f360 d28001a1 MOVD $13, R1 ; Set string length=13 (R1) 0x10009f364 aa1f03e2 MOVD ZR, R2 ; Clear R2 0x10009f368 aa1f03e3 MOVD ZR, R3 ; Clear R3 0x10009f36c aa0303e4 MOVD R3, R4 ; Clear R4 0x10009f370 97ffd890 CALL fmt.Errorf(SB) ; Call fmt.Errorf What disappears is the logging work (formatting, interface/slice plumbing, I/O) and the call itself. Go cannot eliminate calls to functions inside of Printf because they could produce side-effects. Eliminating functions calls like this would be very expensive to do and would clashes with Go's focus on fast compilation times. I'll add a section to the README that explains this. Thanks for pointing it out.
deleted 1y ago
[deleted]
sigmonsays 1y ago
it doesn't appear to truly be zero cost if you log variables that can't be eliminated. The only way (I believe) to implement zero cost is some type of macro system which go does not support.
- lanstin 1y ago
  Yeah I want a log package where the log statements that don't log also don't have their arguments evaluated. Half of my gc pressure is little strings created to call the log package that don't get logged.
  - 9rx 1y ago
    So what you want is slog, found in the standard library? The doc.go file found in the package even goes into detail about what you (seem to) describe and how it avoids that problem.
    - badc0ffee 1y ago
      A link to doc.go, for the lazy: https://cs.opensource.google/go/x/exp/+/645b1fa8:slog/doc.go;l=263 https://cs.opensource.google/go/x/exp/+/645b1fa8:slog/doc.go... Basically it says to pass in objects, not prepared strings, so the formatted output is only computed if the message is actually logged. That object can be a struct implementing the LogValuer interface to do any required work/produce formatted output.
      - lanstin 1y ago
        Oh cool, I hadn't run into LogValuer, that's cool. And passing pointers to strings rather than strings, hmmm.
        9rx 1y ago
        > And passing pointers to strings rather than strings, hmmm. Are you referring to the "URL" example? That isn't a case of passing pointers to strings, that is passing a URL (fmt.Stringer) where the String method has a pointer receiver. To demonstrate why the pointer would be needed in that case, consider: type URL struct{} func (*URL) String() string { return "https://..." } func print(v any) { fmt.Println(v.(fmt.Stringer).String()) } func main() { print(&URL{}) // ok print(URL{}) // panic }
latchkey 1y ago
I'm curious why you prefer this over writing tests.
- 0xFEE1DEAD 1y ago
  I do write tests but I'm not a fan of aiming for 100% coverage because it's incredibly tedious to achieve, and the gains in my experience are marginal. That being said even with 100% coverage your code may still contain bugs. If you've never had to debug code with extensive tests then hats off to you.
  - 9rx 1y ago
    When you write a test you see the cute little "debug test" button show up beside it in your editor. If you press it, your logpoints spill the logging information you seek without having to modify the code. I expect that is what the parent is really asking about: What does this meaningfully offer over the "built-in" debug logging?
    - 0xFEE1DEAD 1y ago
      Well, my vim is missing buttons like these and I wasn't aware such a feature existed. Maybe I'm just old, maybe it's just a different approach, but I built dlg for myself because it fits my workflow. > What does this meaningfully offer over the "built-in" debug logging? For you, it most likely doesn't offer anything meaningful. For devs who use fmt.Printf a lot, it maybe does.
      - latchkey 1y ago
        I'm 52 and coding since I was about 10 years old, so I'm not sure age is the right thing to go off.
  - latchkey 1y ago
    Crazy that I get downvoted for a perfectly valid question, go HN! I'm not saying that tests are perfect, but if you do find a bug, you write a new test and fix it. You don't add print statements that you expect to keep around any longer than the amount of effort there is to write the test and fix the code. Maybe this product is for people who don't write tests, but even in this codebase, there is a pretty well done set of tests and zero dogfood usage that I noticed.
0points 1y ago
> Any feedback is much appreciated. There is way too much going on in this code whose feature essentially boils down to func Printf(f string, v ...any) { if CONDITION { fmt.Printf(f, v...) } } Writing a stack trace is fully unrelated to Printf(), and should be separated.

64 points by 0xFEE1DEAD 1y ago

kitd 1y ago

Very cool! Just one thought: I don't think your stack traces need to include the lines inside Printf itself and it adds to the noise a bit. Maybe just go up to the line where the call to Printf is made?

0xFEE1DEAD 1y ago
Thank you! You're absolutely right, it annoys me as well. It's a bit finicky to do so, but I'm currently in an exploratory phase of providing an even more fine grained stack tracing feature and filtering out dlg itself is definitly on my todo list.

smcameron 1y ago

> printf debugging isn't without its annoyances, namely removing the print statements once you're done. Use something like stacked git[1], and then it's just one "stg pop" and poof, they're gone. [1] https://stacked-git.github.io/ https://stacked-git.github.io/

BobbyTables2 1y ago
I’ve been doing this (manually) for about 10+ years. I rarely use branches, my local work area is about 50-100 commits on top of master. I pick/reorder/edit with “git rebase -i” I’ll prefix the commit summary with a word that helps me keep straight debug changes from ones that will go toward a MR.
shayief 1y ago
I usually leave them as uncommitted changes, then git checkout to undo them. And using something like `git add -p` to skip Printfs if I need to commit other changes.

sethammons 1y ago

In extreme processing needs, I suppose the elimination of a check that would happen with a level logger is a solid trade off. My favored approach is a context aware level logger with structured logs going to an aggregator like Splunk. Because it is context aware, custom filtering logic is available in a middleware.

jerf 1y ago
See the standard library "slog" package: https://pkg.go.dev/log/slog https://pkg.go.dev/log/slog Which is a relatively recent addition to the Go standard library, based on the collective experience with logging over the years. Compare with the original log standard library: https://pkg.go.dev/log https://pkg.go.dev/log and you can see the changes in even just the time since Go was developed in logging best practices. Slog, once you understand the interfaces involved in stuff, has performed most every trick I could desire, up to and including things like subloggers with their own priorities for outputs that override the global settings. I'd like to see some slog integration in this package, though I say that without a design in mind. As it stands, this is exactly what it says on the tin; debugging-only output that you fully intend to just disappear out of the production binary. The trick it uses is a fairly straightforward use of Go's tag-based compilation features, which I do not mean as a criticism, but to point out that any Go programmer who likes the looks of this but wants to adapt it to their own task will find it easy to simply take the technique directly and adapt it in not very many lines of code.

negrel 1y ago

Cool lib! I took the same approach for my zero cost debugging assertion Go library https://github.com/negrel/assert https://github.com/negrel/assert

mdaniel 1y ago

How does the dead code elimination work when using args to Printf? If static strings are fed into an empty function, I can imagine it does nothing. However, this I have less of a firm grip upon dlg.Printf("the thing.Something is %+v", thing.Something()) since surely golang will still call Something, and still call Printf And don't misunderstand me: it's a grave pet peeve of mine to do action inside the args to Printf but I can tell you it's a very common [anti-]pattern so I'd presume your users will want a story for how that interacts with the "disappears completely" claim

llimllib 1y ago
It's easy to show that you're right and that code isn't dead so it can't be eliminated: package main import ( "fmt" "github.com/vvvvv/dlg" ) func risky() error { _, err := fmt.Printf("unexpected error\n") return err } func main() { dlg.Printf("something failed: %s", risky()) risky() } prints "unexpected error" twice
- deleted 1y ago
  [deleted]
exasperaited 1y ago
This is a thing I had a little "are you sure?" itch in my brain about, but you've expressed so clearly in four lines of comment, and this is me showing gratitude for the comment and the untangling of my brain. ETA: Presumably if there was at least an option for passing a closure that would provide a way to address this? Since the closure will only uselessly compile, and not actually uselessly run?
0xFEE1DEAD 1y ago
In short: You're right - Go will still evaluate argument expressions. In hindsight, I should've made that more obvious, not calling this out initially was an expert blind spot on my part, not an intent to mislead. If we consider this example: func risky() error { return fmt.Errorf("unexpected error") } func risky2() error{ return fmt.Errorf("also an error") } func main() { fmt.Printf("something failed: %v", risky()) dlg.Printf("something failed: %v", risky2()) } And look at the disassembly: 0x10009f354 d503201f NOOP ; Dead code of dlg.Printf 0x10009f358 b0000000 ADRP 4096(PC), R0 ; Load "also an error" string address 0x10009f35c 9124ec00 ADD $2363, R0, R0 ; Calculate exact string address 0x10009f360 d28001a1 MOVD $13, R1 ; Set string length=13 (R1) 0x10009f364 aa1f03e2 MOVD ZR, R2 ; Clear R2 0x10009f368 aa1f03e3 MOVD ZR, R3 ; Clear R3 0x10009f36c aa0303e4 MOVD R3, R4 ; Clear R4 0x10009f370 97ffd890 CALL fmt.Errorf(SB) ; Call fmt.Errorf What disappears is the logging work (formatting, interface/slice plumbing, I/O) and the call itself. Go cannot eliminate calls to functions inside of Printf because they could produce side-effects. Eliminating functions calls like this would be very expensive to do and would clashes with Go's focus on fast compilation times. I'll add a section to the README that explains this. Thanks for pointing it out.

deleted 1y ago

[deleted]

sigmonsays 1y ago

it doesn't appear to truly be zero cost if you log variables that can't be eliminated. The only way (I believe) to implement zero cost is some type of macro system which go does not support.

lanstin 1y ago
Yeah I want a log package where the log statements that don't log also don't have their arguments evaluated. Half of my gc pressure is little strings created to call the log package that don't get logged.
- 9rx 1y ago
  So what you want is slog, found in the standard library? The doc.go file found in the package even goes into detail about what you (seem to) describe and how it avoids that problem.
  - badc0ffee 1y ago
    A link to doc.go, for the lazy: https://cs.opensource.google/go/x/exp/+/645b1fa8:slog/doc.go;l=263 https://cs.opensource.google/go/x/exp/+/645b1fa8:slog/doc.go... Basically it says to pass in objects, not prepared strings, so the formatted output is only computed if the message is actually logged. That object can be a struct implementing the LogValuer interface to do any required work/produce formatted output.
    - lanstin 1y ago
      Oh cool, I hadn't run into LogValuer, that's cool. And passing pointers to strings rather than strings, hmmm.
      - 9rx 1y ago
        > And passing pointers to strings rather than strings, hmmm. Are you referring to the "URL" example? That isn't a case of passing pointers to strings, that is passing a URL (fmt.Stringer) where the String method has a pointer receiver. To demonstrate why the pointer would be needed in that case, consider: type URL struct{} func (*URL) String() string { return "https://..." } func print(v any) { fmt.Println(v.(fmt.Stringer).String()) } func main() { print(&URL{}) // ok print(URL{}) // panic }

latchkey 1y ago

I'm curious why you prefer this over writing tests.

0xFEE1DEAD 1y ago
I do write tests but I'm not a fan of aiming for 100% coverage because it's incredibly tedious to achieve, and the gains in my experience are marginal. That being said even with 100% coverage your code may still contain bugs. If you've never had to debug code with extensive tests then hats off to you.
- 9rx 1y ago
  When you write a test you see the cute little "debug test" button show up beside it in your editor. If you press it, your logpoints spill the logging information you seek without having to modify the code. I expect that is what the parent is really asking about: What does this meaningfully offer over the "built-in" debug logging?
  - 0xFEE1DEAD 1y ago
    Well, my vim is missing buttons like these and I wasn't aware such a feature existed. Maybe I'm just old, maybe it's just a different approach, but I built dlg for myself because it fits my workflow. > What does this meaningfully offer over the "built-in" debug logging? For you, it most likely doesn't offer anything meaningful. For devs who use fmt.Printf a lot, it maybe does.
    - latchkey 1y ago
      I'm 52 and coding since I was about 10 years old, so I'm not sure age is the right thing to go off.
- latchkey 1y ago
  Crazy that I get downvoted for a perfectly valid question, go HN! I'm not saying that tests are perfect, but if you do find a bug, you write a new test and fix it. You don't add print statements that you expect to keep around any longer than the amount of effort there is to write the test and fix the code. Maybe this product is for people who don't write tests, but even in this codebase, there is a pretty well done set of tests and zero dogfood usage that I noticed.

0points 1y ago

> Any feedback is much appreciated. There is way too much going on in this code whose feature essentially boils down to func Printf(f string, v ...any) { if CONDITION { fmt.Printf(f, v...) } } Writing a stack trace is fully unrelated to Printf(), and should be separated.