René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"`_remote_debugging`: reading whole pages over and over","articleBody":"# Bug report\n\n### Bug description:\n\nOn a [MacBook Air M4](https://gist.github.com/maurycy/d20d3a37431b95c0725353b71bc9d95a), there are 3 `mach_vm_read_overwrite()` per `get_stack_trace()`, and they're all 16384 bytes (page):\n\n```bash\n2026-05-09T00:42:52.737520000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (main 57ef219*) % sudo dtrace -q -Z -x dynvarsize=64m -x bufsize=128m \\\n    -c \"./python.exe -m profiling.sampling run -r 1000khz -d 15 --pstats -o /dev/null /tmp/busy.py\" \\\n    -n '\n  pid$target::*get_stack_trace*:entry  { self-\u003egst = timestamp; }\n  pid$target::*get_stack_trace*:return /self-\u003egst/ {\n      @gst_avg = avg(timestamp - self-\u003egst);\n      @gst_n = count(); self-\u003egst = 0;\n  }\n\n  pid$target::mach_vm_read_overwrite:entry {\n      self-\u003evmr = timestamp;\n      @vmr_size[arg2] = count();\n  }\n\n  pid$target::mach_vm_read_overwrite:return /self-\u003evmr/ {\n      @vmr_avg = avg(timestamp - self-\u003evmr);\n      @vmr_n = count();\n      self-\u003evmr = 0;\n  }\n\n  END {\n    printf(\"\\n=== get_stack_trace ===\\n\");\n    printf(\"avg ns \"); printa(@gst_avg); printf(\"count \"); printa(@gst_n);\n    printf(\"\\n=== mach_vm_read_overwrite ===\\n\");\n    printf(\"avg ns \"); printa(@vmr_avg); printf(\"count \"); printa(@vmr_n);\n    printf(\"\\n=== mach_vm_read_overwrite read sizes (bytes) ===\\n\");\n    printa(\"%d bytes                                 %@d\\n\", @vmr_size);\n  }'\n\nCaptured 897,532 samples in 15.00 seconds\nSample rate: 59,835.42 samples/sec\nError rate: 0.00\nRaw unwinder rate: 69,908.92 samples/sec (14.30 us/sample)\nWarning: missed 14102479 samples from the expected total of 15000011 (94.02%)\n\n=== get_stack_trace ===\navg ns \n            13104\ncount \n           911514\n\n=== mach_vm_read_overwrite ===\navg ns \n             3137\ncount \n          2734564\n\n=== mach_vm_read_overwrite read sizes (bytes) ===\n880 bytes                                 1\n8 bytes                                 2\n16384 bytes                                 2734561\n\n2026-05-09T00:43:11.123030000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (main 57ef219*) % cat /tmp/busy.py \nx = 0\nwhile True:\n    x = (x + 1) % 1000003\n2026-05-09T00:43:22.664550000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (main 57ef219*) % git diff\ndiff --git i/Lib/profiling/sampling/sample.py w/Lib/profiling/sampling/sample.py\nindex 5bbe2483581..36ed33337aa 100644\n--- i/Lib/profiling/sampling/sample.py\n+++ w/Lib/profiling/sampling/sample.py\n@@ -181,6 +181,19 @@ def sample(self, collector, duration_sec=None, *, async_aware=False):\n             print(f\"Sample rate: {fmt(sample_rate, 2)} samples/sec\")\n             print(f\"Error rate: {fmt(error_rate, 2)}\")\n \n+            # Raw RemoteUnwinder() throughput (tight loop, no scheduler/sleep)\n+            try:\n+                raw_start = time.perf_counter()\n+                raw_n = 0\n+                while time.perf_counter() - raw_start \u003c 0.2:\n+                    self._get_stack_trace(async_aware=async_aware)\n+                    raw_n += 1\n+                raw_elapsed = time.perf_counter() - raw_start\n+                if raw_n and raw_elapsed:\n+                    print(f\"Raw unwinder rate: {fmt(raw_n/raw_elapsed, 2)} samples/sec ({fmt(1e6*raw_elapsed/raw_n, 2)} us/sample)\")\n+            except Exception:\n+                pass\n+\n             # Print unwinder stats if stats collection is enabled\n             if self.collect_stats:\n                 self._print_unwinder_stats()\n2026-05-09T00:43:23.960838000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (main 57ef219*) % \n```\n\n(The `ns` are heavily taxed by DTrace, so should be taken with a grain of salt.)\n\nHowever, the cache is invalidated after reading every sample, so they've very short-lived:\n\nhttps://github.com/python/cpython/blob/57ef2199503387617b8af3d719c74089fb70dbd4/Modules/_remote_debugging/module.c#L717\n\nI believe that's where the reads happen:\n\nhttps://github.com/python/cpython/blob/57ef2199503387617b8af3d719c74089fb70dbd4/Modules/_remote_debugging/module.c#L540-L548\n\nhttps://github.com/python/cpython/blob/57ef2199503387617b8af3d719c74089fb70dbd4/Modules/_remote_debugging/threads.c#L306-L307\n\nhttps://github.com/python/cpython/blob/57ef2199503387617b8af3d719c74089fb70dbd4/Modules/_remote_debugging/frames.c#L200-L205\n\nThese are all relatively small structs, between 80-8000 bytes.\n\n(My understanding is that `InterpState` will nearly always be on a different page than TS / Frame, but they can be.)\n\nThe larger the `mach_vm_read_overwrite`, the slower it gets:\n\n```bash\n[130] 2026-05-09T00:44:06.004867000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (main 57ef219*) % cat /tmp/vmread_bench.c \n#include \u003cmach/mach.h\u003e\n#include \u003cmach/mach_vm.h\u003e\n#include \u003cstdio.h\u003e\n#include \u003ctime.h\u003e\n\nint main(void) {\n    char src[16384] = {0}, dst[16384];\n    mach_port_t self = mach_task_self();\n    mach_vm_size_t out;\n\n    for (size_t sz = 64; sz \u003c= 16384; sz *= 2) {\n        uint64_t t0 = clock_gettime_nsec_np(CLOCK_UPTIME_RAW);\n        for (int i = 0; i \u003c 100000; i++)\n            mach_vm_read_overwrite(self, (mach_vm_address_t)src, sz,\n                                   (mach_vm_address_t)dst, \u0026out);\n        uint64_t t1 = clock_gettime_nsec_np(CLOCK_UPTIME_RAW);\n        printf(\"%6zu B: %.0f ns/op\\n\", sz, (t1 - t0) / 100000.0);\n    }\n}\n2026-05-09T00:44:06.177740000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (main 57ef219*) % cc /tmp/vmread_bench.c -o /tmp/vmread_bench \n2026-05-09T00:44:14.349092000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (main 57ef219*) % /tmp/vmread_bench \n    64 B: 635 ns/op\n   128 B: 388 ns/op\n   256 B: 358 ns/op\n   512 B: 371 ns/op\n  1024 B: 391 ns/op\n  2048 B: 415 ns/op\n  4096 B: 489 ns/op\n  8192 B: 651 ns/op\n 16384 B: 938 ns/op\n```\n\nSimilarly on Linux?\n\n```bash\n2026-05-08T22:53:09.556034847+0000 maurycy@weiss /home/maurycy/cpython (main 57ef219*) # cat /tmp/vm_readv_bench.c \n#define _GNU_SOURCE\n#include \u003cstdio.h\u003e\n#include \u003csys/uio.h\u003e\n#include \u003ctime.h\u003e\n#include \u003cunistd.h\u003e\n\nint main(void) {\n    char src[16384] = {0}, dst[16384];\n    pid_t self = getpid();\n\n    for (size_t sz = 64; sz \u003c= 16384; sz *= 2) {\n        struct iovec local  = {dst, sz};\n        struct iovec remote = {src, sz};\n        struct timespec t0, t1;\n        clock_gettime(CLOCK_MONOTONIC, \u0026t0);\n        for (int i = 0; i \u003c 100000; i++)\n            process_vm_readv(self, \u0026local, 1, \u0026remote, 1, 0);\n        clock_gettime(CLOCK_MONOTONIC, \u0026t1);\n        long ns = (t1.tv_sec - t0.tv_sec) * 1000000000L\n                + (t1.tv_nsec - t0.tv_nsec);\n        printf(\"%6zu B: %ld ns/op\\n\", sz, ns / 100000);\n    }\n}\n2026-05-08T22:53:09.928097987+0000 maurycy@weiss /home/maurycy/cpython (main 57ef219*) # cc /tmp/vm_readv_bench.c -o /tmp/vm_readv_bench\n2026-05-08T22:53:24.934249589+0000 maurycy@weiss /home/maurycy/cpython (main 57ef219*) # /tmp/vm_readv_bench                        \n    64 B: 434 ns/op\n   128 B: 285 ns/op\n   256 B: 250 ns/op\n   512 B: 256 ns/op\n  1024 B: 265 ns/op\n  2048 B: 329 ns/op\n  4096 B: 369 ns/op\n  8192 B: 493 ns/op\n 16384 B: 779 ns/op\n```\n\nI think that one approach is to invalidate more inteligently (or even have two caches: stable and not so stable), using `code_object_generation` or `tlbc_generation` but I cannot figure out a trick for TS/frame.\n\nUsing just `_Py_RemoteDebug_ReadRemoteMemory`:\n\n```diff\ndiff --git a/Modules/_remote_debugging/frames.c b/Modules/_remote_debugging/frames.c\nindex bbdfce3f720..7e565763927 100644\n--- a/Modules/_remote_debugging/frames.c\n+++ b/Modules/_remote_debugging/frames.c\n@@ -197,7 +197,7 @@ parse_frame_object(\n     char frame[SIZEOF_INTERP_FRAME];\n     *address_of_code_object = 0;\n \n-    Py_ssize_t bytes_read = _Py_RemoteDebug_PagedReadRemoteMemory(\n+    Py_ssize_t bytes_read = _Py_RemoteDebug_ReadRemoteMemory(\n         \u0026unwinder-\u003ehandle,\n         address,\n         SIZEOF_INTERP_FRAME,\ndiff --git a/Modules/_remote_debugging/module.c b/Modules/_remote_debugging/module.c\nindex 172f8711a2a..f034fbbf15f 100644\n--- a/Modules/_remote_debugging/module.c\n+++ b/Modules/_remote_debugging/module.c\n@@ -537,7 +537,7 @@ _remote_debugging_RemoteUnwinder_get_stack_trace_impl(RemoteUnwinderObject *self\n     while (current_interpreter != 0) {\n         // Read interpreter state to get the interpreter ID\n         char interp_state_buffer[INTERP_STATE_BUFFER_SIZE];\n-        if (_Py_RemoteDebug_PagedReadRemoteMemory(\n+        if (_Py_RemoteDebug_ReadRemoteMemory(\n                 \u0026self-\u003ehandle,\n                 current_interpreter,\n                 INTERP_STATE_BUFFER_SIZE,\ndiff --git a/Modules/_remote_debugging/threads.c b/Modules/_remote_debugging/threads.c\nindex 4daa5e5f92b..31d83f561a8 100644\n--- a/Modules/_remote_debugging/threads.c\n+++ b/Modules/_remote_debugging/threads.c\n@@ -303,7 +303,7 @@ unwind_stack_for_thread(\n     StackChunkList chunks = {0};\n \n     char ts[SIZEOF_THREAD_STATE];\n-    int bytes_read = _Py_RemoteDebug_PagedReadRemoteMemory(\n+    int bytes_read = _Py_RemoteDebug_ReadRemoteMemory(\n         \u0026unwinder-\u003ehandle, *current_tstate, (size_t)unwinder-\u003edebug_offsets.thread_state.size, ts);\n     if (bytes_read \u003c 0) {\n         set_exception_cause(unwinder, PyExc_RuntimeError, \"Failed to read thread state\");\n```\n\nWe get:\n\n```\n2026-05-09T01:01:17.577709000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (remote-debugging-no-paged 7606bb1*) % sudo dtrace -q -Z -x dynvarsize=64m -x bufsize=128m \\\n    -c \"./python.exe -m profiling.sampling run -r 1000khz -d 15 --pstats -o /dev/null /tmp/busy.py\" \\\n    -n '\n  pid$target::*get_stack_trace*:entry  { self-\u003egst = timestamp; }\n  pid$target::*get_stack_trace*:return /self-\u003egst/ {\n      @gst_avg = avg(timestamp - self-\u003egst);\n      @gst_n = count(); self-\u003egst = 0;\n  }\n\n  pid$target::mach_vm_read_overwrite:entry {\n      self-\u003evmr = timestamp;\n      @vmr_size[arg2] = count();\n  }\n\n  pid$target::mach_vm_read_overwrite:return /self-\u003evmr/ {\n      @vmr_avg = avg(timestamp - self-\u003evmr);\n      @vmr_n = count();\n      self-\u003evmr = 0;\n  }\n\n  END {\n    printf(\"\\n=== get_stack_trace ===\\n\");\n    printf(\"avg ns \"); printa(@gst_avg); printf(\"count \"); printa(@gst_n);\n    printf(\"\\n=== mach_vm_read_overwrite ===\\n\");\n    printf(\"avg ns \"); printa(@vmr_avg); printf(\"count \"); printa(@vmr_n);\n    printf(\"\\n=== mach_vm_read_overwrite read sizes (bytes) ===\\n\");\n    printa(\"%d bytes                                 %@d\\n\", @vmr_size);\n  }'\n\nCaptured 1,077,222 samples in 15.00 seconds\nSample rate: 71,814.76 samples/sec\nError rate: 0.00\nRaw unwinder rate: 87,653.50 samples/sec (11.41 us/sample)\nWarning: missed 13922786 samples from the expected total of 15000008 (92.82%)\n\n=== get_stack_trace ===\navg ns \n            10381\ncount \n          1094753\n\n=== mach_vm_read_overwrite ===\navg ns \n             2570\ncount \n          3284291\n\n=== mach_vm_read_overwrite read sizes (bytes) ===\n8 bytes                                 2\n16384 bytes                                 20\n7992 bytes                                 1094753\n880 bytes                                 1094754\n88 bytes                                 1094762\n```\n\nNote that `mach_vm_read_overwrite` is now 2570 ns vs. 3137 ns before.\n\nAs a result:\n\n```bash\n[130] 2026-05-09T01:08:09.192039000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (remote-debugging-no-paged 7606bb1*) % sudo -E ./python.exe -m profiling.sampling run -r 1000khz -d 15 --pstats -o /dev/null /tmp/busy.py\nCaptured 2,657,910 samples in 15.00 seconds\nSample rate: 177,193.96 samples/sec\nError rate: 0.00\nRaw unwinder rate: 297,398.45 samples/sec (3.36 us/sample)\nWarning: missed 12342093 samples from the expected total of 15000003 (82.28%)\n2026-05-09T01:08:28.996839000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (remote-debugging-no-paged 7606bb1*) % \n```\n\nVersus, on the `main` branch (57ef219 revision):\n\n```bash\n2026-05-09T01:12:48.469595000+0200 maurycy@gimel /Users/maurycy/src/github.com/maurycy/cpython (main 57ef219*) % sudo -E ./python.exe -m profiling.sampling run -r 1000khz -d 15 --pstats -o /dev/null /tmp/busy.py\nCaptured 1,687,897 samples in 15.00 seconds\nSample rate: 112,526.41 samples/sec\nError rate: 0.00\nRaw unwinder rate: 132,402.68 samples/sec (7.55 us/sample)\nWarning: missed 13312110 samples from the expected total of 15000007 (88.75%)\n```\n\nThat's:\n\n- sampling rate: 112 kHz -\u003e 177 kHz (still not great)\n- sampling: 8.88 μs -\u003e 5.64 μs \n- raw unwinder per sample 7.55 μs -\u003e 3.36 μs\n\nPS. Truth to be told, I think that only `tstate.current_frame` and `frame.instr_ptr` have really high churn, and it's still not that efficient.\n\nPS2. What do you think about `mach_vm_remap(copy=FALSE)`? ;-\u003e\n\n### CPython versions tested on:\n\nCPython main branch\n\n### Operating systems tested on:\n\nmacOS\n\n\u003c!-- gh-linked-prs --\u003e\n### Linked PRs\n* gh-149585\n* gh-149649\n* gh-150152\n* gh-150893\n\u003c!-- /gh-linked-prs --\u003e\n","author":{"url":"https://github.com/maurycy","@type":"Person","name":"maurycy"},"datePublished":"2026-05-08T23:25:00.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":10},"url":"https://github.com/149584/cpython/issues/149584"}