wip: count sigprof/samples/matches to find where rust samples vanish

Author: emeryberger

.github/workflows/ci.yml

@@ -333,30 +333,18 @@ jobs:
     - name: DIAGNOSE (temporary)
       if: runner.os == 'Linux'
       run: |
-        sudo apt-get install -y -qq strace >/dev/null
-        COUNT='import json,collections,sys; t=collections.Counter(json.loads(l)["type"] for l in open(sys.argv[1]) if l.strip()); print("   ", dict(t))'
+        echo "##### rust toy: where do the samples go?"
+        COZ_DEBUG_SAMPLES=1 timeout 120 ./coz run -o /tmp/r.jsonl --- ./rust/target/release/examples/toy 2>&1 | grep coz-dbg || echo "  (no coz-dbg line)"
 
-        echo "##### 1. C toy in THIS job (control: is the environment sane?)"
+        echo "##### C toy, same instrumentation, for comparison"
         g++ -g -O2 -c benchmarks/toy/toy.cpp -Iinclude -o /tmp/t.o
         g++ -g /tmp/t.o -o /tmp/ctoy -ldl -lpthread
-        timeout 150 ./coz run -o /tmp/c.jsonl --- /tmp/ctoy >/dev/null 2>&1 || true
-        python3 -c "$COUNT" /tmp/c.jsonl || echo "    C toy: no profile"
-
-        echo "##### 2. does perf_event_open succeed for the Rust toy?"
-        strace -f -qq -e trace=perf_event_open -o /tmp/st.txt ./coz run -o /tmp/s.jsonl --- ./rust/target/release/examples/toy >/dev/null 2>&1 || true
-        echo "  perf_event_open calls: $(grep -c perf_event_open /tmp/st.txt || true)"
-        echo "  failing calls:"; grep perf_event_open /tmp/st.txt | grep -E '= -1' | head -3 | sed 's/^/    /' || true
-        echo "  first call:"; grep perf_event_open /tmp/st.txt | head -1 | sed 's/^/    /' || true
-        python3 -c "$COUNT" /tmp/s.jsonl || echo "    no profile"
-
-        echo "##### 3. profiler lifecycle (verbose, captured to a file)"
-        timeout 120 ./coz run --verbose -o /tmp/v.jsonl --- ./rust/target/release/examples/toy >/tmp/v.txt 2>&1 || true
-        grep -aE 'Profiler thread|Registered thread|Starting sampling|startup complete' /tmp/v.txt | head -8 | sed 's/^/  /' || true
-        python3 -c "$COUNT" /tmp/v.jsonl || echo "    no profile"
-
-        echo "##### 4. C toy under strace, for comparison"
-        strace -f -qq -e trace=perf_event_open -o /tmp/st2.txt ./coz run -o /tmp/c2.jsonl --- /tmp/ctoy >/dev/null 2>&1 || true
-        echo "  C toy perf_event_open calls: $(grep -c perf_event_open /tmp/st2.txt || true)"
+        COZ_DEBUG_SAMPLES=1 timeout 120 ./coz run -o /tmp/c.jsonl --- /tmp/ctoy 2>&1 | grep coz-dbg || echo "  (no coz-dbg line)"
+
+        echo "##### is toy.rs actually in scope?"
+        timeout 30 ./coz run --verbose -o /tmp/v.jsonl --- /bin/true 2>&1 | head -2 || true
+        timeout 60 ./coz run --verbose -o /tmp/v2.jsonl --- ./rust/target/release/examples/toy 2>/tmp/v2.txt >/dev/null || true
+        grep -a 'Included source file' /tmp/v2.txt | grep -aE 'toy.rs|rust/src/lib.rs' | sed 's/^/  /' || echo "  toy.rs NOT in scope"
 
     - name: Profile the Rust toy under coz
       run: |

libcoz/profiler.cpp

@@ -52,6 +52,13 @@
 
 using namespace std;
 
+// TEMPORARY diagnostics for the rust-on-linux CI failure.
+static std::atomic<size_t> g_dbg_sigprof{0};
+static std::atomic<size_t> g_dbg_no_state{0};
+static std::atomic<size_t> g_dbg_records{0};
+static std::atomic<size_t> g_dbg_samples{0};
+static std::atomic<size_t> g_dbg_matched{0};
+
 // Diagnostic counters for delay application (macOS debugging)
 #ifdef __APPLE__
 static std::atomic<size_t> g_delays_applied{0};
@@ -511,6 +518,12 @@ void profiler::log_samples(ofstream& output, size_t start_time) {
  */
 void profiler::shutdown() {
   if(_shutdown_run.test_and_set() == false) {
+    if(getenv("COZ_DEBUG_SAMPLES")) {
+      fprintf(stderr,
+              "[coz-dbg] sigprof=%zu no_state=%zu perf_records=%zu samples=%zu matched=%zu\n",
+              g_dbg_sigprof.load(), g_dbg_no_state.load(), g_dbg_records.load(),
+              g_dbg_samples.load(), g_dbg_matched.load());
+    }
 #ifdef __APPLE__
     // Stop the macOS sampling thread first so no more samples are produced
     // and no more pthread_kill() calls happen from apply_pending_delays()
@@ -718,10 +731,13 @@ void profiler::add_delays(thread_state* state) {
 
 void profiler::process_samples(thread_state* state) {
   for(perf_event::record r : state->sampler) {
+    g_dbg_records.fetch_add(1, std::memory_order_relaxed);
     if(r.is_sample()) {
+      g_dbg_samples.fetch_add(1, std::memory_order_relaxed);
       // Find and match the line that contains this sample
       std::pair<line*, bool> sampled_line = match_line(r);
       if(sampled_line.first) {
+        g_dbg_matched.fetch_add(1, std::memory_order_relaxed);
         sampled_line.first->add_sample();
       }
 
@@ -855,8 +871,10 @@ void* profiler::start_profiler_thread(void* arg) {
 }
 
 void profiler::samples_ready(int signum, siginfo_t* info, void* p) {
+  g_dbg_sigprof.fetch_add(1, std::memory_order_relaxed);
   thread_state* state = get_instance().get_thread_state();
   if (!state) {
+    g_dbg_no_state.fetch_add(1, std::memory_order_relaxed);
     return;
   }
   if (state->check_in_use()) {