From e215a7bc18a2c3263a6fcca37c1ec53af6c4babd Mon Sep 17 00:00:00 2001 From: "David T. Goldblatt" Date: Wed, 19 Jul 2017 18:05:28 -0700 Subject: [PATCH] Add entry and exit logging to all core functions. I.e. mallloc, free, the allocx API, the posix extensions. --- include/jemalloc/internal/log.h | 6 + src/jemalloc.c | 199 +++++++++++++++++++++++++++++++- 2 files changed, 204 insertions(+), 1 deletion(-) diff --git a/include/jemalloc/internal/log.h b/include/jemalloc/internal/log.h index 8413a4d6..1df8cfff 100644 --- a/include/jemalloc/internal/log.h +++ b/include/jemalloc/internal/log.h @@ -30,6 +30,12 @@ * You can then log by writing: * log(log_var, "format string -- my int is %d", my_int); * + * The namespaces currently in use: + * core.[malloc|free|posix_memalign|...].[entry|exit]: + * The entry/exit points of the functions publicly exposed by jemalloc. + * The "entry" variants try to log arguments to the functions, and the + * "exit" ones try to log return values. + * * None of this should be regarded as a stable API for right now. It's intended * as a debugging interface, to let us keep around some of our printf-debugging * statements. diff --git a/src/jemalloc.c b/src/jemalloc.c index 09bac9eb..48a268ff 100644 --- a/src/jemalloc.c +++ b/src/jemalloc.c @@ -1974,6 +1974,13 @@ je_malloc(size_t size) { static_opts_t sopts; dynamic_opts_t dopts; + static log_var_t log_core_malloc_entry = LOG_VAR_INIT( + "core.malloc.entry"); + static log_var_t log_core_malloc_exit = LOG_VAR_INIT( + "core.malloc.exit"); + + log(log_core_malloc_entry, "size: %zu", size); + static_opts_init(&sopts); dynamic_opts_init(&dopts); @@ -1988,6 +1995,8 @@ je_malloc(size_t size) { imalloc(&sopts, &dopts); + log(log_core_malloc_exit, "result: %p", ret); + return ret; } @@ -1998,6 +2007,14 @@ je_posix_memalign(void **memptr, size_t alignment, size_t size) { static_opts_t sopts; dynamic_opts_t dopts; + static log_var_t log_core_posix_memalign_entry = LOG_VAR_INIT( + "core.posix_memalign.entry"); + static log_var_t log_core_posix_memalign_exit = LOG_VAR_INIT( + "core.posix_memalign.exit"); + + log(log_core_posix_memalign_entry, "mem ptr: %p, alignment: %zu, " + "size: %zu", memptr, alignment, size); + static_opts_init(&sopts); dynamic_opts_init(&dopts); @@ -2014,6 +2031,10 @@ je_posix_memalign(void **memptr, size_t alignment, size_t size) { dopts.alignment = alignment; ret = imalloc(&sopts, &dopts); + + log(log_core_posix_memalign_exit, "result: %d, alloc ptr: %p", ret, + *memptr); + return ret; } @@ -2026,6 +2047,14 @@ je_aligned_alloc(size_t alignment, size_t size) { static_opts_t sopts; dynamic_opts_t dopts; + static log_var_t log_core_aligned_alloc_entry = LOG_VAR_INIT( + "core.aligned_alloc.entry"); + static log_var_t log_core_aligned_alloc_exit = LOG_VAR_INIT( + "core.aligned_alloc.exit"); + + log(log_core_aligned_alloc_entry, "alignment: %zu, size: %zu\n", + alignment, size); + static_opts_init(&sopts); dynamic_opts_init(&dopts); @@ -2044,6 +2073,9 @@ je_aligned_alloc(size_t alignment, size_t size) { dopts.alignment = alignment; imalloc(&sopts, &dopts); + + log(log_core_aligned_alloc_exit, "result: %p", ret); + return ret; } @@ -2055,6 +2087,13 @@ je_calloc(size_t num, size_t size) { static_opts_t sopts; dynamic_opts_t dopts; + static log_var_t log_core_calloc_entry = LOG_VAR_INIT( + "core.calloc.entry"); + static log_var_t log_core_calloc_exit = LOG_VAR_INIT( + "core.calloc.exit"); + + log(log_core_calloc_entry, "num: %zu, size: %zu\n", num, size); + static_opts_init(&sopts); dynamic_opts_init(&dopts); @@ -2071,6 +2110,8 @@ je_calloc(size_t num, size_t size) { imalloc(&sopts, &dopts); + log(log_core_calloc_exit, "result: %p", ret); + return ret; } @@ -2204,6 +2245,13 @@ je_realloc(void *ptr, size_t size) { size_t usize JEMALLOC_CC_SILENCE_INIT(0); size_t old_usize = 0; + static log_var_t log_core_realloc_entry = LOG_VAR_INIT( + "core.realloc.entry"); + static log_var_t log_core_realloc_exit = LOG_VAR_INIT( + "core.realloc.exit"); + + log(log_core_realloc_entry, "ptr: %p, size: %zu\n", ptr, size); + if (unlikely(size == 0)) { if (ptr != NULL) { /* realloc(ptr, 0) is equivalent to free(ptr). */ @@ -2216,6 +2264,8 @@ je_realloc(void *ptr, size_t size) { tcache = NULL; } ifree(tsd, ptr, tcache, true); + + log(log_core_realloc_exit, "result: %p", NULL); return NULL; } size = 1; @@ -2248,7 +2298,9 @@ je_realloc(void *ptr, size_t size) { tsdn = tsd_tsdn(tsd); } else { /* realloc(NULL, size) is equivalent to malloc(size). */ - return je_malloc(size); + void *ret = je_malloc(size); + log(log_core_realloc_exit, "result: %p", ret); + return ret; } if (unlikely(ret == NULL)) { @@ -2269,11 +2321,20 @@ je_realloc(void *ptr, size_t size) { } UTRACE(ptr, size, ret); check_entry_exit_locking(tsdn); + + log(log_core_realloc_exit, "result: %p", ret); return ret; } JEMALLOC_EXPORT void JEMALLOC_NOTHROW je_free(void *ptr) { + static log_var_t log_core_free_entry = LOG_VAR_INIT( + "core.free.entry"); + static log_var_t log_core_free_exit = LOG_VAR_INIT( + "core.free.exit"); + + log(log_core_free_entry, "ptr: %p", ptr); + UTRACE(ptr, 0, 0); if (likely(ptr != NULL)) { /* @@ -2303,6 +2364,7 @@ je_free(void *ptr) { } check_entry_exit_locking(tsd_tsdn(tsd)); } + log(log_core_free_exit, "%s", ""); } /* @@ -2322,6 +2384,14 @@ je_memalign(size_t alignment, size_t size) { static_opts_t sopts; dynamic_opts_t dopts; + static log_var_t log_core_memalign_entry = LOG_VAR_INIT( + "core.memalign.entry"); + static log_var_t log_core_memalign_exit = LOG_VAR_INIT( + "core.memalign.exit"); + + log(log_core_memalign_entry, "alignment: %zu, size: %zu\n", alignment, + size); + static_opts_init(&sopts); dynamic_opts_init(&dopts); @@ -2339,6 +2409,8 @@ je_memalign(size_t alignment, size_t size) { dopts.alignment = alignment; imalloc(&sopts, &dopts); + + log(log_core_memalign_exit, "result: %p", ret); return ret; } #endif @@ -2353,6 +2425,13 @@ je_valloc(size_t size) { static_opts_t sopts; dynamic_opts_t dopts; + static log_var_t log_core_valloc_entry = LOG_VAR_INIT( + "core.valloc.entry"); + static log_var_t log_core_valloc_exit = LOG_VAR_INIT( + "core.valloc.exit"); + + log(log_core_valloc_entry, "size: %zu\n", size); + static_opts_init(&sopts); dynamic_opts_init(&dopts); @@ -2371,6 +2450,7 @@ je_valloc(size_t size) { imalloc(&sopts, &dopts); + log(log_core_valloc_exit, "result: %p\n", ret); return ret; } #endif @@ -2444,6 +2524,13 @@ je_mallocx(size_t size, int flags) { static_opts_t sopts; dynamic_opts_t dopts; + static log_var_t log_core_mallocx_entry = LOG_VAR_INIT( + "core.mallocx.entry"); + static log_var_t log_core_mallocx_exit = LOG_VAR_INIT( + "core.mallocx.exit"); + + log(log_core_mallocx_entry, "size: %zu, flags: %d", size, flags); + static_opts_init(&sopts); dynamic_opts_init(&dopts); @@ -2477,6 +2564,8 @@ je_mallocx(size_t size, int flags) { } imalloc(&sopts, &dopts); + + log(log_core_mallocx_exit, "result: %p", ret); return ret; } @@ -2557,6 +2646,15 @@ je_rallocx(void *ptr, size_t size, int flags) { arena_t *arena; tcache_t *tcache; + static log_var_t log_core_rallocx_entry = LOG_VAR_INIT( + "core.rallocx.entry"); + static log_var_t log_core_rallocx_exit = LOG_VAR_INIT( + "core.rallocx.exit"); + + log(log_core_rallocx_entry, "ptr: %p, size: %zu, flags: %d", ptr, + size, flags); + + assert(ptr != NULL); assert(size != 0); assert(malloc_initialized() || IS_INITIALIZER); @@ -2619,6 +2717,8 @@ je_rallocx(void *ptr, size_t size, int flags) { } UTRACE(ptr, size, p); check_entry_exit_locking(tsd_tsdn(tsd)); + + log(log_core_rallocx_exit, "result: %p", p); return p; label_oom: if (config_xmalloc && unlikely(opt_xmalloc)) { @@ -2627,6 +2727,8 @@ label_oom: } UTRACE(ptr, size, 0); check_entry_exit_locking(tsd_tsdn(tsd)); + + log(log_core_rallocx_exit, "result: %p", NULL); return NULL; } @@ -2713,6 +2815,15 @@ je_xallocx(void *ptr, size_t size, size_t extra, int flags) { size_t alignment = MALLOCX_ALIGN_GET(flags); bool zero = flags & MALLOCX_ZERO; + static log_var_t log_core_xallocx_entry = LOG_VAR_INIT( + "core.xallocx.entry"); + static log_var_t log_core_xallocx_exit = LOG_VAR_INIT( + "core.xallocx.exit"); + + log(log_core_xallocx_entry, "ptr: %p, size: %zu, extra: %zu, " + "flags: %d", ptr, size, extra, flags); + + assert(ptr != NULL); assert(size != 0); assert(SIZE_T_MAX - size >= extra); @@ -2762,6 +2873,8 @@ je_xallocx(void *ptr, size_t size, size_t extra, int flags) { label_not_resized: UTRACE(ptr, size, ptr); check_entry_exit_locking(tsd_tsdn(tsd)); + + log(log_core_xallocx_exit, "result: %zu", usize); return usize; } @@ -2771,6 +2884,13 @@ je_sallocx(const void *ptr, int flags) { size_t usize; tsdn_t *tsdn; + static log_var_t log_core_sallocx_entry = LOG_VAR_INIT( + "core.sallocx.entry"); + static log_var_t log_core_sallocx_exit = LOG_VAR_INIT( + "core.sallocx.exit"); + + log(log_core_sallocx_entry, "ptr: %p, flags: %d", ptr, flags); + assert(malloc_initialized() || IS_INITIALIZER); assert(ptr != NULL); @@ -2785,11 +2905,20 @@ je_sallocx(const void *ptr, int flags) { } check_entry_exit_locking(tsdn); + + log(log_core_sallocx_exit, "result: %zu", usize); return usize; } JEMALLOC_EXPORT void JEMALLOC_NOTHROW je_dallocx(void *ptr, int flags) { + static log_var_t log_core_dallocx_entry = LOG_VAR_INIT( + "core.dallocx.entry"); + static log_var_t log_core_dallocx_exit = LOG_VAR_INIT( + "core.dallocx.exit"); + + log(log_core_dallocx_entry, "ptr: %p, flags: %d", ptr, flags); + assert(ptr != NULL); assert(malloc_initialized() || IS_INITIALIZER); @@ -2827,6 +2956,8 @@ je_dallocx(void *ptr, int flags) { ifree(tsd, ptr, tcache, true); } check_entry_exit_locking(tsd_tsdn(tsd)); + + log(log_core_dallocx_exit, "%s", ""); } JEMALLOC_ALWAYS_INLINE size_t @@ -2848,6 +2979,14 @@ je_sdallocx(void *ptr, size_t size, int flags) { assert(ptr != NULL); assert(malloc_initialized() || IS_INITIALIZER); + static log_var_t log_core_sdallocx_entry = LOG_VAR_INIT( + "core.sdallocx.entry"); + static log_var_t log_core_sdallocx_exit = LOG_VAR_INIT( + "core.sdallocx.exit"); + + log(log_core_sdallocx_entry, "ptr: %p, size: %zu, flags: %d", ptr, + size, flags); + tsd_t *tsd = tsd_fetch(); bool fast = tsd_fast(tsd); size_t usize = inallocx(tsd_tsdn(tsd), size, flags); @@ -2884,6 +3023,8 @@ je_sdallocx(void *ptr, size_t size, int flags) { isfree(tsd, ptr, usize, tcache, true); } check_entry_exit_locking(tsd_tsdn(tsd)); + + log(log_core_sdallocx_exit, "%s", ""); } JEMALLOC_EXPORT size_t JEMALLOC_NOTHROW @@ -2892,9 +3033,17 @@ je_nallocx(size_t size, int flags) { size_t usize; tsdn_t *tsdn; + static log_var_t log_core_nallocx_entry = LOG_VAR_INIT( + "core.nallocx.entry"); + static log_var_t log_core_nallocx_exit = LOG_VAR_INIT( + "core.nallocx.exit"); + + log(log_core_nallocx_entry, "size: %zu, flags: %d", size, flags); + assert(size != 0); if (unlikely(malloc_init())) { + log(log_core_nallocx_exit, "result: %zu", ZU(0)); return 0; } @@ -2903,10 +3052,12 @@ je_nallocx(size_t size, int flags) { usize = inallocx(tsdn, size, flags); if (unlikely(usize > LARGE_MAXCLASS)) { + log(log_core_nallocx_exit, "result: %zu", ZU(0)); return 0; } check_entry_exit_locking(tsdn); + log(log_core_nallocx_exit, "result: %zu", usize); return usize; } @@ -2916,7 +3067,15 @@ je_mallctl(const char *name, void *oldp, size_t *oldlenp, void *newp, int ret; tsd_t *tsd; + static log_var_t log_core_mallctl_entry = LOG_VAR_INIT( + "core.mallctl.entry"); + static log_var_t log_core_mallctl_exit = LOG_VAR_INIT( + "core.mallctl.exit"); + + log(log_core_mallctl_entry, "name: %s", name); + if (unlikely(malloc_init())) { + log(log_core_mallctl_exit, "result: %d", EAGAIN); return EAGAIN; } @@ -2924,6 +3083,8 @@ je_mallctl(const char *name, void *oldp, size_t *oldlenp, void *newp, check_entry_exit_locking(tsd_tsdn(tsd)); ret = ctl_byname(tsd, name, oldp, oldlenp, newp, newlen); check_entry_exit_locking(tsd_tsdn(tsd)); + + log(log_core_mallctl_exit, "result: %d", ret); return ret; } @@ -2931,7 +3092,15 @@ JEMALLOC_EXPORT int JEMALLOC_NOTHROW je_mallctlnametomib(const char *name, size_t *mibp, size_t *miblenp) { int ret; + static log_var_t log_core_mallctlnametomib_entry = LOG_VAR_INIT( + "core.mallctlnametomib.entry"); + static log_var_t log_core_mallctlnametomib_exit = LOG_VAR_INIT( + "core.mallctlnametomib.exit"); + + log(log_core_mallctlnametomib_entry, "name: %s", name); + if (unlikely(malloc_init())) { + log(log_core_mallctlnametomib_exit, "result: %d", EAGAIN); return EAGAIN; } @@ -2939,6 +3108,8 @@ je_mallctlnametomib(const char *name, size_t *mibp, size_t *miblenp) { check_entry_exit_locking(tsd_tsdn(tsd)); ret = ctl_nametomib(tsd, name, mibp, miblenp); check_entry_exit_locking(tsd_tsdn(tsd)); + + log(log_core_mallctlnametomib_exit, "result: %d", ret); return ret; } @@ -2948,7 +3119,16 @@ je_mallctlbymib(const size_t *mib, size_t miblen, void *oldp, size_t *oldlenp, int ret; tsd_t *tsd; + static log_var_t log_core_mallctlbymib_entry = LOG_VAR_INIT( + "core.mallctlbymib.entry"); + static log_var_t log_core_mallctlbymib_exit = LOG_VAR_INIT( + "core.mallctlbymib.exit"); + + log(log_core_mallctlbymib_entry, "%s", ""); + + if (unlikely(malloc_init())) { + log(log_core_mallctlbymib_exit, "result: %d", EAGAIN); return EAGAIN; } @@ -2956,6 +3136,7 @@ je_mallctlbymib(const size_t *mib, size_t miblen, void *oldp, size_t *oldlenp, check_entry_exit_locking(tsd_tsdn(tsd)); ret = ctl_bymib(tsd, mib, miblen, oldp, oldlenp, newp, newlen); check_entry_exit_locking(tsd_tsdn(tsd)); + log(log_core_mallctlbymib_exit, "result: %d", ret); return ret; } @@ -2964,10 +3145,18 @@ je_malloc_stats_print(void (*write_cb)(void *, const char *), void *cbopaque, const char *opts) { tsdn_t *tsdn; + static log_var_t log_core_malloc_stats_print_entry = LOG_VAR_INIT( + "core.malloc_stats_print.entry"); + static log_var_t log_core_malloc_stats_print_exit = LOG_VAR_INIT( + "core.malloc_stats_print.exit"); + + log(log_core_malloc_stats_print_entry, "%s", ""); + tsdn = tsdn_fetch(); check_entry_exit_locking(tsdn); stats_print(write_cb, cbopaque, opts); check_entry_exit_locking(tsdn); + log(log_core_malloc_stats_print_exit, "%s", ""); } JEMALLOC_EXPORT size_t JEMALLOC_NOTHROW @@ -2975,6 +3164,13 @@ je_malloc_usable_size(JEMALLOC_USABLE_SIZE_CONST void *ptr) { size_t ret; tsdn_t *tsdn; + static log_var_t log_core_malloc_usable_size_entry = LOG_VAR_INIT( + "core.malloc_usable_size.entry"); + static log_var_t log_core_malloc_usable_size_exit = LOG_VAR_INIT( + "core.malloc_usable_size.exit"); + + log(log_core_malloc_usable_size_entry, "ptr: %p", ptr); + assert(malloc_initialized() || IS_INITIALIZER); tsdn = tsdn_fetch(); @@ -2992,6 +3188,7 @@ je_malloc_usable_size(JEMALLOC_USABLE_SIZE_CONST void *ptr) { } check_entry_exit_locking(tsdn); + log(log_core_malloc_usable_size_exit, "result: %zu", ret); return ret; }