Skip site navigation (1)Skip section navigation (2)
Date:      Fri, 21 Dec 2012 19:37:52 -0800
From:      Alfred Perlstein <bright@mu.org>
To:        Daniel Eischen <deischen@freebsd.org>, Jason Evans <jasone@freebsd.org>, hackers@freebsd.org
Subject:   malloc+utrace, tracking memory leaks in a running program.
Message-ID:  <50D52B10.1060205@mu.org>

next in thread | raw e-mail | index | archive | help
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 <pid>,
   1.3) then set __jemalloc_opt_utrace = 1
   1.4) enable ktrace on the running binary: ktrace -p <pid> -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_CAPFAIL)
 #define KTRFAC_FAULT	(1<<KTR_FAULT)
 #define KTRFAC_FAULTEND	(1<<KTR_FAULTEND)
+#define KTRFAC_USER2	(1<<KTR_USER2)
 
 /*
  * trace flags (also in p_traceflags)
@@ -277,8 +280,13 @@
 __BEGIN_DECLS
 int	ktrace(const char *, int, int, pid_t);
 int	utrace(const void *, size_t);
+int	utrace2(const void *, size_t);
 __END_DECLS
 
+#define	UTRACE_MALLOC		0x001
+#define UTRACE_SYSMAX		0x100
+#define UTRACE_APPLICATIONMIN	0x101
+
 #endif
 
 #endif
Index: sys/sys/syscall.h
===================================================================
--- sys/sys/syscall.h	(revision 244503)
+++ sys/sys/syscall.h	(working copy)
@@ -452,4 +452,5 @@
 #define	SYS_posix_fallocate	530
 #define	SYS_posix_fadvise	531
 #define	SYS_wait6	532
-#define	SYS_MAXSYSCALL	533
+#define	SYS_utrace2	533
+#define	SYS_MAXSYSCALL	534
Index: sys/sys/syscall.mk
===================================================================
--- sys/sys/syscall.mk	(revision 244503)
+++ sys/sys/syscall.mk	(working copy)
@@ -400,4 +400,5 @@
 	rctl_remove_rule.o \
 	posix_fallocate.o \
 	posix_fadvise.o \
-	wait6.o
+	wait6.o \
+	utrace2.o
Index: sys/sys/sysproto.h
===================================================================
--- sys/sys/sysproto.h	(revision 244503)
+++ sys/sys/sysproto.h	(working copy)
@@ -1762,6 +1762,10 @@
 	char wrusage_l_[PADL_(struct __wrusage *)]; struct __wrusage * wrusage; char wrusage_r_[PADR_(struct __wrusage *)];
 	char info_l_[PADL_(siginfo_t *)]; siginfo_t * info; char info_r_[PADR_(siginfo_t *)];
 };
+struct utrace2_args {
+	char addr_l_[PADL_(const void *)]; const void * addr; char addr_r_[PADR_(const void *)];
+	char len_l_[PADL_(size_t)]; size_t len; char len_r_[PADR_(size_t)];
+};
 int	nosys(struct thread *, struct nosys_args *);
 void	sys_sys_exit(struct thread *, struct sys_exit_args *);
 int	sys_fork(struct thread *, struct fork_args *);
@@ -2144,6 +2148,7 @@
 int	sys_posix_fallocate(struct thread *, struct posix_fallocate_args *);
 int	sys_posix_fadvise(struct thread *, struct posix_fadvise_args *);
 int	sys_wait6(struct thread *, struct wait6_args *);
+int	sys_utrace2(struct thread *, struct utrace2_args *);
 
 #ifdef COMPAT_43
 
@@ -2840,6 +2845,7 @@
 #define	SYS_AUE_posix_fallocate	AUE_NULL
 #define	SYS_AUE_posix_fadvise	AUE_NULL
 #define	SYS_AUE_wait6	AUE_WAIT6
+#define	SYS_AUE_utrace2	AUE_NULL
 
 #undef PAD_
 #undef PADL_
Index: usr.bin/kdump/kdump.c
===================================================================
--- usr.bin/kdump/kdump.c	(revision 244503)
+++ usr.bin/kdump/kdump.c	(working copy)
@@ -83,6 +83,8 @@
 #include "ktrace.h"
 #include "kdump_subr.h"
 
+struct utrace_malloc_v2;
+
 u_int abidump(struct ktr_header *);
 int fetchprocinfo(struct ktr_header *, u_int *);
 int fread_tail(void *, int, int);
@@ -96,9 +98,11 @@
 void ktrpsig(struct ktr_psig *);
 void ktrcsw(struct ktr_csw *);
 void ktrcsw_old(struct ktr_csw_old *);
-void ktruser_malloc(unsigned char *);
+void ktruser_malloc(struct utrace_malloc_v2 *, int);
 void ktruser_rtld(int, unsigned char *);
-void ktruser(int, unsigned char *);
+void ktruser(int, void *);
+void ktruser2(size_t, void *);
+void ktruser_data(size_t, unsigned char *);
 void ktrsockaddr(struct sockaddr *);
 void ktrstat(struct stat *);
 void ktrstruct(char *, size_t);
@@ -321,6 +325,9 @@
 		case KTR_FAULTEND:
 			ktrfaultend((struct ktr_faultend *)m);
 			break;
+		case KTR_USER2:
+			ktruser2(ktrlen, m);
+			break;
 		default:
 			printf("\n");
 			break;
@@ -469,6 +476,9 @@
 	case KTR_FAULTEND:
 		type = "PRET";
 		break;
+	case KTR_USER2:
+		type = "USR2";
+		break;
 	default:
 		sprintf(unknown, "UNKNOWN(%d)", kth->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 <stdio.h>
#include <stdlib.h>
#include <unistd.h>

#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--



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?50D52B10.1060205>