From owner-freebsd-hackers@FreeBSD.ORG Sat Dec 22 03:37:59 2012 Return-Path: Delivered-To: hackers@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [69.147.83.52]) by hub.freebsd.org (Postfix) with ESMTP id 3C838CAA; Sat, 22 Dec 2012 03:37:59 +0000 (UTC) (envelope-from bright@mu.org) Received: from elvis.mu.org (elvis.mu.org [192.203.228.196]) by mx1.freebsd.org (Postfix) with ESMTP id 11B428FC0A; Sat, 22 Dec 2012 03:37:58 +0000 (UTC) Received: from Alfreds-MacBook-Pro-9.local (c-67-180-208-218.hsd1.ca.comcast.net [67.180.208.218]) by elvis.mu.org (Postfix) with ESMTPSA id EB4221A3C1C; Fri, 21 Dec 2012 19:37:51 -0800 (PST) Message-ID: <50D52B10.1060205@mu.org> Date: Fri, 21 Dec 2012 19:37:52 -0800 From: Alfred Perlstein User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:17.0) Gecko/17.0 Thunderbird/17.0 MIME-Version: 1.0 To: Daniel Eischen , Jason Evans , hackers@freebsd.org Subject: malloc+utrace, tracking memory leaks in a running program. Content-Type: multipart/mixed; boundary="------------000103040406040707070503" X-Content-Filtered-By: Mailman/MimeDel 2.1.14 X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 22 Dec 2012 03:37:59 -0000 This is a multi-part message in MIME format. --------------000103040406040707070503 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Hey guys. So the other day in an effort to debug a memory leak I decided to take a look at malloc+utrace(2) and decided to make a tool to debug where leaks are coming from. A few hours later I have: 1) a new version of utrace(2) (utrace2(2)) that uses structured data to prevent overloading of data. (utrace2.diff) 2) changes to ktrace and kdump to decode the new format. (also in utrace2.diff) 3) changes to jemalloc to include the new format AND the function caller so it's easy to get the source of the leaks. (also in utrace2.diff) 4) a program that can take a pipe of kdump(1) and figure out what memory has leaked. (alloctrace.py) 5) simple test program (test_utrace.c) If you want to get a trace now you can do this: gcc -Wall -O ./test_utrace.c env MALLOC_CONF='utrace:true' ktrace ./a.out kdump | ./alloctrace.py Now the problem I am having is making this work on a running program: 1) turning on the "opt_utrace" in a running program is almost impossible. This is because libc is installed stripped. Unfortunately my gdb-foo is weak and I was unable to load the symbol file without a really bad hack. The only way I could get it done was to use a trick from Ed Maste which was to: 1.1) install a debug copy of libc.so over the installed one. <- dislike! 1.2) then launching gdb ./a.out , 1.3) then set __jemalloc_opt_utrace = 1 1.4) enable ktrace on the running binary: ktrace -p -t U # this is utrace2 enabled 1.5) run 'cont' in gdb to proceed. There has to be an easier way to access the symbol __jemalloc_opt_utrace besides copying over the installed libc. Is there a workaround for 1.1? Is it time to start installing with some form of debug symbols? This would help us also with dtrace. Ideas? -Alfred --------------000103040406040707070503 Content-Type: text/plain; charset=UTF-8; x-mac-type="0"; x-mac-creator="0"; name="utrace2.diff" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="utrace2.diff" Index: contrib/jemalloc/src/jemalloc.c =================================================================== --- contrib/jemalloc/src/jemalloc.c (revision 244503) +++ contrib/jemalloc/src/jemalloc.c (working copy) @@ -78,20 +78,26 @@ static malloc_mutex_t init_lock = MALLOC_MUTEX_INITIALIZER; #endif +#ifdef JEMALLOC_UTRACE typedef struct { + int ut_type; /* utrace type UTRACE_MALLOC */ + int ut_version; /* utrace malloc version */ void *p; /* Input pointer (as in realloc(p, s)). */ size_t s; /* Request size. */ void *r; /* Result pointer. */ + void *ut_caller; /* Caller */ } malloc_utrace_t; -#ifdef JEMALLOC_UTRACE # define UTRACE(a, b, c) do { \ if (opt_utrace) { \ malloc_utrace_t ut; \ + ut.ut_type = UTRACE_MALLOC; \ + ut.ut_version = 2; \ ut.p = (a); \ ut.s = (b); \ ut.r = (c); \ - utrace(&ut, sizeof(ut)); \ + ut.ut_caller = __builtin_return_address(0); \ + utrace2(&ut, sizeof(ut)); \ } \ } while (0) #else @@ -975,7 +981,6 @@ } if (config_prof && opt_prof && result != NULL) prof_malloc(result, usize, cnt); - UTRACE(0, size, result); return (ret); } @@ -985,6 +990,7 @@ int ret = imemalign(memptr, alignment, size, sizeof(void *)); JEMALLOC_VALGRIND_MALLOC(ret == 0, *memptr, isalloc(*memptr, config_prof), false); + UTRACE(0, size, *memptr); return (ret); } @@ -1000,6 +1006,7 @@ } JEMALLOC_VALGRIND_MALLOC(err == 0, ret, isalloc(ret, config_prof), false); + UTRACE(0, size, ret); return (ret); } @@ -1265,6 +1272,7 @@ void *ret JEMALLOC_CC_SILENCE_INIT(NULL); imemalign(&ret, alignment, size, 1); JEMALLOC_VALGRIND_MALLOC(ret != NULL, ret, size, false); + UTRACE(0, size, ret); return (ret); } #endif @@ -1276,6 +1284,7 @@ void *ret JEMALLOC_CC_SILENCE_INIT(NULL); imemalign(&ret, PAGE, size, 1); JEMALLOC_VALGRIND_MALLOC(ret != NULL, ret, size, false); + UTRACE(0, size, ret); return (ret); } #endif Index: sys/compat/freebsd32/syscalls.master =================================================================== --- sys/compat/freebsd32/syscalls.master (revision 244503) +++ sys/compat/freebsd32/syscalls.master (working copy) @@ -1004,4 +1004,5 @@ int *status, int options, \ struct wrusage32 *wrusage, \ siginfo_t *info); } +533 AUE_NULL STD { int utrace2(const void *addr, size_t len); } Index: sys/kern/init_sysent.c =================================================================== --- sys/kern/init_sysent.c (revision 244503) +++ sys/kern/init_sysent.c (working copy) @@ -567,4 +567,5 @@ { AS(posix_fallocate_args), (sy_call_t *)sys_posix_fallocate, AUE_NULL, NULL, 0, 0, 0, SY_THR_STATIC }, /* 530 = posix_fallocate */ { AS(posix_fadvise_args), (sy_call_t *)sys_posix_fadvise, AUE_NULL, NULL, 0, 0, 0, SY_THR_STATIC }, /* 531 = posix_fadvise */ { AS(wait6_args), (sy_call_t *)sys_wait6, AUE_WAIT6, NULL, 0, 0, 0, SY_THR_STATIC }, /* 532 = wait6 */ + { AS(utrace2_args), (sy_call_t *)sys_utrace2, AUE_NULL, NULL, 0, 0, 0, SY_THR_STATIC }, /* 533 = utrace2 */ }; Index: sys/kern/kern_ktrace.c =================================================================== --- sys/kern/kern_ktrace.c (revision 244503) +++ sys/kern/kern_ktrace.c (working copy) @@ -123,6 +123,7 @@ sizeof(struct ktr_cap_fail), /* KTR_CAPFAIL */ sizeof(struct ktr_fault), /* KTR_FAULT */ sizeof(struct ktr_faultend), /* KTR_FAULTEND */ + 0, /* KTR_USER2 */ }; static STAILQ_HEAD(, ktr_request) ktr_free; @@ -1025,7 +1026,43 @@ #endif /* KTRACE */ } +/* ARGSUSED */ +int +sys_utrace2(td, uap) + struct thread *td; + register struct utrace2_args *uap; +{ + #ifdef KTRACE + struct ktr_request *req; + void *cp; + int error; + + if (!KTRPOINT(td, KTR_USER2)) + return (0); + if (uap->len > KTR_USER_MAXLEN) + return (EINVAL); + cp = malloc(uap->len, M_KTRACE, M_WAITOK); + error = copyin(uap->addr, cp, uap->len); + if (error) { + free(cp, M_KTRACE); + return (error); + } + req = ktr_getrequest(KTR_USER2); + if (req == NULL) { + free(cp, M_KTRACE); + return (ENOMEM); + } + req->ktr_buffer = cp; + req->ktr_header.ktr_len = uap->len; + ktr_submitrequest(td, req); + return (0); +#else /* !KTRACE */ + return (ENOSYS); +#endif /* KTRACE */ +} + +#ifdef KTRACE static int ktrops(td, p, ops, facs, vp) struct thread *td; Index: sys/kern/syscalls.c =================================================================== --- sys/kern/syscalls.c (revision 244503) +++ sys/kern/syscalls.c (working copy) @@ -540,4 +540,5 @@ "posix_fallocate", /* 530 = posix_fallocate */ "posix_fadvise", /* 531 = posix_fadvise */ "wait6", /* 532 = wait6 */ + "utrace2", /* 533 = utrace2 */ }; Index: sys/kern/syscalls.master =================================================================== --- sys/kern/syscalls.master (revision 244503) +++ sys/kern/syscalls.master (working copy) @@ -955,5 +955,6 @@ int *status, int options, \ struct __wrusage *wrusage, \ siginfo_t *info); } +533 AUE_NULL STD { int utrace2(const void *addr, size_t len); } ; Please copy any additions and changes to the following compatability tables: ; sys/compat/freebsd32/syscalls.master Index: sys/kern/systrace_args.c =================================================================== --- sys/kern/systrace_args.c (revision 244503) +++ sys/kern/systrace_args.c (working copy) @@ -3286,6 +3286,14 @@ *n_args = 6; break; } + /* utrace2 */ + case 533: { + struct utrace2_args *p = params; + uarg[0] = (intptr_t) p->addr; /* const void * */ + uarg[1] = p->len; /* size_t */ + *n_args = 2; + break; + } default: *n_args = 0; break; @@ -8745,6 +8753,19 @@ break; }; break; + /* utrace2 */ + case 533: + switch(ndx) { + case 0: + p = "const void *"; + break; + case 1: + p = "size_t"; + break; + default: + break; + }; + break; default: break; }; @@ -10638,6 +10659,11 @@ if (ndx == 0 || ndx == 1) p = "int"; break; + /* utrace2 */ + case 533: + if (ndx == 0 || ndx == 1) + p = "int"; + break; default: break; }; Index: sys/sys/ktrace.h =================================================================== --- sys/sys/ktrace.h (revision 244503) +++ sys/sys/ktrace.h (working copy) @@ -216,6 +216,8 @@ int result; }; +#define KTR_USER2 15 + /* * KTR_DROP - If this bit is set in ktr_type, then at least one event * between the previous record and this record was dropped. @@ -240,6 +242,7 @@ #define KTRFAC_CAPFAIL (1<ktr_type); type = unknown; @@ -1369,51 +1379,117 @@ } } -struct utrace_malloc { - void *p; - size_t s; - void *r; +struct utrace_malloc_old { + void *p; /* Input pointer (as in realloc(p, s)). */ + size_t s; /* Request size. */ + void *r; /* Result pointer. */ }; +struct utrace_malloc_v2 { + int utrace_type; /* utrace type UTRACE_MALLOC */ + int utrace_version; /* utrace malloc version */ + void *p; /* Input pointer (as in realloc(p, s)). */ + size_t s; /* Request size. */ + void *r; /* Result pointer. */ + void *caller; /* Caller */ +}; + void -ktruser_malloc(unsigned char *p) +ktruser_malloc(struct utrace_malloc_v2 *ut, int v2) { - struct utrace_malloc *ut = (struct utrace_malloc *)p; if (ut->p == (void *)(intptr_t)(-1)) - printf("malloc_init()\n"); + printf("malloc_init()"); else if (ut->s == 0) - printf("free(%p)\n", ut->p); + printf("free(%p)", ut->p); else if (ut->p == NULL) - printf("%p = malloc(%zu)\n", ut->r, ut->s); + printf("%p = malloc(%zu)", ut->r, ut->s); else - printf("%p = realloc(%p, %zu)\n", ut->r, ut->p, ut->s); + printf("%p = realloc(%p, %zu)", ut->r, ut->p, ut->s); + if (v2) + printf(", caller %p", ut->caller); + putchar('\n'); } void -ktruser(int len, unsigned char *p) +ktruser_data(size_t len, unsigned char *p) { + printf("%zd ", len); + while (len--) + if (decimal) + printf(" %d", *p++); + else + printf(" %02x", *p++); + printf("\n"); +} + +void +ktruser(int len, void *p) +{ + if (len >= 8 && bcmp(p, "RTLD", 4) == 0) { ktruser_rtld(len, p); return; } - if (len == sizeof(struct utrace_malloc)) { - ktruser_malloc(p); + if (len == sizeof(struct utrace_malloc_old)) { + struct utrace_malloc_old *utm_old; + struct utrace_malloc_v2 utm_v2; + + utm_old = p; + utm_v2.p = utm_old->p; + utm_v2.s = utm_old->s; + utm_v2.r = utm_old->r; + ktruser_malloc(&utm_v2, 0); return; } - printf("%d ", len); - while (len--) - if (decimal) - printf(" %d", *p++); - else - printf(" %02x", *p++); - printf("\n"); + ktruser_data(len, p); } void +ktruser2(size_t len, void *p) +{ + struct ktruser2_header { + int type; + int version; + } *ktru2_hd; + + if (len < sizeof(struct ktruser2_header)) { + warnx("utrace2 size too small: %zd (want: %zd)", + len, sizeof(struct ktruser2_header)); + ktruser_data(len, p); + return; + } + + ktru2_hd = p; + switch (ktru2_hd->type) { + case UTRACE_MALLOC: + if (ktru2_hd->version == 2) { + if (len == sizeof(struct utrace_malloc_v2)) { + ktruser_malloc(p, 1); + return; + } + warnx("ktruser2: UTRACE_MALLOC, version = 2, " + "size incorrect %zd (want: %zd)", + len, sizeof(struct utrace_malloc_v2)); + ktruser_data(len, p); + return; + } else { + warnx("ktruser2: UTRACE_MALLOC, unknown version = %d, " + "(want: %d)", ktru2_hd->version, 2); + ktruser_data(len, p); + return; + } + default: + break; + } + ktruser_data(len, p); + return; +} + +void ktrsockaddr(struct sockaddr *sa) { /* Index: usr.bin/ktrace/ktrace.h =================================================================== --- usr.bin/ktrace/ktrace.h (revision 244503) +++ usr.bin/ktrace/ktrace.h (working copy) @@ -32,7 +32,8 @@ #define DEF_POINTS (KTRFAC_SYSCALL | KTRFAC_SYSRET | KTRFAC_NAMEI | \ KTRFAC_GENIO | KTRFAC_PSIG | KTRFAC_USER | \ - KTRFAC_STRUCT | KTRFAC_SYSCTL | KTRFAC_CAPFAIL) + KTRFAC_STRUCT | KTRFAC_SYSCTL | KTRFAC_CAPFAIL | \ + KTRFAC_USER2) #define PROC_ABI_POINTS (KTRFAC_PROCCTOR | KTRFAC_PROCDTOR) Index: usr.bin/ktrace/subr.c =================================================================== --- usr.bin/ktrace/subr.c (revision 244503) +++ usr.bin/ktrace/subr.c (working copy) @@ -82,6 +82,9 @@ case 'u': facs |= KTRFAC_USER; break; + case 'U': + facs |= KTRFAC_USER2; + break; case 'w': facs |= KTRFAC_CSW; break; --------------000103040406040707070503 Content-Type: text/plain; charset=UTF-8; x-mac-type="0"; x-mac-creator="0"; name="test_utrace.c" Content-Transfer-Encoding: 7bit Content-Disposition: attachment; filename="test_utrace.c" #include #include #include #define SZ 10 int main(void) { void *allocs[SZ]; int i; volatile int dummy = 0; for (i = 0; i < SZ; i++) allocs[i] = malloc(10); while (dummy) { printf("sleeping...\n"); sleep(1); } for (i = 0; i < SZ; i++) allocs[i] = realloc(allocs[i], 100); for (i = 0; i < SZ; i++) allocs[i] = realloc(allocs[i], 200); for (i = 0; i < SZ; i++) allocs[i] = realloc(allocs[i], 20); //for (i = 0; i < SZ; i++) free(allocs[i]); return 0; } --------------000103040406040707070503--