From 5af032139e0d1ab8b26b651afd34408628896214 Mon Sep 17 00:00:00 2001 From: mattip Date: Mon, 21 Sep 2026 20:53:29 +0300 Subject: [PATCH 1/4] Add a timestamp for the samples and weight the report by the sample duration --- src/compat.c | 39 +++++++++++++ src/compat.h | 8 +++ src/vmprof.h | 3 + src/vmprof_common.c | 2 +- src/vmprof_common.h | 9 +++ src/vmprof_unix.c | 14 ++++- src/vmprof_win.c | 22 +++++-- vmprof/profiler.py | 12 +++- vmprof/reader.py | 75 +++++++++++++++++++++--- vmprof/stats.py | 58 +++++++++++++----- vmprof/test/test_reader.py | 117 ++++++++++++++++++++++++++++++++++++- vmprof/test/test_run.py | 4 +- 12 files changed, 329 insertions(+), 34 deletions(-) diff --git a/src/compat.c b/src/compat.c index 93f83343..6cfbf3d9 100644 --- a/src/compat.c +++ b/src/compat.c @@ -96,9 +96,48 @@ int vmp_write_time_now(int marker) { vmp_write_all(buffer, __SIZE); return 0; } + +#if defined(VMPROF_APPLE) && !defined(CLOCK_MONOTONIC) +/* SDK older than macOS 10.12: no clock_gettime. mach_absolute_time is a + monotonic clock; there is no signal-safe process cpu clock, so both + modes use it (it is what setitimer(ITIMER_REAL) measures anyway). */ +#include +int64_t vmp_sample_time_ns(int cpu_time) +{ + mach_timebase_info_data_t tb; + uint64_t t = mach_absolute_time(); + (void)cpu_time; + if (mach_timebase_info(&tb) != KERN_SUCCESS || tb.denom == 0) + return (int64_t)t; + return (int64_t)(t / tb.denom * tb.numer + t % tb.denom * tb.numer / tb.denom); +} +#else +int64_t vmp_sample_time_ns(int cpu_time) +{ + struct timespec ts; + clockid_t clk = cpu_time ? CLOCK_PROCESS_CPUTIME_ID : CLOCK_MONOTONIC; + if (clock_gettime(clk, &ts) != 0) + return 0; + return (int64_t)ts.tv_sec * 1000000000LL + ts.tv_nsec; +} +#endif #endif #ifdef VMPROF_WINDOWS +int64_t vmp_sample_time_ns(int cpu_time) +{ + /* the frequency is fixed at boot, so it is safe to cache it */ + static LARGE_INTEGER freq; + LARGE_INTEGER now; + (void)cpu_time; + if (freq.QuadPart == 0 && !QueryPerformanceFrequency(&freq)) + return 0; + if (!QueryPerformanceCounter(&now)) + return 0; + return (int64_t)(now.QuadPart / freq.QuadPart * 1000000000LL + + now.QuadPart % freq.QuadPart * 1000000000LL / freq.QuadPart); +} + int vmp_write_time_now(int marker) { char buffer[__SIZE]; struct timezone_buf buf; diff --git a/src/compat.h b/src/compat.h index 1f95af5f..cad559c2 100644 --- a/src/compat.h +++ b/src/compat.h @@ -23,5 +23,13 @@ int vmp_write_all(const char *buf, size_t bufsize); int vmp_write_time_now(int marker); int vmp_write_meta(const char * key, const char * value); +/* Nanosecond timestamp stored at the end of every stack sample. With + 'cpu_time' set it reads the process cpu-time clock, which is the clock + that drives ITIMER_PROF; otherwise it reads a monotonic wall clock, which + drives ITIMER_REAL and the Windows sampler thread. The reader weights + each sample by the distance to the previous one on the same clock, so + timer signals that were dropped still count. Async-signal-safe. */ +int64_t vmp_sample_time_ns(int cpu_time); + int vmp_profile_fileno(void); void vmp_set_profile_fileno(int fileno); diff --git a/src/vmprof.h b/src/vmprof.h index 36ba4197..287c77f2 100644 --- a/src/vmprof.h +++ b/src/vmprof.h @@ -27,6 +27,9 @@ #define VERSION_MODE_AWARE '\x04' #define VERSION_DURATION '\x05' #define VERSION_TIMESTAMP '\x06' +/* every MARKER_STACKTRACE record ends with a 64-bit nanosecond timestamp, + see vmp_sample_time_ns() */ +#define VERSION_SAMPLE_TIME '\x07' #define PROFILE_MEMORY '\x01' #define PROFILE_LINES '\x02' diff --git a/src/vmprof_common.c b/src/vmprof_common.c index 5a644664..41a75cea 100644 --- a/src/vmprof_common.c +++ b/src/vmprof_common.c @@ -137,7 +137,7 @@ int opened_profile(const char *interp_name, int memory, int proflines, int nativ } header.interp_name[0] = MARKER_HEADER; header.interp_name[1] = '\x00'; - header.interp_name[2] = VERSION_TIMESTAMP; + header.interp_name[2] = VERSION_SAMPLE_TIME; header.interp_name[3] = memory*PROFILE_MEMORY + proflines*PROFILE_LINES + \ native*PROFILE_NATIVE + real_time*PROFILE_REAL_TIME; #ifdef RPYTHON_VMPROF diff --git a/src/vmprof_common.h b/src/vmprof_common.h index ec6b323e..e837316d 100644 --- a/src/vmprof_common.h +++ b/src/vmprof_common.h @@ -45,6 +45,12 @@ long vmp_native_thread_id(void); #define MAX_STACK_DEPTH \ ((SINGLE_BUF_SIZE - sizeof(struct prof_stacktrace_s)) / sizeof(void *)) +/* Slots at the end of a stack sample that are not stack entries: the thread + id, the (optional) rss and the 64-bit sample timestamp. Walk at most + MAX_STACK_DEPTH - STACK_TRAILER_SLOTS frames so that they always fit. */ +#define STACK_TRAILER_SLOTS \ + (2 + (sizeof(int64_t) + sizeof(void *) - 1) / sizeof(void *)) + /* * NOTE SHOULD NOT BE DONE THIS WAY. Here is an example why: * assume the following struct content: @@ -77,6 +83,9 @@ typedef struct prof_stacktrace_s { char marker; long count, depth; void *stack[]; + /* the file record continues after stack[depth] with the thread id, + the rss if memory profiling is on, and an int64_t timestamp + (VERSION_SAMPLE_TIME, see vmp_sample_time_ns) */ } prof_stacktrace_s; #define SIZEOF_PROF_STACKTRACE sizeof(long)+sizeof(long)+sizeof(char) diff --git a/src/vmprof_unix.c b/src/vmprof_unix.c index 2aa2050c..ebff0b2b 100644 --- a/src/vmprof_unix.c +++ b/src/vmprof_unix.c @@ -95,13 +95,16 @@ void segfault_handler(int arg) int _vmprof_sample_stack(struct profbuf_s *p, PY_THREAD_STATE_T * tstate, ucontext_t * uc) { int depth; + int64_t sample_time; struct prof_stacktrace_s *st = (struct prof_stacktrace_s *)p->data; st->marker = MARKER_STACKTRACE; st->count = 1; #ifdef RPYTHON_VMPROF - depth = get_stack_trace(get_vmprof_stack(), st->stack, MAX_STACK_DEPTH-1, (intptr_t)GetPC(uc)); + depth = get_stack_trace(get_vmprof_stack(), st->stack, + MAX_STACK_DEPTH - STACK_TRAILER_SLOTS, (intptr_t)GetPC(uc)); #else - depth = get_stack_trace(tstate, st->stack, MAX_STACK_DEPTH-1, (intptr_t)NULL); + depth = get_stack_trace(tstate, st->stack, + MAX_STACK_DEPTH - STACK_TRAILER_SLOTS, (intptr_t)NULL); #endif // useful for tests (see test_stop_sampling) #ifndef RPYTHON_LL2CTYPES @@ -114,8 +117,13 @@ int _vmprof_sample_stack(struct profbuf_s *p, PY_THREAD_STATE_T * tstate, uconte long rss = get_current_proc_rss(); if (rss >= 0) st->stack[depth++] = (void*)rss; + /* ITIMER_PROF counts process cpu time, ITIMER_REAL wall time: stamp the + sample with the clock that drives the timer. memcpy: the slot is only + pointer-aligned, which is less than int64_t needs on 32 bit. */ + sample_time = vmp_sample_time_ns(vmprof_get_itimer_type() == ITIMER_PROF); + memcpy(&st->stack[depth], &sample_time, sizeof(sample_time)); p->data_offset = offsetof(struct prof_stacktrace_s, marker); - p->data_size = (depth * sizeof(void *) + + p->data_size = (depth * sizeof(void *) + sizeof(sample_time) + sizeof(struct prof_stacktrace_s) - offsetof(struct prof_stacktrace_s, marker)); return 1; diff --git a/src/vmprof_win.c b/src/vmprof_win.c index 830d1d32..a6b758d8 100644 --- a/src/vmprof_win.c +++ b/src/vmprof_win.c @@ -90,11 +90,17 @@ HANDLE write_mutex; #include "vmprof_common.h" +/* Fill 'stack' with a sample of the given thread. Returns the number of + pointer-sized slots written after the header (frames plus the thread id), + or <= 0 if nothing was sampled. The record is followed by the int64_t + sample timestamp, so the caller must write + SIZEOF_PROF_STACKTRACE + depth * sizeof(void*) + sizeof(int64_t) bytes. */ int vmprof_snapshot_thread(DWORD thread_id, PY_WIN_THREAD_STATE *tstate, prof_stacktrace_s *stack) { HRESULT result; HANDLE hThread; int depth; + int64_t sample_time; CONTEXT ctx; #ifdef RPYTHON_LL2CTYPES return 0; // not much we can do @@ -115,9 +121,11 @@ int vmprof_snapshot_thread(DWORD thread_id, PY_WIN_THREAD_STATE *tstate, prof_st if (!GetThreadContext(hThread, &ctx)) return -1; depth = get_stack_trace(tstate->vmprof_tl_stack, - stack->stack, MAX_STACK_DEPTH-2, ctx.Eip); + stack->stack, MAX_STACK_DEPTH - STACK_TRAILER_SLOTS, ctx.Eip); stack->depth = depth; stack->stack[depth++] = thread_id; + sample_time = vmp_sample_time_ns(0); + memcpy(&stack->stack[depth], &sample_time, sizeof(sample_time)); stack->count = 1; stack->marker = MARKER_STACKTRACE; ResumeThread(hThread); @@ -142,9 +150,9 @@ int vmprof_snapshot_thread(DWORD thread_id, PY_WIN_THREAD_STATE *tstate, prof_st #else frame = PyThreadState_GetFrame(tstate); #endif - /* leave room for the thread id appended below */ + /* leave room for the thread id and timestamp appended below */ depth = vmp_walk_and_record_stack(frame, stack->stack, - MAX_STACK_DEPTH - 1, 0, 0); + MAX_STACK_DEPTH - STACK_TRAILER_SLOTS, 0, 0); #ifdef _MSC_VER } __except (EXCEPTION_EXECUTE_HANDLER) { depth = -1; @@ -160,6 +168,9 @@ int vmprof_snapshot_thread(DWORD thread_id, PY_WIN_THREAD_STATE *tstate, prof_st } stack->depth = depth; stack->stack[depth++] = (void*)((ULONG_PTR)thread_id); + /* the sampler thread sleeps in wall time, so use the wall clock */ + sample_time = vmp_sample_time_ns(0); + memcpy(&stack->stack[depth], &sample_time, sizeof(sample_time)); stack->count = 1; stack->marker = MARKER_STACKTRACE; ResumeThread(hThread); @@ -226,7 +237,8 @@ long __stdcall vmprof_mainloop(void *arg) depth = vmprof_snapshot_thread(tstate->thread_id, tstate, stack); if (depth > 0) { vmp_write_all((char*)stack + offsetof(prof_stacktrace_s, marker), - SIZEOF_PROF_STACKTRACE + depth * sizeof(void*)); + SIZEOF_PROF_STACKTRACE + depth * sizeof(void*) + + sizeof(int64_t)); } sampler_busy = 0; } @@ -246,7 +258,7 @@ long __stdcall vmprof_mainloop(void *arg) depth = vmprof_snapshot_thread(tstate->thread_ident, tstate, stack); if (depth > 0) { vmp_write_all((char*)stack + offsetof(prof_stacktrace_s, marker), - depth * sizeof(void *) + + depth * sizeof(void *) + sizeof(int64_t) + sizeof(struct prof_stacktrace_s) - offsetof(struct prof_stacktrace_s, marker)); } diff --git a/vmprof/profiler.py b/vmprof/profiler.py index 403abd5e..ef0c4d13 100644 --- a/vmprof/profiler.py +++ b/vmprof/profiler.py @@ -2,7 +2,7 @@ import tempfile from vmprof.stats import Stats -from vmprof.reader import _read_prof +from vmprof.reader import _read_prof, DEFAULT_MAX_SAMPLE_GAP class VMProfError(Exception): @@ -32,12 +32,18 @@ def __exit__(self, type, value, traceback): self.done = True -def read_profile(prof_file): +def read_profile(prof_file, max_sample_gap=DEFAULT_MAX_SAMPLE_GAP): + """ Read a profile file into a Stats object. + + max_sample_gap caps, in seconds, how much time a single sample may + stand for when the timestamps show that timer signals were lost; + see vmprof.reader.LogReader.sample_weight. + """ file_to_close = None if not hasattr(prof_file, 'read'): prof_file = file_to_close = open(str(prof_file), 'rb') - state = _read_prof(prof_file) + state = _read_prof(prof_file, max_sample_gap=max_sample_gap) if file_to_close: file_to_close.close() diff --git a/vmprof/reader.py b/vmprof/reader.py index d1138f39..00e2d09d 100644 --- a/vmprof/reader.py +++ b/vmprof/reader.py @@ -26,11 +26,21 @@ VERSION_MODE_AWARE = 4 VERSION_DURATION = 5 VERSION_TIMESTAMP = 6 +# every stack sample ends with a 64-bit nanosecond timestamp +VERSION_SAMPLE_TIME = 7 PROFILE_MEMORY = 1 PROFILE_LINES = 2 PROFILE_NATIVE = 4 PROFILE_RPYTHON = 8 +PROFILE_REAL_TIME = 16 + +# A sample is weighted by the time elapsed since the previous one, so that +# timer signals the process never received (it was off the cpu, or the +# signal was still pending) are still accounted for. The gap is capped at +# this many seconds: a process that was stopped in a debugger or suspended +# with the laptop lid should not attribute minutes to a single frame. +DEFAULT_MAX_SAMPLE_GAP = 1.0 VMPROF_CODE_TAG = 1 VMPROF_BLACKHOLE_TAG = 2 @@ -96,6 +106,8 @@ def __init__(self, fileobj, state): self.state = state self.word_size = None self.addr_size = None + # timestamp of the previous sample, see sample_weight() + self.last_sample_time = {} self.setup() def setup(self): @@ -163,10 +175,12 @@ def read_header(self): s.profile_memory = (mode & PROFILE_MEMORY) != 0 s.profile_lines = (mode & PROFILE_LINES) != 0 s.profile_rpython = (mode & PROFILE_RPYTHON) != 0 + s.profile_real_time = (mode & PROFILE_REAL_TIME) != 0 else: s.profile_memory = s.version == VERSION_MEMORY s.profile_lines = False s.profile_rpython = False + s.profile_real_time = False lgt = ord(fileobj.read(1)) s.interp_name = fileobj.read(lgt) @@ -230,7 +244,43 @@ def read_addresses(self, count): return addrs def read_s64(self): - return struct.unpack('q', self.fileobj.read(8))[0] + return struct.unpack(' prev: + self.last_sample_time[key] = sample_time + if prev is None: + weight = 1.0 + else: + gap = sample_time - prev + max_gap = s.max_sample_gap * 10**9 + if gap > max_gap: + s.lost_time += (gap - max_gap) / 10.0**9 + gap = max_gap + weight = max(gap / (s.period * 1000.0), 1.0) + s.expected_samples += weight + return weight def read_time_and_zone(self): return datetime.datetime.fromtimestamp( @@ -274,12 +324,16 @@ def read_all(self): trace = self.read_trace(depth) thread_id = 0 mem_in_kb = 0 + sample_time = None if s.version >= VERSION_THREAD_ID: thread_id = self.read_addr() if s.profile_memory: mem_in_kb = self.read_addr() + if s.version >= VERSION_SAMPLE_TIME: + sample_time = self.read_s64() trace.reverse() - self.add_trace(trace, 1, thread_id, mem_in_kb) + weight = self.sample_weight(thread_id, sample_time) + self.add_trace(trace, weight, thread_id, mem_in_kb) elif marker == MARKER_VIRTUAL_IP or marker == MARKER_NATIVE_SYMBOLS: unique_id = self.read_addr() name = self.read_string() @@ -356,7 +410,7 @@ class ReaderState(object): pass class LogReaderState(ReaderState): - def __init__(self): + def __init__(self, max_sample_gap=DEFAULT_MAX_SAMPLE_GAP): self.virtual_ips = [] self.profiles = [] self.interp_name = None @@ -365,14 +419,21 @@ def __init__(self): self.version = 0 self.profile_memory = False self.profile_lines = False + self.profile_real_time = False self.meta = {} self.little_endian = True - self.period = 0 - -def _read_prof(fileobj, virtual_ips_only=False): + self.period = 0 # microseconds + # see LogReader.sample_weight + self.max_sample_gap = max_sample_gap + self.n_samples = 0 # stack samples in the file + self.expected_samples = 0 # timer periods those samples stand for + self.lost_time = 0.0 # seconds cut off by max_sample_gap + +def _read_prof(fileobj, virtual_ips_only=False, + max_sample_gap=DEFAULT_MAX_SAMPLE_GAP): fileobj = gunzip(fileobj) - state = LogReaderState() + state = LogReaderState(max_sample_gap) reader = LogReader(fileobj, state) reader.read_all() diff --git a/vmprof/stats.py b/vmprof/stats.py index 9d5ca043..0b46e04c 100644 --- a/vmprof/stats.py +++ b/vmprof/stats.py @@ -3,20 +3,37 @@ class EmptyProfileFile(Exception): pass +def _count_str(count): + if count == int(count): + return '%d' % count + return '%.1f' % count + class Stats(object): + """ profiles is a list of (trace, weight, thread_id[, mem_in_kb]). + + The weight is the number of timer periods the sample stands for. It + is 1 for files without sample timestamps, and >= 1.0 (a float) when + the reader could tell that timer signals were lost between samples. + Every count in the tree, in top_profile() and in function_profile() + is a sum of weights. + """ def __init__(self, profiles, adr_dict=None, jit_frames=None, interp=None, meta=None, start_time=None, end_time=None, state=None): self.profiles = profiles self.adr_dict = adr_dict self.functions = {} + self.n_samples = len(profiles) + self.expected_samples = sum(p[1] for p in profiles) # kludgy, state is optional. stats should only take state as input if state: self.profile_lines = state.profile_lines self.profile_memory = state.profile_memory + self.lost_time = state.lost_time else: # unknown, for tests only self.profile_lines = False self.profile_memory = False + self.lost_time = 0.0 self.generate_top() if jit_frames is None: jit_frames = set() @@ -34,6 +51,17 @@ def get_runtime_in_microseconds(self): ts = self.end_time - self.start_time return ts.total_seconds() * 1000000 + def get_lost_fraction(self): + """ The fraction of timer periods for which no sample was taken, + as judged from the sample timestamps: 0.0 means every timer signal + produced a sample, 0.25 means one in four was lost. Always 0.0 for + files without timestamps. Time cut off by the reader's + max_sample_gap is not included here, see self.lost_time. + """ + if not self.expected_samples: + return 0.0 + return 1.0 - float(self.n_samples) / self.expected_samples + def get_name(self, addr): if addr not in self.adr_dict: return "unknown" @@ -66,13 +94,14 @@ def display(self, no): def generate_top(self): for profile in self.profiles: current_iter = {} + weight = profile[1] for i, addr in enumerate(profile[0]): if self.profile_lines and i % 2 == 1: # this entry in the profile is a negative number indicating a line assert addr <= 0 continue if addr not in current_iter: # count only topmost - self.functions[addr] = self.functions.get(addr, 0) + 1 + self.functions[addr] = self.functions.get(addr, 0) + weight current_iter[addr] = None def top_profile(self): @@ -93,16 +122,17 @@ def function_profile(self, top_function): for profile in self.profiles: current_iter = {} # don't count twice counting = False + weight = profile[1] for addr in profile[0]: if counting: if addr in current_iter: continue current_iter[addr] = None - result[addr] = result.get(addr, 0) + 1 + result[addr] = result.get(addr, 0) + weight else: if addr == top_function: counting = True - total += 1 + total += weight result = sorted(result.items(), key=lambda a: a[1]) return result, total @@ -114,7 +144,7 @@ def get_top(self, profiles): raise EmptyProfileFile() top_addr = prof[0][0] top = Node(top_addr, self._get_name(top_addr)) - top.count = len(self.profiles) + top.count = self.expected_samples return top def get_tree(self): @@ -125,6 +155,7 @@ def get_tree(self): for profile in self.profiles: last_addr = top.addr cur = top + weight = profile[1] for i in range(0, len(profile[0])): if isinstance(profile[0][i], AssemblerCode): continue # just ignore it for now @@ -132,17 +163,17 @@ def get_tree(self): if addr <= 0: # negative address means line number - cur.lines[-addr] = cur.lines.get(-addr, 0) + 1 + cur.lines[-addr] = cur.lines.get(-addr, 0) + weight else: if addr == last_addr: continue # ignore duplicates last_addr = addr name = self._get_name(addr) - cur = cur.add_child(addr, name) + cur = cur.add_child(addr, name, weight) if isinstance(addr, JittedCode): - cur.meta['jit'] = cur.meta.get('jit', 0) + 1 + cur.meta['jit'] = cur.meta.get('jit', 0) + weight if isinstance(addr, NativeCode): - cur.meta['native'] = cur.meta.get('native', 0) + 1 + cur.meta['native'] = cur.meta.get('native', 0) + weight # get the first "interesting" node, that is after vmprof and pypy # mess @@ -246,12 +277,12 @@ def get_self_count(self): self_count = property(get_self_count) - def add_child(self, addr, name): + def add_child(self, addr, name, count=1): try: next = self.children[addr] - next.count += 1 + next.count += count except KeyError: - next = Node(addr, name) + next = Node(addr, name, count) self.children[addr] = next return next @@ -265,6 +296,7 @@ def __ne__(self, other): def __repr__(self): items = sorted(self.children.items()) - child_str = ", ".join([("(%d, %s)" % (v.count, v.name)) + child_str = ", ".join([("(%s, %s)" % (_count_str(v.count), v.name)) for k, v in items]) - return '' % (self.name, self.count, child_str) + return '' % (self.name, _count_str(self.count), + child_str) diff --git a/vmprof/test/test_reader.py b/vmprof/test/test_reader.py index d976a3d9..579c3f73 100644 --- a/vmprof/test/test_reader.py +++ b/vmprof/test/test_reader.py @@ -1,7 +1,11 @@ +import io import struct, pytest from vmprof import reader -from vmprof.reader import (FileReadError, MARKER_HEADER) +from vmprof.reader import (FileReadError, MARKER_HEADER, MARKER_STACKTRACE, + MARKER_TRAILER, MARKER_VIRTUAL_IP, VERSION_SAMPLE_TIME, + VERSION_TIMESTAMP, PROFILE_REAL_TIME) +from vmprof.profiler import read_profile from vmprof.test.test_run import (read_one_marker, read_header, BufferTooSmallError, FileObjWrapper) @@ -48,3 +52,114 @@ def test_fileobj_wrapper(): assert fw.read(4) == b'4567' assert fw.read(2) == b'89' + +MS = 10**6 # nanoseconds in a millisecond + +def build_profile(samples, period_usec=1000, version=VERSION_SAMPLE_TIME, + mode=0): + """ A 64-bit little-endian profile of (trace, thread_id, timestamp_ns) + samples, written the way src/vmprof_unix.c writes it. The timestamp + is only written for version >= VERSION_SAMPLE_TIME. + """ + word = lambda v: struct.pack('= VERSION_SAMPLE_TIME: + out.append(struct.pack('' + +def test_sample_weights_fractional(): + stats = read_profile(build_profile([ + ([1], 7, 0), + ([1], 7, 5 * MS // 2), + ])) + assert weights(stats) == [1.0, 2.5] + assert repr(stats.get_tree()) == '' + +def test_sample_weights_old_version(): + # no timestamps in the file: every sample is worth one period + stats = read_profile(build_profile([ + ([1, 2], 7, 0), + ([1, 2], 7, 5 * MS), + ], version=VERSION_TIMESTAMP)) + assert weights(stats) == [1, 1] + assert stats.get_lost_fraction() == 0.0 + assert stats.get_tree().count == 2 + +def test_sample_weights_capped(): + # the gap is capped at max_sample_gap, the excess ends up in lost_time + profile = build_profile([ + ([1], 7, 0), + ([1], 7, 30 * MS), + ]) + stats = read_profile(profile, max_sample_gap=0.010) + assert weights(stats) == [1.0, 10.0] + assert stats.lost_time == pytest.approx(0.020) + profile.seek(0) + stats = read_profile(profile) + assert weights(stats) == [1.0, 30.0] + assert stats.lost_time == 0.0 + +def test_sample_weights_two_threads(): + # thread 7 and thread 8 both miss the signal at 1 ms + samples = [ + ([1], 7, 0), + ([2], 8, MS // 10), + ([1], 7, 2 * MS), + ([2], 8, 2 * MS + MS // 10), + ] + # cpu time mode: one process-wide timer, the timestamp is process cpu + # time, so the gap is measured against the previous sample of any thread + stats = read_profile(build_profile(samples)) + assert weights(stats) == [1.0, 1.0, 1.9, 1.0] + # real time mode: every thread gets its own signal per period, so the + # gap is measured per thread + stats = read_profile(build_profile(samples, mode=PROFILE_REAL_TIME)) + assert weights(stats) == [1.0, 1.0, 2.0, 2.0] + assert stats.get_lost_fraction() == pytest.approx(1.0 - 4.0 / 6.0) + +def test_sample_weights_out_of_order(): + # buffers of different threads can be written out of order; a sample + # that is older than the previous one is worth one period and does + # not move the clock backwards + stats = read_profile(build_profile([ + ([1], 7, 2 * MS), + ([2], 8, 1 * MS), + ([1], 7, 3 * MS), + ])) + assert weights(stats) == [1.0, 1.0, 1.0] + diff --git a/vmprof/test/test_run.py b/vmprof/test/test_run.py index 80754b75..4dd6a543 100644 --- a/vmprof/test/test_run.py +++ b/vmprof/test/test_run.py @@ -15,7 +15,7 @@ from vmprof.show import PrettyPrinter from vmprof.profiler import read_profile from vmprof.reader import (gunzip, MARKER_STACKTRACE, MARKER_VIRTUAL_IP, - MARKER_TRAILER, FileReadError, VERSION_THREAD_ID, + MARKER_TRAILER, FileReadError, VERSION_THREAD_ID, VERSION_SAMPLE_TIME, MARKER_TIME_N_ZONE, assert_error, MARKER_META, MARKER_NATIVE_SYMBOLS) from vmshare.binary import read_string, read_word, read_addr @@ -426,6 +426,8 @@ def read_one_marker(fileobj, status, buffer_so_far=None): mem_in_kb = read_addr(fileobj) else: mem_in_kb = 0 + if status.version >= VERSION_SAMPLE_TIME: + fileobj.read(8) # the sample timestamp, ignored here trace.reverse() status.profiles.append((trace, 1, thread_id, mem_in_kb)) elif marker == MARKER_VIRTUAL_IP or marker == MARKER_NATIVE_SYMBOLS: From bfffbdb8890491eaabc26ace617c20b7afe78542 Mon Sep 17 00:00:00 2001 From: mattip Date: Tue, 22 Sep 2026 09:07:12 +0300 Subject: [PATCH 2/4] bump version --- meson.build | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/meson.build b/meson.build index c925dd1e..f4b5bd25 100644 --- a/meson.build +++ b/meson.build @@ -1,5 +1,5 @@ project('vmprof', 'c', - version: '0.5.1', + version: '0.6.0', license: 'MIT', meson_version: '>=1.1.0', ) From 9ca966540058bd580df49c4e37c7b604002807d1 Mon Sep 17 00:00:00 2001 From: mattip Date: Tue, 22 Sep 2026 11:42:31 +0300 Subject: [PATCH 3/4] read version and raise if version is not understood --- vmprof/reader.py | 4 ++++ vmprof/test/test_reader.py | 29 ++++++++++++++++++++++++----- 2 files changed, 28 insertions(+), 5 deletions(-) diff --git a/vmprof/reader.py b/vmprof/reader.py index 00e2d09d..2da63f34 100644 --- a/vmprof/reader.py +++ b/vmprof/reader.py @@ -169,6 +169,10 @@ def read_header(self): s = self.state fileobj = self.fileobj s.version, = struct.unpack("!h", fileobj.read(2)) + if s.version > VERSION_SAMPLE_TIME: + raise FileReadError("profile format version %d is newer than " + "this reader supports (%d), please upgrade " + "vmprof" % (s.version, VERSION_SAMPLE_TIME)) if s.version >= VERSION_MODE_AWARE: mode = ord(fileobj.read(1)) diff --git a/vmprof/test/test_reader.py b/vmprof/test/test_reader.py index 579c3f73..04975229 100644 --- a/vmprof/test/test_reader.py +++ b/vmprof/test/test_reader.py @@ -4,7 +4,9 @@ from vmprof import reader from vmprof.reader import (FileReadError, MARKER_HEADER, MARKER_STACKTRACE, MARKER_TRAILER, MARKER_VIRTUAL_IP, VERSION_SAMPLE_TIME, - VERSION_TIMESTAMP, PROFILE_REAL_TIME) + VERSION_TIMESTAMP, VERSION_THREAD_ID, VERSION_MEMORY, + VERSION_MODE_AWARE, VERSION_DURATION, PROFILE_MEMORY, + PROFILE_REAL_TIME) from vmprof.profiler import read_profile from vmprof.test.test_run import (read_one_marker, read_header, BufferTooSmallError, FileObjWrapper) @@ -63,18 +65,26 @@ def build_profile(samples, period_usec=1000, version=VERSION_SAMPLE_TIME, """ word = lambda v: struct.pack('= VERSION_MODE_AWARE: + out.append(struct.pack('B', mode)) + out.append(struct.pack('B', 4) + b'test') for addr, name in [(1, b'foo'), (2, b'bar'), (3, b'baz')]: out.append(MARKER_VIRTUAL_IP + word(addr) + word(len(name)) + name) for trace, thread_id, timestamp in samples: out.append(MARKER_STACKTRACE + word(1) + word(len(trace))) for addr in reversed(trace): out.append(word(addr)) - out.append(word(thread_id)) + if version >= VERSION_THREAD_ID: + out.append(word(thread_id)) + if version == VERSION_MEMORY or (version >= VERSION_MODE_AWARE and + mode & PROFILE_MEMORY): + out.append(word(0)) # rss in kb if version >= VERSION_SAMPLE_TIME: out.append(struct.pack('= VERSION_DURATION: + out.append(word(0) + word(0) + b'\x00' * 8) return io.BytesIO(b''.join(out)) def weights(stats): @@ -152,6 +162,15 @@ def test_sample_weights_two_threads(): assert weights(stats) == [1.0, 1.0, 2.0, 2.0] assert stats.get_lost_fraction() == pytest.approx(1.0 - 4.0 / 6.0) +def test_newer_format_version_is_refused(): + # the header names the format version, so a file written by a newer + # vmprof fails up front instead of being misparsed + with pytest.raises(FileReadError, match="version 8 is newer"): + read_profile(build_profile([([1], 7, 0)], version=VERSION_SAMPLE_TIME + 1)) + # the current version and every older one are fine + for version in range(VERSION_SAMPLE_TIME + 1): + read_profile(build_profile([([1], 7, 0)], version=version)) + def test_sample_weights_out_of_order(): # buffers of different threads can be written out of order; a sample # that is older than the previous one is worth one period and does From c4b17f586d57f10b30807e1326e674503c08160d Mon Sep 17 00:00:00 2001 From: mattip Date: Tue, 22 Sep 2026 14:19:58 +0300 Subject: [PATCH 4/4] drop python3.9 --- .github/workflows/tests.yml | 4 ++-- pyproject.toml | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 9530d282..1514a3f3 100644 --- a/.github/workflows/tests.yml +++ b/.github/workflows/tests.yml @@ -18,12 +18,12 @@ jobs: matrix: # Test all supported versions on Ubuntu: os: [ubuntu-latest] - python: ["3.9", "3.10", "3.11", "3.12", "3.13", "3.14", "3.15.0-rc.2", "pypy-3.11"] + python: ["3.10", "3.11", "3.12", "3.13", "3.14", "3.15.0-rc.2", "pypy-3.11"] experimental: [false] include: # Windows on the earliest and latest supported versions: - os: windows-latest - python: "3.9" + python: "3.10" experimental: false - os: windows-latest python: "3.15.0-rc.2" diff --git a/pyproject.toml b/pyproject.toml index e0ade52b..1aa1376a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -12,7 +12,7 @@ license-files = ["LICENSE"] authors = [ {name = "vmprof team", email = "fijal@baroquesoftware.com"}, ] -requires-python = ">=3.9,<3.16" +requires-python = ">=3.10,<3.16" dependencies = [ "requests", "colorama",