Merge pull request #178 from pythonspeed/170.debug-when-cant-free

More debug output, when can't free() for some reason.

.changelog/170.feature

@@ -0,0 +1 @@
+Improved debugging information when FIL_DEBUG is set.

filprofiler/_filpreload.c

@@ -392,7 +392,7 @@ SYMBOL_PREFIX(realloc)(void *addr, size_t size) {
   // existing but Fil thinking it's gone. However, at that point Fil will then
   // exit with OOM report, so... not the end of the world, and unlikely in
   // practice.
-  if (should_track_memory()) {
+  if (should_track_memory() && ((size_t)addr != 0)) {
     set_will_i_be_reentrant(1);
     // Sometimes you'll get same address, so if we did add first and then
     // removed, it would remove the entry erroneously.

memapi/Cargo.toml

@@ -13,6 +13,7 @@ itertools = "0.10.0"
 ahash = "0.7.0"
 derivative = "2.2.0"
 lazy_static = "1.4.0"
+backtrace = "0.3"
 
 [dependencies.inferno]
 version = "0.10.3"

memapi/src/memorytracking.rs

@@ -349,6 +349,10 @@ pub struct AllocationTracker {
     // Allocations that somehow disappeared. Not relevant for sampling profiler.
     #[cfg(not(feature = "production"))]
     missing_allocated_bytes: usize,
+
+    // free()/realloc() of unknown address. Not relevant for sampling profiler.
+    #[cfg(not(feature = "production"))]
+    failed_deallocations: usize,
 }
 
 impl<'a> AllocationTracker {
@@ -363,6 +367,7 @@ impl<'a> AllocationTracker {
             current_allocated_bytes: 0,
             peak_allocated_bytes: 0,
             missing_allocated_bytes: 0,
+            failed_deallocations: 0,
             default_path,
         }
     }
@@ -441,6 +446,14 @@ impl<'a> AllocationTracker {
                         "The allocation from this traceback disappeared:",
                         previous.callstack_id,
                     );
+                    self.print_traceback(
+                        "The current traceback that overwrote the disappearing allocation:",
+                        alloc.callstack_id,
+                    );
+                    eprintln!(
+                        "|= The current C/Rust backtrace: {:?}",
+                        backtrace::Backtrace::new()
+                    );
                 }
             }
         }
@@ -452,12 +465,21 @@ impl<'a> AllocationTracker {
         // Before we reduce memory, let's check if we've previously hit a peak:
         self.check_if_new_peak();
 
-        // Possibly this allocation doesn't exist; that's OK! It can if e.g. we
-        // didn't capture an allocation for some reason.
         if let Some(removed) = self.current_allocations.remove(&address) {
             self.remove_memory_usage(removed.callstack_id, removed.size());
             Some(removed.size())
         } else {
+            // This allocation doesn't exist; often this will be something
+            // allocated before Fil tracking was started, but it might also be a
+            // bug.
+            #[cfg(not(feature = "production"))]
+            if *crate::util::DEBUG_MODE {
+                self.failed_deallocations += 1;
+                eprintln!(
+                    "=fil-profile= Your program attempted to free an allocation at an address we don't know about:"
+                );
+                eprintln!("=| {:?}", backtrace::Backtrace::new());
+            }
             None
         }
     }
@@ -552,6 +574,9 @@ impl<'a> AllocationTracker {
             if self.missing_allocated_bytes > 0 {
                 eprintln!("=fil-profile= WARNING: {:.2}% ({} bytes) of tracked memory somehow disappeared. If this is a small percentage you can just ignore this warning, since the missing allocations won't impact the profiling results. If the % is high, please run `export FIL_DEBUG=1` to get more output', re-run Fil on your script, and then file a bug report at https://github.com/pythonspeed/filprofiler/issues/new", self.missing_allocated_bytes as f64 * 100.0 / allocated_bytes as f64, self.missing_allocated_bytes);
             }
+            if self.failed_deallocations > 0 {
+                eprintln!("=fil-profile= WARNING: Encountered {} deallocations of untracked allocations. A certain number are expected in normal operation, of allocations created before Fil started tracking, and even more if you're using the Fil API to turn tracking on and off.", self.failed_deallocations);
+            }
         }
 
         eprintln!("=fil-profile= Preparing to write to {}", path);