gen/stack_logging.c

   1 /*
   2  * Copyright (c) 1999, 2000, 2002-2008 Apple Inc. All rights reserved.
   3  *
   4  * @APPLE_LICENSE_HEADER_START@
   5  *
   6  * This file contains Original Code and/or Modifications of Original Code
   7  * as defined in and that are subject to the Apple Public Source License
   8  * Version 2.0 (the 'License'). You may not use this file except in
   9  * compliance with the License. Please obtain a copy of the License at
  10  * http://www.opensource.apple.com/apsl/ and read it before using this
  11  * file.
  12  *
  13  * The Original Code and all software distributed under the License are
  14  * distributed on an 'AS IS' basis, WITHOUT WARRANTY OF ANY KIND, EITHER
  15  * EXPRESS OR IMPLIED, AND APPLE HEREBY DISCLAIMS ALL SUCH WARRANTIES,
  16  * INCLUDING WITHOUT LIMITATION, ANY WARRANTIES OF MERCHANTABILITY,
  17  * FITNESS FOR A PARTICULAR PURPOSE, QUIET ENJOYMENT OR NON-INFRINGEMENT.
  18  * Please see the License for the specific language governing rights and
  19  * limitations under the License.
  20  *
  21  * @APPLE_LICENSE_HEADER_END@
  22  */
  23
  24 /*      Bertrand from vmutils -> CF -> System */
  25
  26 #import "stack_logging.h"
  27 #import "malloc_printf.h"
  28
  29 #import <libc.h>
  30 #import <pthread.h>
  31 #import <mach/mach.h>
  32 #include <mach/vm_statistics.h>
  33 #import <malloc/malloc.h>
  34 #import <stdlib.h>
  35 #import <CrashReporterClient.h>
  36
  37 extern void spin_lock(int *);
  38 extern void spin_unlock(int *);
  39 extern void thread_stack_pcs(vm_address_t *, unsigned, unsigned *);
  40
  41 static inline void *allocate_pages(unsigned) __attribute__((always_inline));
  42 static inline void *allocate_pages(unsigned bytes) {
  43     void *address;
  44     if (vm_allocate(mach_task_self(), (vm_address_t *)&address, bytes,
  45                     VM_MAKE_TAG(VM_MEMORY_ANALYSIS_TOOL)| TRUE)) {
  46         malloc_printf("*** out of memory while stack logging\n");
  47         CRSetCrashLogMessage("*** out of memory while stack logging\n");
  48         abort();
  49     }
  50     return (void *)address;
  51 }
  52
  53 static inline void deallocate_pages(void *, unsigned) __attribute__((always_inline));
  54 static inline void deallocate_pages(void *ptr, unsigned bytes) {
  55     vm_deallocate(mach_task_self(), (vm_address_t)ptr, bytes);
  56 }
  57
  58 static inline void copy_pages(const void *, void *, unsigned) __attribute__((always_inline));
  59 static inline void copy_pages(const void *source, void *dest, unsigned bytes) {
  60     if (vm_copy(mach_task_self(), (vm_address_t)source, bytes, (vm_address_t)dest)) memmove(dest, source, bytes);
  61 }
  62
  63 /***************        Uniquing stack          ***********/
  64
  65 #define MAX_COLLIDE     8
  66
  67 #define MAX_NUM_PC      512
  68
  69 static int enter_pair_in_table(unsigned *table, unsigned numPages, unsigned *uniquedParent, unsigned thisPC) {
  70     // uniquedParent is in-out; return 1 is collisions max not exceeded
  71     unsigned    base = numPages * vm_page_size / (sizeof(int)*2*2);
  72     unsigned    hash = base + (((*uniquedParent) << 4) ^ (thisPC >> 2)) % (base - 1); // modulo odd number for hashing
  73     unsigned    collisions = MAX_COLLIDE;
  74     while (collisions--) {
  75         unsigned        *head = table + hash*2;
  76         if (! head[0] && !head[1]) {
  77             /* end of chain; store this entry! */
  78             /* Note that we need to test for both head[0] and head[1] as (0, -1) is a valid entry */
  79             head[0] = thisPC;
  80             head[1] = *uniquedParent;
  81             *uniquedParent = hash;
  82             return 1;
  83         }
  84         if ((head[0] == thisPC) && (head[1] == *uniquedParent)) {
  85             /* we found the proper entry, the value for the pair is the entry offset */
  86             *uniquedParent = hash;
  87             return 1;
  88         }
  89         hash++;
  90         if (hash == base*2) hash = base;
  91     }
  92     return 0;
  93 }
  94
  95 unsigned stack_logging_get_unique_stack(unsigned **table, unsigned *table_num_pages, unsigned *stack_entries, unsigned count, unsigned num_hot_to_skip) {
  96     unsigned    uniquedParent = (unsigned)-1;
  97     // we skip the warmest entries that are an artefact of the code
  98     while (num_hot_to_skip--) {
  99         if (count > 0) { stack_entries++; count--; }
 100     }
 101     while (count--) {
 102         unsigned        thisPC = stack_entries[count];
 103         while (!enter_pair_in_table(*table, *table_num_pages, &uniquedParent, thisPC)) {
 104             unsigned    *newTable;
 105             unsigned    oldBytes = (*table_num_pages) * vm_page_size;
 106             newTable = allocate_pages(oldBytes*2);
 107             copy_pages(*table, newTable, oldBytes);
 108             deallocate_pages(*table, oldBytes);
 109             *table_num_pages *= 2;
 110             *table = newTable;
 111         }
 112     }
 113     return uniquedParent;
 114 }
 115
 116 /***************        Logging stack and arguments             ***********/
 117
 118 stack_logging_record_list_t *stack_logging_the_record_list = NULL;
 119
 120 int stack_logging_enable_logging = 0;
 121 int stack_logging_dontcompact = 0;
 122 int stack_logging_finished_init = 0;
 123 int stack_logging_postponed = 0;
 124
 125 static int stack_logging_spin_lock = 0;
 126
 127 static stack_logging_record_list_t *GrowLogRecords(stack_logging_record_list_t *records, unsigned desiredNumRecords) {
 128     stack_logging_record_list_t *new_records;
 129     unsigned    old_size = records->overall_num_bytes;
 130     if (desiredNumRecords*sizeof(stack_logging_record_t)+sizeof(stack_logging_record_list_t) < records->overall_num_bytes) return records;
 131     records->overall_num_bytes += records->overall_num_bytes + vm_page_size; // in order to always get an even number of pages
 132     new_records = allocate_pages(records->overall_num_bytes);
 133     copy_pages(records, new_records, old_size);
 134     deallocate_pages(records, old_size);
 135     return new_records;
 136 }
 137
 138 static void prepare_to_log_stack(void) {
 139     if (!stack_logging_the_record_list) {
 140         unsigned        totalSize = 4 * vm_page_size;
 141         stack_logging_the_record_list = allocate_pages(totalSize);
 142         memset(stack_logging_the_record_list, 0, sizeof(stack_logging_record_list_t));
 143         stack_logging_the_record_list->overall_num_bytes = totalSize;
 144         stack_logging_the_record_list->uniquing_table_num_pages = 128;
 145         stack_logging_the_record_list->uniquing_table = allocate_pages(stack_logging_the_record_list->uniquing_table_num_pages * vm_page_size);
 146     }
 147 }
 148
 149 void stack_logging_log_stack(unsigned type, unsigned arg1, unsigned arg2, unsigned arg3, unsigned result, unsigned num_hot_to_skip) {
 150     stack_logging_record_t      *rec;
 151     if (!stack_logging_enable_logging) return;
 152     // printf("stack_logging_log_stack 0x%x 0x%x 0x%x 0x%x -> 0x%x\n", type, arg1, arg2, arg3, result);
 153     if (type & stack_logging_flag_zone) {
 154         // just process it now and be done with it!
 155         arg1 = arg2; arg2 = arg3; arg3 = 0; type &= ~stack_logging_flag_zone;
 156     }
 157     if (type & stack_logging_flag_calloc) {
 158         // just process it now and be done with it!
 159         arg1 *= arg2; arg2 = arg3; arg3 = 0; type &= ~stack_logging_flag_calloc;
 160     }
 161     if (type & stack_logging_flag_object) {
 162         unsigned        *class = (unsigned *)(uintptr_t)arg1;
 163         arg1 = arg2 + class[5]; // corresponds to the instance_size field
 164         arg2 = 0; arg3 = 0; type = stack_logging_type_alloc;
 165     }
 166     if (type & stack_logging_flag_cleared) {
 167         type &= ~stack_logging_flag_cleared;
 168     }
 169     if (type & stack_logging_flag_handle) {
 170         if (stack_logging_type_alloc) {
 171             if (!result) return;
 172             stack_logging_log_stack(stack_logging_type_alloc, 0, 0, 0, result, num_hot_to_skip+1);
 173             stack_logging_log_stack(stack_logging_type_alloc, arg1, 0, 0, *((int *)(uintptr_t)result), num_hot_to_skip+1);
 174             return;
 175         }
 176         if (stack_logging_type_dealloc) {
 177             if (!arg1) return;
 178             stack_logging_log_stack(stack_logging_type_dealloc, *((int *)(uintptr_t)arg1), 0, 0, 0, num_hot_to_skip+1);
 179             stack_logging_log_stack(stack_logging_type_dealloc, arg1, 0, 0, 0, num_hot_to_skip+1);
 180             return;
 181         }
 182         fprintf(stderr, "*** Unknown logging type: 0x%x\n", type);
 183     }
 184     if (type == stack_logging_flag_set_handle_size) {
 185         if (!arg1) return;
 186         // Thanks to a horrible hack, arg3 contains the prvious handle value
 187         if (arg3 == *((int *)(uintptr_t)arg1)) return;
 188         stack_logging_log_stack(stack_logging_type_dealloc, arg3, 0, 0, 0, num_hot_to_skip+1);
 189         stack_logging_log_stack(stack_logging_type_alloc, arg2, 0, 0, *((int *)(uintptr_t)arg1), num_hot_to_skip+1);
 190         return;
 191     }
 192     if (type == (stack_logging_type_dealloc|stack_logging_type_alloc)) {
 193         if (arg1 == result) return; // realloc had no effect, skipping
 194         if (!arg1) {
 195             // realloc(NULL, size) same as malloc(size)
 196             type = stack_logging_type_alloc; arg1 = arg2; arg2 = arg3; arg3 = 0;
 197         } else {
 198             // realloc(arg1, arg2) -> result is same as free(arg1); malloc(arg2) -> result
 199             stack_logging_log_stack(stack_logging_type_dealloc, arg1, 0, 0, 0, num_hot_to_skip+1);
 200             stack_logging_log_stack(stack_logging_type_alloc, arg2, 0, 0, result, num_hot_to_skip+1);
 201             return;
 202         }
 203     }
 204     if (type == stack_logging_type_dealloc) {
 205         // simple free
 206         if (!arg1) return; // free(nil)
 207     }
 208     prepare_to_log_stack();
 209     spin_lock(&stack_logging_spin_lock);
 210     stack_logging_the_record_list = GrowLogRecords(stack_logging_the_record_list, stack_logging_the_record_list->num_records + 1);
 211     rec = stack_logging_the_record_list->records + stack_logging_the_record_list->num_records;
 212     // We take care of the common case of alloc-dealloc
 213     if (!stack_logging_dontcompact && stack_logging_the_record_list->num_records && (type == stack_logging_type_dealloc) && arg1 && ((rec-1)->type == stack_logging_type_alloc) && (arg1 == STACK_LOGGING_DISGUISE((rec-1)->address))) {
 214         stack_logging_the_record_list->num_records--;
 215         // printf("Erased previous record in alloc-dealloc sequence\n");
 216     } else {
 217         unsigned        stack_entries[MAX_NUM_PC];
 218         unsigned        count = 0;
 219         rec->type = type;
 220         if (type == stack_logging_type_dealloc) {
 221             rec->argument = 0;
 222             rec->address = STACK_LOGGING_DISGUISE(arg1); // we disguise the address
 223         } else if (type == stack_logging_type_alloc) {
 224             rec->argument = arg1;
 225             rec->address = STACK_LOGGING_DISGUISE(result); // we disguise the address
 226         } else {
 227             rec->argument = arg2;
 228             rec->address = STACK_LOGGING_DISGUISE(arg1); // we disguise the address
 229         }
 230         // printf("Before getting samples  0x%x 0x%x 0x%x 0x%x -> 0x%x\n", type, arg1, arg2, arg3, result);
 231         thread_stack_pcs((vm_address_t *)stack_entries, MAX_NUM_PC - 1, &count);
 232         // We put at the bottom of the stack a marker that denotes the thread (+1 for good measure...)
 233         stack_entries[count++] = (int)(uintptr_t)pthread_self() + 1;
 234         /* now let's unique the sample */
 235         // printf("Uniquing 0x%x 0x%x 0x%x 0x%x -> 0x%x\n", type, arg1, arg2, arg3, result);
 236         rec->uniqued_stack = stack_logging_get_unique_stack(&stack_logging_the_record_list->uniquing_table, &stack_logging_the_record_list->uniquing_table_num_pages, stack_entries, count, num_hot_to_skip+2); // we additionally skip the warmest 2 entries that are an artefact of the code
 237         stack_logging_the_record_list->num_records++;
 238     }
 239     spin_unlock(&stack_logging_spin_lock);
 240 }
 241
 242 static kern_return_t default_reader(task_t task, vm_address_t address, vm_size_t size, void **ptr) {
 243     *ptr = (void *)address;
 244     return 0;
 245 }
 246
 247 static kern_return_t get_remote_records(task_t task, memory_reader_t reader, stack_logging_record_list_t **records) {
 248     // sets records
 249     vm_address_t        *remote_records_address_ref;
 250     kern_return_t       err;
 251     *records = NULL;
 252     err = reader(task, (vm_address_t)&stack_logging_the_record_list, sizeof(vm_address_t), (void **)&remote_records_address_ref);
 253     if (err) return err;
 254     if (!*remote_records_address_ref) {
 255         // printf("stack_logging: no stack record\n");
 256         return 0;
 257     }
 258     // printf("stack_logging: stack records at %p\n", (void *)(*remote_records_address_ref));
 259     // printf("stack_logging: reading %d bytes\n", sizeof(stack_logging_record_list_t));
 260     err = reader(task, *remote_records_address_ref, sizeof(stack_logging_record_list_t), (void **)records); // get the list head
 261     if (err) return err;
 262     // printf("stack_logging: overall num bytes = %d\n", records->overall_num_bytes);
 263     return reader(task, *remote_records_address_ref, (*records)->overall_num_bytes, (void **)records);
 264 }
 265
 266 kern_return_t stack_logging_get_frames(task_t task, memory_reader_t reader, vm_address_t address, vm_address_t *stack_frames_buffer, unsigned max_stack_frames, unsigned *num_frames) {
 267     stack_logging_record_list_t *records;
 268     kern_return_t       err;
 269     unsigned            index;
 270     unsigned            disguised = STACK_LOGGING_DISGUISE(address);
 271     if (!reader) reader = default_reader;
 272     *num_frames = 0;
 273     err = get_remote_records(task, reader, &records);
 274     if (err || !records) return err;
 275     // printf("stack_logging: %d records\n", records->num_records);
 276     index = 0;
 277     while (index < records->num_records) {
 278         stack_logging_record_t  *record = records->records + index;
 279         if (record->address == disguised) {
 280             return stack_logging_frames_for_uniqued_stack(task, reader, record->uniqued_stack, stack_frames_buffer, max_stack_frames, num_frames);
 281         }
 282         index++;
 283     }
 284     fprintf(stderr, "*** stack_logging: no record found for %p\n", address);
 285     return 0;
 286 }
 287
 288 kern_return_t stack_logging_enumerate_records(task_t task, memory_reader_t reader, vm_address_t address, void enumerator(stack_logging_record_t, void *), void *context) {
 289     stack_logging_record_list_t *records;
 290     kern_return_t       err;
 291     unsigned            index;
 292     unsigned            disguised = STACK_LOGGING_DISGUISE(address);
 293     if (!reader) reader = default_reader;
 294     err = get_remote_records(task, reader, &records);
 295     if (err || !records) return err;
 296     // printf("stack_logging: %d records\n", records->num_records);
 297     index = 0;
 298     while (index < records->num_records) {
 299         stack_logging_record_t  *record = records->records + index;
 300         if (!address || (record->address == disguised)) enumerator(*record, context);
 301         index++;
 302     }
 303     return 0;
 304 }
 305
 306 kern_return_t stack_logging_frames_for_uniqued_stack(task_t task, memory_reader_t reader, unsigned uniqued_stack, vm_address_t *stack_frames_buffer, unsigned max_stack_frames, unsigned *num_frames) {
 307     stack_logging_record_list_t *records;
 308     unsigned            *uniquing_table;
 309     kern_return_t       err;
 310     if (!reader) reader = default_reader;
 311     *num_frames = 0;
 312     err = get_remote_records(task, reader, &records);
 313     if (err || !records) return err;
 314     err = reader(task, (vm_address_t)records->uniquing_table, records->uniquing_table_num_pages * vm_page_size, (void **)&uniquing_table);
 315     if (err) return err;
 316     while (max_stack_frames && (uniqued_stack != -1)) {
 317         unsigned        thisPC;
 318         if ((uniqued_stack * 2 + 1) * sizeof(unsigned) >= records->uniquing_table_num_pages * vm_page_size) {
 319             fprintf(stderr, "*** stack_logging: Invalid uniqued stack 0x%x", uniqued_stack);
 320             break;
 321         }
 322         thisPC = uniquing_table[uniqued_stack * 2];
 323         uniqued_stack = uniquing_table[uniqued_stack * 2 + 1];
 324         if (!thisPC && !uniqued_stack) {
 325             // Invalid entry
 326             fprintf(stderr, "*** stack_logging: Invalid entry 0x%x", thisPC);
 327             break;
 328         }
 329         stack_frames_buffer[0] = thisPC;
 330         stack_frames_buffer++;
 331         (*num_frames)++;
 332         max_stack_frames--;
 333     }
 334     return 0;
 335 }