Skip to content

Commit

Permalink
Switch gdebug to log/slog
Browse files Browse the repository at this point in the history
  • Loading branch information
diamondburned committed Nov 3, 2024
1 parent 2bdce31 commit f5d8467
Show file tree
Hide file tree
Showing 4 changed files with 142 additions and 94 deletions.
41 changes: 27 additions & 14 deletions pkg/core/gdebug/gdebug.go
Original file line number Diff line number Diff line change
@@ -1,48 +1,61 @@
package gdebug

import (
"context"
"fmt"
"io"
"log"
"log/slog"
"os"
"slices"
"strings"
)

var debug = strings.Split(os.Getenv("GOTK4_DEBUG"), ",")

func HasKey(key string) bool {
for _, k := range debug {
if k == key {
return true
}
}
return false
return slices.Contains(debug, key) || slices.Contains(debug, "all")
}

func NewDebugLogger(key string) *log.Logger {
func NewDebugLogger(key string) *slog.Logger {
if !HasKey(key) {
return log.New(io.Discard, "", 0)
return slog.New(noopLogHandler{})
}
return mustDebugLogger(key)
}

func NewDebugLoggerNullable(key string) *log.Logger {
func NewDebugLoggerNullable(key string) *slog.Logger {
if !HasKey(key) {
return nil
}
return mustDebugLogger(key)
}

func mustDebugLogger(name string) *log.Logger {
func mustDebugLogger(name string) *slog.Logger {
if HasKey("to-console") {
return log.Default()
return slog.With("gotk4_module", name)
}

f, err := os.CreateTemp(os.TempDir(), fmt.Sprintf("gotk4-%s-%d-*", name, os.Getpid()))
if err != nil {
log.Panicln("cannot create temp", name, "file:", err)
}

log.Println("gotk4: intern: enabled debug file at", f.Name())
return log.New(f, "", log.LstdFlags)
slog.Info(
"gotk4: intern: enabled debug file",
"file", f.Name())

return slog.New(
slog.NewTextHandler(f, &slog.HandlerOptions{
Level: slog.LevelDebug,
}),
)
}

type noopLogHandler struct{}

var _ slog.Handler = noopLogHandler{}

func (noopLogHandler) Enabled(context.Context, slog.Level) bool { return false }
func (noopLogHandler) Handle(context.Context, slog.Record) error { return nil }
func (noopLogHandler) WithAttrs([]slog.Attr) slog.Handler { return noopLogHandler{} }
func (noopLogHandler) WithGroup(string) slog.Handler { return noopLogHandler{} }
23 changes: 16 additions & 7 deletions pkg/core/gioutil/listmodel.c
Original file line number Diff line number Diff line change
@@ -1,3 +1,6 @@
#define G_LOG_USE_STRUCTURED
#define G_LOG_DOMAIN "Gotk4GboxObject"

#include "listmodel.h"

#define GDK_ARRAY_ELEMENT_TYPE Gotk4GboxObject *
Expand All @@ -20,8 +23,7 @@ static void gotk4_gbox_object_finalize(GObject *object) {

g_warn_if_fail(self->id != 0);
callbackDelete(self->id);
g_log_structured("Gotk4GboxObject", G_LOG_LEVEL_DEBUG, //
"MESSAGE", "Freed gbox object %d in gotk4_gbox_object_finalize", self->id);
g_debug("Freed gbox object %p in gotk4_gbox_object_finalize", (void *)self->id);

G_OBJECT_CLASS(gotk4_gbox_object_parent_class)->finalize(object);
}
Expand All @@ -34,6 +36,7 @@ static void gotk4_gbox_object_class_init(Gotk4GboxObjectClass *klass) {
Gotk4GboxObject *gotk4_gbox_object_new(guintptr id) {
Gotk4GboxObject *self = g_object_new(GOTK4_TYPE_GBOX_OBJECT, NULL);
self->id = id;
g_debug("Created gbox object %p in gotk4_gbox_object_new", (void *)id);
return self;
}

Expand All @@ -60,7 +63,15 @@ static gpointer gotk4_gbox_list_get_item(GListModel *list, guint index) {
if (index >= objects_get_size(&self->items)) {
return NULL;
}
return g_object_ref(objects_get(&self->items, index));

Gotk4GboxObject *item = objects_get(&self->items, index);
guint old_ref_count = item->parent_instance.ref_count;
item = g_object_ref(item);

g_debug("Adding new reference onto object %p, ref=%d->%d", (void *)item->id, old_ref_count,
item->parent_instance.ref_count);

return item;
}

static void gotk4_gbox_list_list_model_init(GListModelInterface *iface) {
Expand Down Expand Up @@ -105,8 +116,7 @@ void gotk4_gbox_list_splice(Gotk4GboxList *self, guint position, guint n_removal
for (guint i = 0; i < n_additions; i++) {
*objects_index(&self->items, position + i) = gotk4_gbox_object_new(additions[i]);
}
g_log_structured("Gotk4GboxList", G_LOG_LEVEL_DEBUG, //
"MESSAGE", "Added %d objects using splice()", n_additions);
g_debug("Added %d objects using splice()", n_additions);

if (n_removals || n_additions) {
g_list_model_items_changed(G_LIST_MODEL(self), position, n_removals, n_additions);
Expand All @@ -117,8 +127,7 @@ void gotk4_gbox_list_append(Gotk4GboxList *self, guintptr id) {
g_return_if_fail(GOTK4_IS_GBOX_LIST(self));

objects_append(&self->items, gotk4_gbox_object_new(id));
g_log_structured("Gotk4GboxList", G_LOG_LEVEL_DEBUG, //
"MESSAGE", "Added 1 object using append()");
g_debug("Added 1 object using append()");

g_list_model_items_changed(G_LIST_MODEL(self), objects_get_size(&self->items) - 1, 0, 1);
}
Expand Down
106 changes: 64 additions & 42 deletions pkg/core/intern/intern.go
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@ import "C"

import (
"fmt"
"log/slog"
"runtime"
"runtime/debug"
"runtime/pprof"
Expand Down Expand Up @@ -69,8 +70,8 @@ func sink(v interface{}) {
}

var (
traceObjects = gdebug.NewDebugLoggerNullable("trace-objects")
toggleRefs = gdebug.NewDebugLoggerNullable("toggle-refs")
traceObjects = gdebug.HasKey("trace-objects")
toggleRefs = gdebug.HasKey("toggle-refs")
objectProfile *pprof.Profile
)

Expand All @@ -80,8 +81,12 @@ func init() {
}
}

func objInfo(obj unsafe.Pointer) string {
return fmt.Sprintf("%p (%s):", obj, C.GoString(C.gotk4_object_type_name(C.gpointer(obj))))
func objInfo(obj unsafe.Pointer) slog.Attr {
return slog.Group(
"gobject",
slog.String("ptr", fmt.Sprintf("%p", obj)),
slog.String("type", C.GoString(C.gotk4_object_type_name(C.gpointer(obj)))),
slog.Int("refs", objRefCount(obj)))
}

func objRefCount(obj unsafe.Pointer) int {
Expand All @@ -103,8 +108,11 @@ func newBox(obj unsafe.Pointer) *Box {
objectProfile.Add(obj, 3)
}

if traceObjects != nil {
traceObjects.Printf("%p: %s", obj, debug.Stack())
if traceObjects {
slog.Debug(
"allocating new box for object",
"stack", string(debug.Stack()),
objInfo(obj))
}

// Force box on the heap. Objects on the stack can move, but not objects on
Expand Down Expand Up @@ -170,9 +178,10 @@ func Get(gobject unsafe.Pointer, take bool) *Box {
//
shared.strong[gobject] = box

if toggleRefs != nil {
toggleRefs.Println(objInfo(gobject),
"Get: will introduce new box, current ref =", objRefCount(gobject))
if toggleRefs {
slog.Debug(
"Get: will introduce new box for object",
objInfo(gobject))
}

shared.mu.Unlock()
Expand All @@ -182,6 +191,12 @@ func Get(gobject unsafe.Pointer, take bool) *Box {
(*[0]byte)(C.goToggleNotify), nil,
)

if toggleRefs {
slog.Debug(
"Get: added toggle reference to object",
objInfo(gobject))
}

// We should already have a strong reference. Sink the object in case. This
// will force the reference to be truly strong.
if C.g_object_is_floating(C.gpointer(gobject)) != C.FALSE {
Expand All @@ -191,26 +206,23 @@ func Get(gobject unsafe.Pointer, take bool) *Box {
// Then, we need to unref it to balance the ref_sink.
C.g_object_unref(C.gpointer(gobject))

if toggleRefs != nil {
toggleRefs.Println(objInfo(gobject),
"Get: ref_sink'd the object, current ref =", objRefCount(gobject))
if toggleRefs {
slog.Debug(
"Get: ref_sink'd the object",
objInfo(gobject))
}
}

// If we're "not taking," then we can assume our ownership over the object,
// meaning the strong reference is now ours. That means we need to replace
// it, not add.
if !take {
if toggleRefs != nil {
toggleRefs.Println(objInfo(gobject),
"Get: not taking, so unrefing the object, current ref =", objRefCount(gobject))
}
C.g_object_unref(C.gpointer(gobject))
}

if toggleRefs != nil {
toggleRefs.Println(objInfo(gobject),
"Get: introduced new box, current ref =", objRefCount(gobject))
if toggleRefs {
slog.Debug(
"Get: not taking, so unref'd the object",
objInfo(gobject))
}
}

// Undo the initial ref_sink.
Expand Down Expand Up @@ -246,8 +258,10 @@ func finalizeBox(dummy *boxDummy) {
// out it hates being finalized in goFinishRemovingToggleRef, so we just
// don't call it there and let the GC do its thing.

if traceObjects != nil {
traceObjects.Printf("%p: finalizeBox: unknown object", dummy.gobject)
if traceObjects {
slog.Debug(
"finalizeBox: unknown object, possible bug?",
"gobject.ptr", fmt.Sprintf("%p", dummy.gobject))
}

return
Expand All @@ -261,10 +275,10 @@ func finalizeBox(dummy *boxDummy) {
// If the box is already finalizing, then we don't need to do anything.
// Repeat this until box is gone from the registry.

if toggleRefs != nil {
toggleRefs.Printf(
"%p: finalizeBox: already finalizing, waiting for goFinishRemovingToggleRef",
dummy.gobject)
if toggleRefs {
slog.Debug(
"finalizeBox: already finalizing, waiting for goFinishRemovingToggleRef",
"gobject.ptr", fmt.Sprintf("%p", dummy.gobject))
}

return
Expand All @@ -275,10 +289,10 @@ func finalizeBox(dummy *boxDummy) {
// be referenced from the C side, and those closures might access this
// object. Don't free.

if toggleRefs != nil {
toggleRefs.Println(
objInfo(dummy.gobject),
"finalizeBox: moving finalize to next GC cycle since object is still strong")
if toggleRefs {
slog.Debug(
"finalizeBox: moving finalize to next GC cycle since object is still strong",
objInfo(dummy.gobject))
}

return
Expand All @@ -289,9 +303,9 @@ func finalizeBox(dummy *boxDummy) {

// Do this before we dispatch the remove_toggle_ref, because the
// remove_toggle_ref might destroy the object.
var objInfoS string
if toggleRefs != nil {
objInfoS = objInfo(dummy.gobject)
var prevObjInfo slog.Attr
if toggleRefs {
prevObjInfo = objInfo(dummy.gobject)
}

// Do this in the main loop instead. This is because finalizers are
Expand All @@ -302,10 +316,10 @@ func finalizeBox(dummy *boxDummy) {
(*[0]byte)(C.gotk4_intern_remove_toggle_ref),
C.gpointer(dummy.gobject))

if toggleRefs != nil {
toggleRefs.Printf(
"%s finalizeBox: remove_toggle_ref queued for next main loop iteration for box %p",
objInfoS, box)
if toggleRefs {
slog.Debug(
"finalizeBox: remove_toggle_ref queued for next main loop iteration",
prevObjInfo)
}
}

Expand Down Expand Up @@ -338,8 +352,12 @@ func makeStrong(gobject unsafe.Pointer) *Box {
// TODO: double mutex check, similar to ShouldFree.

box, strong := gets(gobject)
if toggleRefs != nil {
toggleRefs.Println(objInfo(gobject), "makeStrong: obtained box", box, "strong =", strong)
if toggleRefs {
slog.Debug(
"makeStrong: obtained box",
"strong", strong,
"box", box != nil,
objInfo(gobject))
}
if box == nil {
return nil
Expand All @@ -362,8 +380,12 @@ func makeStrong(gobject unsafe.Pointer) *Box {
//go:nosplit
func makeWeak(gobject unsafe.Pointer) *Box {
box, strong := gets(gobject)
if toggleRefs != nil {
toggleRefs.Println(objInfo(gobject), "makeWeak: obtained box", box, "strong =", strong)
if toggleRefs {
slog.Debug(
"makeWeak: obtained box",
"strong", strong,
"box", box != nil,
objInfo(gobject))
}
if box == nil {
return nil
Expand Down
Loading

0 comments on commit f5d8467

Please sign in to comment.