The dot in ... --- ...
Chris Gerhard's Weblog
Thursday September 10, 2009
Using dtrace to find double frees Some of the most common failures that result in customer calls are misuses of the memory allocation routines, malloc, calloc, realloc, valloc, memalign and free. There are many ways in which you can misuse these routines and the data that they return and the resulting failures often occur within the routines even though the problem is with the calling program.
I'm not going to discuss here all the ways you can abuse these routines but look at a particular type abuse. The double free. When you allocate memory using these routines it is your responsibility to free it again so that the memory does not “leak”. However you must only free the memory once. Freeing it more than once is a bug and the results of that are undefined.
This very simple code has a double free:
#include <stdlib.h>
void
doit(int n, char *x)
{
if (n-- == 0)
free(x);
else
doit(n,x);
}
int
main(int argc, char **argv)
{
char *x;
char *y;
x = malloc(100000);
doit(3, x);
doit(10, x);
}and if you compile and run that program all appears well;
However a more realistic program could go on to fail in interesting ways leaving you with the difficult task of finding the culprit. It is for that reason the libumem has good checking for double frees:
: exdev.eu FSS 26 $; LD_PRELOAD=libumem.so.1 /home/cg13442/lang/c/double_free Abort(coredump) : exdev.eu FSS 27 $; mdb core Loading modules: [ libumem.so.1 libc.so.1 ld.so.1 ] > ::status debugging core file of double_free (64-bit) from exdev file: /home/cg13442/lang/c/double_free initial argv: /home/cg13442/lang/c/double_free threading model: native threads status: process terminated by SIGABRT (Abort), pid=18108 uid=14442 code=-1 > ::umem_status Status: ready and active Concurrency: 16 Logs: (inactive) Message buffer: free(e53650): double-free or invalid buffer stack trace: libumem.so.1'umem_err_recoverable+0xa6 libumem.so.1'process_free+0x17e libumem.so.1'free+0x16 double_free'doit+0x3a double_free'doit+0x4d double_free'doit+0x4d double_free'doit+0x4d double_free'doit+0x4d double_free'doit+0x4d double_free'doit+0x4d double_free'doit+0x4d double_free'doit+0x4d double_free'doit+0x4d double_free'doit+0x4d double_free'main+0x100 double_free'_start+0x6c >
Good though this is there are situations when libumem is not used and others where it can't be used1. In those cases it is useful to be able to use dtrace to do this and any way it is always nice to have more than one arrow in your quiver:
: exdev.eu FSS 54 $; me/cg13442/lang/c/double_free 2> /dev/null <
/usr/sbin/dtrace -qs doublefree.d -c /home/cg13442/lang/c/double_free 2> /dev/null
Hit Control-C to stop tracing
double free?
Address: 0xe53650
Previous free at: 2009 Jun 23 12:23:22, LWP -1
This free at: 2009 Jun 23 12:23:22, LWP -1
Frees 42663 nsec apart
Allocated 64474 nsec ago by LWP -1
libumem.so.1`free
double_free`doit+0x3a
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
: exdev.eu FSS 56 $;
If run as root you can get the the real LWP values that did the allocation and the frees:
: exdev.eu FSS 63 $; pfexec /usr/sbin/dtrace -qs doublefree.d -c /home/cg1344>
Hit Control-C to stop tracing
double free?
Address: 0xe53650
Previous free at: 2009 Jun 23 14:21:29, LWP 1
This free at: 2009 Jun 23 14:21:29, LWP 1
Frees 27543 nsec apart
Allocated 39366 nsec ago by LWP 1
libumem.so.1`free
double_free`doit+0x3a
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
double_free`doit+0x4d
: exdev.eu FSS 64 $;Here is the script in all it's glory.
#!/usr/sbin/dtrace -qs
BEGIN
{
printf("Hit Control-C to stop tracing\n");
}
ERROR
/ arg4 == DTRACEFLT_KPRIV || arg4 == DTRACEFLT_UPRIV /
{
lwp = -1;
}
pid$target::realloc:entry,
pid$target::free:entry
{
self->addr = arg0;
self->recurse++;
}
pid$target::realloc:return,
pid$target::free:return
/ self->recurse /
{
self->recurse--;
self->addr = 0;
}
pid$target::malloc:entry,
pid$target::memalign:entry,
pid$target::valloc:entry,
pid$target::calloc:entry,
pid$target::realloc:entry,
pid$target::realloc:entry,
pid$target::free:entry
/ lwp != -1 && self->lwp == 0 /
{
self->lwp = curlwpsinfo->pr_lwpid;
}
pid$target::malloc:entry,
pid$target::calloc:entry,
pid$target::realloc:entry,
pid$target::memalign:entry,
pid$target::valloc:entry,
pid$target::free:entry
/ self->lwp == 0 /
{
self->lwp = lwp;
}
pid$target::malloc:return,
pid$target::calloc:return,
pid$target::realloc:return,
pid$target::memalign:return,
pid$target::valloc:return
{
alloc_time[arg1] = timestamp;
allocated[arg1] = 1;
free_walltime[arg1] = 0LL;
free_time[arg1] = 0LL;
free_lwpid[arg1] = 0;
alloc_lwpid[arg1] = self->lwp;
self->lwp = 0;
}
pid$target::realloc:entry,
pid$target::free:entry
/ self->recurse == 1 && alloc_time[arg0] && allocated[arg0] == 0 /
{
printf("double free?\n");
printf("\tAddress: 0x%p\n", arg0);
printf("\tPrevious free at: %Y, LWP %d\n", free_walltime[arg0],
free_lwpid[arg0]);
printf("\tThis free at: %Y, LWP %d\n", walltimestamp,
self->lwp);
printf("\tFrees %d nsec apart\n", timestamp - free_time[arg0]);
printf("\tAllocated %d nsec ago by LWP %d\n",
timestamp - alloc_time[arg0], alloc_lwpid[arg0]);
ustack(10);
}
pid$target::realloc:entry,
pid$target::free:entry
/ self->recurse == 1 && alloc_time[arg0] && allocated[arg0] == 1 /
{
free_walltime[arg0] = walltimestamp;
free_time[arg0] = timestamp;
free_lwpid[arg0] = self->lwp;
allocated[arg0] = 0;
}
pid$target::free:entry
/self->lwp && self->recurse == 0/
{
self->lwp = 0;
}
1Most of the cases it “can't” be used is because it finds fatal problems early on in the start up of applications. Then the application writers make bizarre claims that this is a problem with libumem and will tell you it is not supported with their app. In fact the problem is with the application.
( Sep 10 2009, 12:31:28 PM BST ) Permalink Trackback
Tuesday June 30, 2009
Using dtrace to track down memory leaks I've been working with a customer to try and find a memory “leak” in their application. Many things have been tried, libumem, and the mdb ::findleaks command all with no success.
So I was, as I am sure others before me have, pondering if you could use dtrace to do this. Well I think you can. I have a script that puts probes into malloc et al and counts how often they are called by this thread and when they are freed often free is called.
Then in the entry probe of the target application note away how many calls there have been to the allocators and how many to free and with a bit of care realloc. Then in the return probe compare the number of calls to allocate and free with the saved values and aggregate the results. The principle is that you find the routines that are resulting in allocations that they don't clear up. This should give you a list of functions that are possible leakers which you can then investigate1.
Using the same technique I for getting dtrace to “follow fork” that I described here I ran this up on diskomizer, a program that I understand well and I'm reasonably sure does not have systemic memory leaks. The dtrace script reports three sets of results.
A count of how many times each routine and it's descendents have called a memory allocator.
A count of how many times each routine and it's descendents have called free or realloc with a non NULL pointer as the first argument.
The difference between the two numbers above.
Then with a little bit of nawk to remove all the functions for which the counts are zero gives:
# /usr/sbin/dtrace -Z -wD TARGET_OBJ=diskomizer2 -o /tmp/out-us \ -s /tmp/followfork.d \ -Cs /tmp/allocated.d -c \ "/opt/SUNWstc-diskomizer/bin/sparcv9/diskomizer -f /devs -f background \ -o background=0 -o SECONDS_TO_RUN=1800" dtrace: failed to compile script /tmp/allocated.d: line 20: failed to create entry probe for 'realloc': No such process dtrace: buffer size lowered to 25m dtrace: buffer size lowered to 25m dtrace: buffer size lowered to 25m dtrace: buffer size lowered to 25m # nawk '$1 != 0 { print $0 }' < /tmp/out.3081 allocations 1 diskomizer`do_dev_control 1 diskomizer`set_dev_state 1 diskomizer`set_state 3 diskomizer`report_exit_reason 6 diskomizer`alloc_time_str 6 diskomizer`alloc_time_str_fmt 6 diskomizer`update_aio_read_stats 7 diskomizer`cancel_all_io 9 diskomizer`update_aio_write_stats 13 diskomizer`cleanup 15 diskomizer`update_aio_time_stats 15 diskomizer`update_time_stats 80 diskomizer`my_calloc 240 diskomizer`init_read 318 diskomizer`do_restart_stopped_devices 318 diskomizer`start_io 449 diskomizer`handle_write 606 diskomizer`do_new_write 2125 diskomizer`handle_read_then_write 2561 diskomizer`init_buf 2561 diskomizer`set_io_len 58491 diskomizer`handle_read 66255 diskomizer`handle_write_then_read 124888 diskomizer`init_read_buf 124897 diskomizer`do_new_read 127460 diskomizer`expect_signal freecount 1 diskomizer`expect_signal 3 diskomizer`report_exit_reason 4 diskomizer`close_and_free_paths 6 diskomizer`update_aio_read_stats 9 diskomizer`update_aio_write_stats 11 diskomizer`cancel_all_io 15 diskomizer`update_aio_time_stats 15 diskomizer`update_time_stats 17 diskomizer`cleanup 160 diskomizer`init_read 318 diskomizer`do_restart_stopped_devices 318 diskomizer`start_io 442 diskomizer`handle_write 599 diskomizer`do_new_write 2125 diskomizer`handle_read_then_write 2560 diskomizer`init_buf 2560 diskomizer`set_io_len 58491 diskomizer`handle_read 66246 diskomizer`handle_write_then_read 124888 diskomizer`do_new_read 124888 diskomizer`init_read_buf 127448 diskomizer`cancel_expected_signal mismatch_count -127448 diskomizer`cancel_expected_signal -4 diskomizer`cancel_all_io -4 diskomizer`cleanup -4 diskomizer`close_and_free_paths 1 diskomizer`do_dev_control 1 diskomizer`init_buf 1 diskomizer`set_dev_state 1 diskomizer`set_io_len 1 diskomizer`set_state 6 diskomizer`alloc_time_str 6 diskomizer`alloc_time_str_fmt 7 diskomizer`do_new_write 7 diskomizer`handle_write 9 diskomizer`do_new_read 9 diskomizer`handle_write_then_read 80 diskomizer`init_read 80 diskomizer`my_calloc 127459 diskomizer`expect_signal #
From the above you can see that there are two functions that create and free the majority of the allocations and the allocations almost match each other, which is expected as they are effectively constructor and destructor for each other. The small mismatch is not unexpected in this context.
However it is the vast number of functions that are not listed at all as they and their children make no calls to the memory allocator or have exactly matching allocation and free that are important here. Those are the functions that we have just ruled out.
From here it is easy now to drill down on the functions that are interesting you, ie the ones where there are unbalanced allocations.
I've uploaded the files allocated.d and followfork.d so you can see the details. If you find it useful then let me know.
1Unfortunately the list is longer than you want as on SPARC it includes any functions that don't have their own stack frame due to the way dtrace calculates ustackdepth, which the script makes use of.
2The script only probes particular objects, in this case the main diskomizer binary, but you can limit it to a particular library or even a particular set of entry points based on name if you edit the script.
( Jun 30 2009, 12:14:33 PM BST ) Permalink Trackback
Friday November 23, 2007
Memory upgrade With the addition of the photo frame and a second Sun Ray the home server was beginning to struggle. The ideal (realistic) solution would be a multi core CPU but the lack of power management on those, at least the ones that will fit in the existing system, puts me off. However since most of the performance issues have been due to lack of memory there was a way out.
If you recall the motherboard in the system is ASUS M2NPV-VM which has four memory slots, however the system was supplied with a Zalman 8000 Low Profile Cooler which interferes with one memory slot reducing the number of available slots to 2 (the slots have to be used in pairs). The reason given for the optional cooler is to make the system quieter. So the only ways to increase the memory would be to replace the existing DIMMS with larger 2G DIMMS or swap the CPU fan for the default one, which I still have, and then add the extra memory. The alternative would be to unteach the family that it is OK just to pull your card out of the system when you walk away, now what is the fun of that?
It seems like a no brainer to me. I can always put the system in another room so the noise does not get me down.
So I have now added 4G of RAM, giving 6G total and put the AMD cooler on the system, so far so good:
Last login: Fri Nov 23 17:37:41 2007 from gmp-ea-fw-1.sun
Sun Microsystems Inc. SunOS 5.11 snv_78 October 2007
: pearson FSS 1 $; prtconf | head -3
System Configuration: Sun Microsystems i86pc
Memory size: 6111 Megabytes
System Peripherals (Software Nodes):
: pearson FSS 2 $; batstat -t
Thermal zone: \_TZ_.THRM, temperature = 40C, critical = 75C
Active Cooling: 73
: pearson FSS 3 $;
Once again battling with the hardware really brought home just how fantastic the designs of Sun hardware is. This could have been designed by Citroen1 given how difficult it is to replace bits. Even if I had not had to remove the CPU fan to add the memory I still would have had to remove all the disks, the main power supply the fan power cable just to add a DIMM.
What is surprising is that the system is very much quieter now than is used to be and even with the original AMD fan.
1 I once, well twice owned and or leased Citroen Xantia cars. While driving up the motorway on the way home one day, the day after it had been serviced, the “stop or you will die” light came on on the dashboard as the engine started making some alarming noises. So I pull over sharpish onto the hard shoulder and pop the bonnet and take a look. No problem spotting the issue. One of the spark plugs had come out, still attached to the high tension lead. I make a mental note not to return to that garage the service the car but am not that worried. I have a tool kit in the boot and so can just refit the spark plug and be on my way. That is until I see where the plug has come from , a deep deep whole which those cunning French engineers have made so difficult to access that a normal spark plug socket won't fit down there. I ring the AA, thankful that I am a member and wait. I did not have to wait long. I explain to the AA man who looks at me as if I am a fool, possibly I am, after all I am the one driving, or not, the Citroen and he says the immortal words: “No problem, I'll have you going in 2 minutes”. 30 minutes later he has managed to get the sparc plug in but not tight but the car will run so he follows me to a Citroen garage who did indeed have the special tool required to fit spark plugs and also employed a double jointed Frenchman (he may not actually have been French, but you get the picture) capable of using them. Suffice to say the phrase “ease of maintenance” and “Citroen cars” are not ones you will often hear together, unless there is also the word “nightmare” in the sentence. That said this was the first of my Citroens so it did not put me off. Though now I think about it the last car was replaced by a bike.
( Nov 23 2007, 06:18:01 PM GMT ) Permalink Trackback
Except where otherwise noted, this site is
licensed under a Creative Commons License 2.0
This is a personal weblog, I do not speak for my employer.
