From 7e8b282e1db68a00eedaa4174e42cb560fb9ca3c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20Wr=C3=B3blewski?= Date: Thu, 24 Aug 2017 10:51:21 +0200 Subject: [PATCH 1/8] Reproduce a failing test case. --- vmprof/test/test_run.py | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/vmprof/test/test_run.py b/vmprof/test/test_run.py index 29455978..a23014ff 100644 --- a/vmprof/test/test_run.py +++ b/vmprof/test/test_run.py @@ -79,14 +79,24 @@ def function_bar(): def functime_foo(t=0.05, insert=False): + import threading + thread_id = threading.get_ident() if (insert): - vmprof.insert_real_time_thread() + thread_count = vmprof.insert_real_time_thread() + else: + thread_count = None + print("foo:", thread_id, thread_count, file=sys.stderr) return time.sleep(t) def functime_bar(t=0.05, remove=False): + import threading + thread_id = threading.get_ident() if (remove): - vmprof.remove_real_time_thread() + thread_count = vmprof.remove_real_time_thread() + else: + thread_count = None + print("bar:", thread_id, thread_count, file=sys.stderr) return time.sleep(t) @@ -255,7 +265,6 @@ def test_vmprof_real_time(): assert d[foo_time_name] > 0 -@py.test.mark.xfail() @py.test.mark.skipif("'__pypy__' in sys.builtin_module_names") @py.test.mark.skipif("sys.platform == 'win32'") @py.test.mark.parametrize("insert_foo,remove_bar", [ From 00144e056f0fc2a60ffde7134ac72a31764687bc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20Wr=C3=B3blewski?= Date: Thu, 24 Aug 2017 11:01:55 +0200 Subject: [PATCH 2/8] Reproduce a failing test case, portably. --- vmprof/test/test_run.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/vmprof/test/test_run.py b/vmprof/test/test_run.py index a23014ff..c6634442 100644 --- a/vmprof/test/test_run.py +++ b/vmprof/test/test_run.py @@ -84,8 +84,8 @@ def functime_foo(t=0.05, insert=False): if (insert): thread_count = vmprof.insert_real_time_thread() else: - thread_count = None - print("foo:", thread_id, thread_count, file=sys.stderr) + thread_count = -1 + sys.stderr.writelines("foo:%i:%i\n" % (thread_id, thread_count)) return time.sleep(t) @@ -96,7 +96,7 @@ def functime_bar(t=0.05, remove=False): thread_count = vmprof.remove_real_time_thread() else: thread_count = None - print("bar:", thread_id, thread_count, file=sys.stderr) + sys.stderr.writelines("bar:%i:%i\n" % (thread_id, thread_count)) return time.sleep(t) From 86753efdefbe7d5ea5576290d8a47a604ff6067a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20Wr=C3=B3blewski?= Date: Thu, 24 Aug 2017 11:56:58 +0200 Subject: [PATCH 3/8] Possible fix. --- src/_vmprof.c | 4 ++-- src/vmprof_common.c | 23 ++++++++++++----------- src/vmprof_common.h | 22 +++++++++++++++++++--- src/vmprof_unix.c | 2 +- vmprof/test/test_run.py | 4 ++-- 5 files changed, 36 insertions(+), 19 deletions(-) diff --git a/src/_vmprof.c b/src/_vmprof.c index f96feb20..e51dc9e3 100644 --- a/src/_vmprof.c +++ b/src/_vmprof.c @@ -393,7 +393,7 @@ insert_real_time_thread(PyObject *module, PyObject * noargs) { } vmprof_aquire_lock(); - thread_count = insert_thread(pthread_self(), -1); + thread_count = insert_thread(GET_THREAD_ID(), -1); vmprof_release_lock(); return PyLong_FromSsize_t(thread_count); @@ -414,7 +414,7 @@ remove_real_time_thread(PyObject *module, PyObject * noargs) { } vmprof_aquire_lock(); - thread_count = remove_thread(pthread_self(), -1); + thread_count = remove_thread(GET_THREAD_ID(), -1); vmprof_release_lock(); return PyLong_FromSsize_t(thread_count); diff --git a/src/vmprof_common.c b/src/vmprof_common.c index d81b9119..eb64d51a 100644 --- a/src/vmprof_common.c +++ b/src/vmprof_common.c @@ -28,7 +28,7 @@ static long profile_interval_usec = 0; #ifdef VMPROF_UNIX static int signal_type = SIGPROF; static int itimer_type = ITIMER_PROF; -static pthread_t *threads = NULL; +static THREAD_ID *threads = NULL; static size_t threads_size = 0; static size_t thread_count = 0; static size_t threads_size_step = 8; @@ -221,19 +221,19 @@ intptr_t vmprof_get_traceback(void *stack, void *ucontext, #ifdef VMPROF_UNIX -ssize_t search_thread(pthread_t tid, ssize_t i) +ssize_t search_thread(THREAD_ID tid, ssize_t i) { if (i < 0) i = 0; while ((size_t)i < thread_count) { - if (pthread_equal(threads[i], tid)) + if (THREAD_EQUALS(threads[i], tid)) return i; i++; } return -1; } -ssize_t insert_thread(pthread_t tid, ssize_t i) +ssize_t insert_thread(THREAD_ID tid, ssize_t i) { assert(signal_type == SIGALRM); i = search_thread(tid, i); @@ -241,15 +241,15 @@ ssize_t insert_thread(pthread_t tid, ssize_t i) return -1; if (thread_count == threads_size) { threads_size += threads_size_step; - threads = realloc(threads, sizeof(pid_t) * threads_size); + threads = realloc(threads, sizeof(THREAD_ID) * threads_size); assert(threads != NULL); - memset(threads + thread_count, 0, sizeof(pid_t) * threads_size_step); + memset(threads + thread_count, 0, sizeof(THREAD_ID) * threads_size_step); } threads[thread_count++] = tid; return thread_count; } -ssize_t remove_thread(pthread_t tid, ssize_t i) +ssize_t remove_thread(THREAD_ID tid, ssize_t i) { assert(signal_type == SIGALRM); if (thread_count == 0) @@ -280,13 +280,14 @@ int broadcast_signal_for_threads(void) { int done = 1; size_t i = 0; - pthread_t self = pthread_self(); - pthread_t tid; + THREAD_ID self = GET_THREAD_ID(); + THREAD_ID tid; + pid_t pid = getpid(); while (i < thread_count) { tid = threads[i]; - if (pthread_equal(tid, self)) { + if (THREAD_EQUALS(tid, self)) { done = 0; - } else if (pthread_kill(tid, SIGALRM)) { + } else if (THREAD_SIGNAL(pid, tid, SIGALRM)) { remove_thread(tid, i); } i++; diff --git a/src/vmprof_common.h b/src/vmprof_common.h index 9f55f796..5d496539 100644 --- a/src/vmprof_common.h +++ b/src/vmprof_common.h @@ -21,15 +21,31 @@ #ifdef VMPROF_LINUX #include +#define THREAD_ID pid_t +#define GET_THREAD_ID() ((pid_t) syscall(SYS_gettid)) +#define THREAD_EQUALS(thread_one, thread_two) (thread_one == thread_two) +#define THREAD_SIGNAL(pid, tid, signal) syscall(SYS_tgkill, pid, tid, signal) +#else +#ifdef VMPROF_UNIX +#define THREAD_ID pthread_t +#define GET_THREAD_ID() ((pthread_t) pthread_self()) +#define THREAD_EQUALS(thread_one, thread_two) pthread_equal(thread_one, thread_two) +#define THREAD_SIGNAL(pid, tid, signal) pthread_kill(tid, signal) +#endif #endif #define MAX_FUNC_NAME 1024 +#ifdef VMPROF_LINUX +#else +#define THREAD_ID_TYPE +#endif + #ifdef VMPROF_UNIX -ssize_t search_thread(pthread_t tid, ssize_t i); -ssize_t insert_thread(pthread_t tid, ssize_t i); -ssize_t remove_thread(pthread_t tid, ssize_t i); +ssize_t search_thread(THREAD_ID tid, ssize_t i); +ssize_t insert_thread(THREAD_ID tid, ssize_t i); +ssize_t remove_thread(THREAD_ID tid, ssize_t i); ssize_t remove_threads(void); #endif diff --git a/src/vmprof_unix.c b/src/vmprof_unix.c index 1a85a10c..766e630d 100644 --- a/src/vmprof_unix.c +++ b/src/vmprof_unix.c @@ -359,7 +359,7 @@ int vmprof_enable(int memory, int native, int real_time) if (memory && setup_rss() == -1) goto error; #if VMPROF_UNIX - if (real_time && insert_thread(pthread_self(), -1) == -1) + if (real_time && insert_thread(GET_THREAD_ID(), -1) == -1) goto error; #endif if (install_pthread_atfork_hooks() == -1) diff --git a/vmprof/test/test_run.py b/vmprof/test/test_run.py index c6634442..3c6206a2 100644 --- a/vmprof/test/test_run.py +++ b/vmprof/test/test_run.py @@ -84,7 +84,7 @@ def functime_foo(t=0.05, insert=False): if (insert): thread_count = vmprof.insert_real_time_thread() else: - thread_count = -1 + thread_count = -2 sys.stderr.writelines("foo:%i:%i\n" % (thread_id, thread_count)) return time.sleep(t) @@ -95,7 +95,7 @@ def functime_bar(t=0.05, remove=False): if (remove): thread_count = vmprof.remove_real_time_thread() else: - thread_count = None + thread_count = -2 sys.stderr.writelines("bar:%i:%i\n" % (thread_id, thread_count)) return time.sleep(t) From c852425cf05c6567807735a328a3846ecdcb8aa8 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20Wr=C3=B3blewski?= Date: Thu, 24 Aug 2017 12:18:27 +0200 Subject: [PATCH 4/8] Even more details. --- vmprof/test/test_run.py | 19 ++++++++++++++----- 1 file changed, 14 insertions(+), 5 deletions(-) diff --git a/vmprof/test/test_run.py b/vmprof/test/test_run.py index 3c6206a2..6adf01a7 100644 --- a/vmprof/test/test_run.py +++ b/vmprof/test/test_run.py @@ -79,8 +79,11 @@ def function_bar(): def functime_foo(t=0.05, insert=False): - import threading - thread_id = threading.get_ident() + if PY3K: + from threading import get_ident + else: + from thread import get_ident + thread_id = get_ident() if (insert): thread_count = vmprof.insert_real_time_thread() else: @@ -90,8 +93,11 @@ def functime_foo(t=0.05, insert=False): def functime_bar(t=0.05, remove=False): - import threading - thread_id = threading.get_ident() + if PY3K: + from threading import get_ident + else: + from thread import get_ident + thread_id = get_ident() if (remove): thread_count = vmprof.remove_real_time_thread() else: @@ -275,16 +281,19 @@ def test_vmprof_real_time(): ]) def test_vmprof_real_time_threaded(insert_foo, remove_bar): import threading + import pprint prof = vmprof.Profiler() wait = 0.5 thread = threading.Thread(target=functime_foo, args=[wait, insert_foo]) - with prof.measure(period=0.25, real_time=True): + with prof.measure(period=wait/4, real_time=True): thread.start() functime_bar(wait, remove_bar) thread.join() stats = prof.get_stats() tprof = stats.top_profile() d = dict(tprof) + f = pprint.pformat(d) + '\n' + sys.stderr.writelines(f) assert insert_foo == (foo_time_name in d) assert remove_bar != (bar_time_name in d) From c2a7ae9c21cde4e42c613318c8aebc533f519e68 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20Wr=C3=B3blewski?= Date: Thu, 24 Aug 2017 13:51:03 +0200 Subject: [PATCH 5/8] Two different bugs? --- vmprof/stats.py | 12 ++++++++++++ vmprof/test/test_run.py | 3 ++- 2 files changed, 14 insertions(+), 1 deletion(-) diff --git a/vmprof/stats.py b/vmprof/stats.py index ee81f18e..2eb16a67 100644 --- a/vmprof/stats.py +++ b/vmprof/stats.py @@ -76,6 +76,18 @@ def generate_top(self): self.functions[addr] = self.functions.get(addr, 0) + 1 current_iter[addr] = None + def all_profile(self): + all_functions = {} + for profile in self.profiles: + 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 + else: + all_functions[addr] = all_functions.get(addr, 0) + 1 + return [(self._get_name(k), v) for (k, v) in six.iteritems(all_functions)] + def top_profile(self): return [(self._get_name(k), v) for (k, v) in six.iteritems(self.functions)] diff --git a/vmprof/test/test_run.py b/vmprof/test/test_run.py index 6adf01a7..b64600d1 100644 --- a/vmprof/test/test_run.py +++ b/vmprof/test/test_run.py @@ -291,8 +291,9 @@ def test_vmprof_real_time_threaded(insert_foo, remove_bar): thread.join() stats = prof.get_stats() tprof = stats.top_profile() + aprof = stats.all_profile() d = dict(tprof) - f = pprint.pformat(d) + '\n' + f = pprint.pformat(d) + '\n' + pprint.pformat(dict(aprof)) + '\n' sys.stderr.writelines(f) assert insert_foo == (foo_time_name in d) assert remove_bar != (bar_time_name in d) From 82c192082587973d15ad4f1756b217dd73f196e1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20Wr=C3=B3blewski?= Date: Thu, 24 Aug 2017 13:58:42 +0200 Subject: [PATCH 6/8] When all else fails, sleep better. --- vmprof/test/test_run.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/vmprof/test/test_run.py b/vmprof/test/test_run.py index b64600d1..b7e80218 100644 --- a/vmprof/test/test_run.py +++ b/vmprof/test/test_run.py @@ -283,9 +283,9 @@ def test_vmprof_real_time_threaded(insert_foo, remove_bar): import threading import pprint prof = vmprof.Profiler() - wait = 0.5 + wait = 10.0 thread = threading.Thread(target=functime_foo, args=[wait, insert_foo]) - with prof.measure(period=wait/4, real_time=True): + with prof.measure(period=wait/999, real_time=True): thread.start() functime_bar(wait, remove_bar) thread.join() From b81743a79aae342da415268b34dffb92d3b38b11 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20Wr=C3=B3blewski?= Date: Mon, 5 Nov 2018 21:25:20 -0800 Subject: [PATCH 7/8] Quick check. --- vmprof/test/test_run.py | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/vmprof/test/test_run.py b/vmprof/test/test_run.py index b7e80218..5d156fad 100644 --- a/vmprof/test/test_run.py +++ b/vmprof/test/test_run.py @@ -89,7 +89,10 @@ def functime_foo(t=0.05, insert=False): else: thread_count = -2 sys.stderr.writelines("foo:%i:%i\n" % (thread_id, thread_count)) - return time.sleep(t) + # HACK: sleep many times, hopefully giving the profiler a chance to grab our stack trace + for i in range(10): + time.sleep(t / 10) + return def functime_bar(t=0.05, remove=False): @@ -103,7 +106,10 @@ def functime_bar(t=0.05, remove=False): else: thread_count = -2 sys.stderr.writelines("bar:%i:%i\n" % (thread_id, thread_count)) - return time.sleep(t) + # HACK: sleep many times, hopefully giving the profiler a chance to grab our stack trace + for i in range(10): + time.sleep(t / 10) + return foo_full_name = "py:function_foo:%d:%s" % (function_foo.__code__.co_firstlineno, From ae0092d0503314dd9e8ede4f5678450b84159122 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bartosz=20Wr=C3=B3blewski?= Date: Mon, 5 Nov 2018 21:55:19 -0800 Subject: [PATCH 8/8] Run the integration tests again. --- vmprof/test/test_run.py | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/vmprof/test/test_run.py b/vmprof/test/test_run.py index 5d156fad..69ff93e2 100644 --- a/vmprof/test/test_run.py +++ b/vmprof/test/test_run.py @@ -89,9 +89,7 @@ def functime_foo(t=0.05, insert=False): else: thread_count = -2 sys.stderr.writelines("foo:%i:%i\n" % (thread_id, thread_count)) - # HACK: sleep many times, hopefully giving the profiler a chance to grab our stack trace - for i in range(10): - time.sleep(t / 10) + time.sleep(t) return @@ -106,9 +104,7 @@ def functime_bar(t=0.05, remove=False): else: thread_count = -2 sys.stderr.writelines("bar:%i:%i\n" % (thread_id, thread_count)) - # HACK: sleep many times, hopefully giving the profiler a chance to grab our stack trace - for i in range(10): - time.sleep(t / 10) + time.sleep(t) return @@ -289,9 +285,9 @@ def test_vmprof_real_time_threaded(insert_foo, remove_bar): import threading import pprint prof = vmprof.Profiler() - wait = 10.0 + wait = 0.5 thread = threading.Thread(target=functime_foo, args=[wait, insert_foo]) - with prof.measure(period=wait/999, real_time=True): + with prof.measure(period=wait/5, real_time=True): thread.start() functime_bar(wait, remove_bar) thread.join()