From 20a52bdb1eb4da00fe974d7b6c4e918e72d89c74 Mon Sep 17 00:00:00 2001 From: diamondburned Date: Sat, 2 Nov 2024 20:10:27 -0700 Subject: [PATCH] Switch gdebug to log/slog Also add g_debug logging to listmodel.c for #154 --- pkg/core/gdebug/gdebug.go | 41 ++++++++---- pkg/core/gioutil/listmodel.c | 55 +++++++++------- pkg/core/gioutil/listmodel.h | 10 +-- pkg/core/intern/intern.go | 106 +++++++++++++++++++------------ pkg/core/intern/intern_export.go | 66 ++++++++++--------- 5 files changed, 163 insertions(+), 115 deletions(-) diff --git a/pkg/core/gdebug/gdebug.go b/pkg/core/gdebug/gdebug.go index 47c90bbc1..ccb796e0f 100644 --- a/pkg/core/gdebug/gdebug.go +++ b/pkg/core/gdebug/gdebug.go @@ -1,41 +1,38 @@ 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())) @@ -43,6 +40,22 @@ func mustDebugLogger(name string) *log.Logger { 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{} } diff --git a/pkg/core/gioutil/listmodel.c b/pkg/core/gioutil/listmodel.c index a28be4db9..24fee5a3a 100644 --- a/pkg/core/gioutil/listmodel.c +++ b/pkg/core/gioutil/listmodel.c @@ -1,7 +1,7 @@ -#include "listmodel.h" +#define G_LOG_USE_STRUCTURED +#define G_LOG_DOMAIN "Gotk4GboxObject" -// defined in gbox. -extern void callbackDelete(guintptr id); +#include "listmodel.h" #define GDK_ARRAY_ELEMENT_TYPE Gotk4GboxObject * #define GDK_ARRAY_NAME objects @@ -20,9 +20,11 @@ static void gotk4_gbox_object_init(Gotk4GboxObject *self) { self->id = 0; } static void gotk4_gbox_object_finalize(GObject *object) { Gotk4GboxObject *self = GOTK4_GBOX_OBJECT(object); - if (self->id != 0) { - callbackDelete(self->id); - } + + g_warn_if_fail(self->id != 0); + callbackDelete(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); } @@ -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; } @@ -48,9 +51,7 @@ struct _Gotk4GboxClass { GObjectClass parent_class; }; -static GType gotk4_gbox_list_get_item_type(GListModel *list) { - return G_TYPE_OBJECT; -} +static GType gotk4_gbox_list_get_item_type(GListModel *list) { return G_TYPE_OBJECT; } static guint gotk4_gbox_list_get_n_items(GListModel *list) { Gotk4GboxList *self = GOTK4_GBOX_LIST(list); @@ -62,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) { @@ -72,8 +81,7 @@ static void gotk4_gbox_list_list_model_init(GListModelInterface *iface) { } G_DEFINE_TYPE_WITH_CODE(Gotk4GboxList, gotk4_gbox_list, G_TYPE_OBJECT, - G_IMPLEMENT_INTERFACE(G_TYPE_LIST_MODEL, - gotk4_gbox_list_list_model_init)) + G_IMPLEMENT_INTERFACE(G_TYPE_LIST_MODEL, gotk4_gbox_list_list_model_init)) static void gotk4_gbox_list_dispose(GObject *object) { Gotk4GboxList *self = GOTK4_GBOX_LIST(object); @@ -86,18 +94,16 @@ static void gotk4_gbox_list_class_init(Gotk4GboxListClass *klass) { object_class->dispose = gotk4_gbox_list_dispose; } -static void gotk4_gbox_list_init(Gotk4GboxList *self) { - objects_init(&self->items); -} +static void gotk4_gbox_list_init(Gotk4GboxList *self) { objects_init(&self->items); } Gotk4GboxList *gotk4_gbox_list_new() { return GOTK4_GBOX_LIST(g_object_new(GOTK4_TYPE_GBOX_LIST, NULL)); } -void gotk4_gbox_list_splice(Gotk4GboxList *self, guint position, - guint n_removals, const guintptr *additions) { +void gotk4_gbox_list_splice(Gotk4GboxList *self, guint position, guint n_removals, + guintptr *additions) { g_return_if_fail(GOTK4_IS_GBOX_LIST(self)); - g_return_if_fail(position + n_removals >= position); // overflow + g_return_if_fail(position + n_removals >= position); // overflow g_return_if_fail(position + n_removals <= objects_get_size(&self->items)); guint n_additions = 0; @@ -108,21 +114,22 @@ void gotk4_gbox_list_splice(Gotk4GboxList *self, guint position, objects_splice(&self->items, position, n_removals, FALSE, NULL, n_additions); for (guint i = 0; i < n_additions; i++) { - *objects_index(&self->items, position + i) = - gotk4_gbox_object_new(additions[i]); + *objects_index(&self->items, position + i) = gotk4_gbox_object_new(additions[i]); } + 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); + g_list_model_items_changed(G_LIST_MODEL(self), position, n_removals, n_additions); } } 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_list_model_items_changed(G_LIST_MODEL(self), - objects_get_size(&self->items) - 1, 0, 1); + g_debug("Added 1 object using append()"); + + g_list_model_items_changed(G_LIST_MODEL(self), objects_get_size(&self->items) - 1, 0, 1); } guintptr gotk4_gbox_list_get_id(Gotk4GboxList *self, guint position) { diff --git a/pkg/core/gioutil/listmodel.h b/pkg/core/gioutil/listmodel.h index 20eaf48c7..f61fc4778 100644 --- a/pkg/core/gioutil/listmodel.h +++ b/pkg/core/gioutil/listmodel.h @@ -4,12 +4,14 @@ #include #include +// defined in gbox; is linked to gbox.Delete. +extern void callbackDelete(guintptr id); + G_BEGIN_DECLS #define GOTK4_TYPE_GBOX_OBJECT (gotk4_gbox_object_get_type()) -G_DECLARE_FINAL_TYPE(Gotk4GboxObject, gotk4_gbox_object, GOTK4, GBOX_OBJECT, - GObject) +G_DECLARE_FINAL_TYPE(Gotk4GboxObject, gotk4_gbox_object, GOTK4, GBOX_OBJECT, GObject) Gotk4GboxObject *gotk4_gbox_object_new(guintptr id); guintptr gotk4_gbox_object_get_id(Gotk4GboxObject *self); @@ -19,8 +21,8 @@ guintptr gotk4_gbox_object_get_id(Gotk4GboxObject *self); G_DECLARE_FINAL_TYPE(Gotk4GboxList, gotk4_gbox_list, GOTK4, GBOX_LIST, GObject) Gotk4GboxList *gotk4_gbox_list_new(void); -void gotk4_gbox_list_splice(Gotk4GboxList *self, guint position, - guint n_removals, const guintptr *additions); +void gotk4_gbox_list_splice(Gotk4GboxList *self, guint position, guint n_removals, + guintptr *additions); void gotk4_gbox_list_append(Gotk4GboxList *self, guintptr id); guintptr gotk4_gbox_list_get_id(Gotk4GboxList *self, guint position); diff --git a/pkg/core/intern/intern.go b/pkg/core/intern/intern.go index dbaa3caa7..4fee699aa 100644 --- a/pkg/core/intern/intern.go +++ b/pkg/core/intern/intern.go @@ -7,6 +7,7 @@ import "C" import ( "fmt" + "log/slog" "runtime" "runtime/debug" "runtime/pprof" @@ -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 ) @@ -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 { @@ -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 @@ -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() @@ -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 { @@ -191,9 +206,10 @@ 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)) } } @@ -201,16 +217,12 @@ func Get(gobject unsafe.Pointer, take bool) *Box { // 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. @@ -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 @@ -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 @@ -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 @@ -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 @@ -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) } } @@ -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 @@ -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 diff --git a/pkg/core/intern/intern_export.go b/pkg/core/intern/intern_export.go index bb4ed5f22..f66d4c7ac 100644 --- a/pkg/core/intern/intern_export.go +++ b/pkg/core/intern/intern_export.go @@ -5,6 +5,7 @@ package intern import "C" import ( + "log/slog" "unsafe" ) @@ -28,23 +29,26 @@ func goToggleNotify(_ C.gpointer, obj *C.GObject, isLastInt C.gboolean) { } if box == nil { - if toggleRefs != nil { - toggleRefs.Println(objInfo(unsafe.Pointer(obj)), "goToggleNotify: box not found") + if toggleRefs { + slog.Debug( + "goToggleNotify: box not found", + objInfo(unsafe.Pointer(obj))) } return } + if toggleRefs { + slog.Debug( + "goToggleNotify: finished", + "is_last", isLast, + "finalize", box.finalize, + objInfo(unsafe.Pointer(obj))) + } + if box.finalize { - if toggleRefs != nil { - toggleRefs.Println(objInfo(unsafe.Pointer(obj)), "goToggleNotify: resurrecting finalized object") - } box.finalize = false return } - - if toggleRefs != nil { - toggleRefs.Println(objInfo(unsafe.Pointer(obj)), "goToggleNotify: is last =", isLast) - } } // finishRemovingToggleRef is called after the toggle reference removal routine @@ -52,51 +56,51 @@ func goToggleNotify(_ C.gpointer, obj *C.GObject, isLastInt C.gboolean) { // //export goFinishRemovingToggleRef func goFinishRemovingToggleRef(gobject unsafe.Pointer) { - if toggleRefs != nil { - toggleRefs.Printf("goFinishRemovingToggleRef: called on %p", gobject) - } - shared.mu.Lock() defer shared.mu.Unlock() box, strong := gets(gobject) if box == nil { - if toggleRefs != nil { - toggleRefs.Printf( - "goFinishRemovingToggleRef: object %p not found in weak map", - gobject) + if toggleRefs { + slog.Debug( + "goFinishRemovingToggleRef: object not found in weak map", + "box", false, + objInfo(gobject)) } return } - if toggleRefs != nil { - toggleRefs.Printf( - "goFinishRemovingToggleRef: object %p found in weak map containing box %p", - gobject, box) + if toggleRefs { + slog.Debug( + "goFinishRemovingToggleRef: object found in weak map", + "box", true, + objInfo(gobject)) } if strong { - if toggleRefs != nil { - toggleRefs.Printf( - "goFinishRemovingToggleRef: object %p still strong", - gobject) + if toggleRefs { + slog.Debug( + "goFinishRemovingToggleRef: object still strong", + objInfo(gobject)) } return } if !box.finalize { - if toggleRefs != nil { - toggleRefs.Printf( - "goFinishRemovingToggleRef: object %p not finalizing, instead resurrected", - gobject) + if toggleRefs { + slog.Debug( + "goFinishRemovingToggleRef: object resurrected", + objInfo(gobject)) } return } shared.weak.Delete(gobject) - if toggleRefs != nil { - toggleRefs.Printf("goFinishRemovingToggleRef: removed %p from weak ref, will be finalized soon", gobject) + if toggleRefs { + slog.Debug( + "goFinishRemovingToggleRef: removed from weak ref", + objInfo(gobject)) } if objectProfile != nil {