[pypy-commit] stmgc default: Starting on reporting timings, more directly than in the 'timelog'
arigo
noreply at buildbot.pypy.org
Sun Mar 30 19:14:02 CEST 2014
Author: Armin Rigo <arigo at tunes.org>
Branch:
Changeset: r1119:e1c90b6ac3f8
Date: 2014-03-30 19:13 +0200
http://bitbucket.org/pypy/stmgc/changeset/e1c90b6ac3f8/
Log: Starting on reporting timings, more directly than in the 'timelog'
branch but without tracebacks
diff --git a/c7/demo/Makefile b/c7/demo/Makefile
--- a/c7/demo/Makefile
+++ b/c7/demo/Makefile
@@ -17,22 +17,20 @@
H_FILES = ../stmgc.h ../stm/*.h
C_FILES = ../stmgc.c ../stm/*.c
+COMMON = -I.. -pthread -lrt -g -Wall -Werror
+
# note that 'build' is partially optimized but still contains all asserts
debug-%: %.c ${H_FILES} ${C_FILES}
- clang -I.. -pthread -DSTM_DEBUGPRINT -DSTM_GC_NURSERY=128 -g -O0 \
- $< -o debug-$* -Wall -Werror ../stmgc.c
+ clang $(COMMON) -DSTM_DEBUGPRINT -DSTM_GC_NURSERY=128 -O0 \
+ $< -o debug-$* ../stmgc.c
build-%: %.c ${H_FILES} ${C_FILES}
- clang -I.. -pthread -DSTM_GC_NURSERY=128 -g -O1 \
- $< -o build-$* -Wall -Werror ../stmgc.c
+ clang $(COMMON) -DSTM_GC_NURSERY=128 -O1 $< -o build-$* ../stmgc.c
release-%: %.c ${H_FILES} ${C_FILES}
- clang -I.. -pthread -g -DNDEBUG -O2 $< -o release-$* \
- -Wall -Werror ../stmgc.c
+ clang $(COMMON) -DNDEBUG -O2 $< -o release-$* ../stmgc.c
release-htm-%: %.c ../../htm-c7/stmgc.? ../../htm-c7/htm.h
- clang -I.. -pthread -g -O2 $< -o release-htm-$* ../../htm-c7/stmgc.c -Wall -DUSE_HTM
-
-
+ clang $(COMMON) -O2 $< -o release-htm-$* ../../htm-c7/stmgc.c -DUSE_HTM
diff --git a/c7/stm/core.c b/c7/stm/core.c
--- a/c7/stm/core.c
+++ b/c7/stm/core.c
@@ -172,7 +172,7 @@
retry:
if (jmpbuf == NULL) {
- wait_for_end_of_inevitable_transaction(false);
+ wait_for_end_of_inevitable_transaction(tl);
}
if (!acquire_thread_segment(tl))
@@ -181,6 +181,8 @@
assert(STM_PSEGMENT->safe_point == SP_NO_TRANSACTION);
assert(STM_PSEGMENT->transaction_state == TS_NONE);
+ change_timing_state(STM_TIME_RUN_CURRENT);
+ STM_PSEGMENT->start_time = tl->_timing_cur_start;
STM_PSEGMENT->safe_point = SP_RUNNING;
STM_PSEGMENT->transaction_state = (jmpbuf != NULL ? TS_REGULAR
: TS_INEVITABLE);
@@ -433,7 +435,7 @@
list_clear(STM_PSEGMENT->modified_old_objects);
}
-static void _finish_transaction(void)
+static void _finish_transaction(enum stm_time_e attribute_to)
{
STM_PSEGMENT->safe_point = SP_NO_TRANSACTION;
STM_PSEGMENT->transaction_state = TS_NONE;
@@ -442,6 +444,8 @@
LIST_FREE(STM_PSEGMENT->objects_pointing_to_nursery);
LIST_FREE(STM_PSEGMENT->large_overflow_objects);
+ timing_end_transaction(attribute_to);
+
stm_thread_local_t *tl = STM_SEGMENT->running_thread;
release_thread_segment(tl);
/* cannot access STM_SEGMENT or STM_PSEGMENT from here ! */
@@ -505,7 +509,7 @@
}
/* done */
- _finish_transaction();
+ _finish_transaction(STM_TIME_RUN_COMMITTED);
/* cannot access STM_SEGMENT or STM_PSEGMENT from here ! */
s_mutex_unlock();
@@ -635,7 +639,7 @@
: NURSERY_END;
}
- _finish_transaction();
+ _finish_transaction(STM_TIME_RUN_ABORTED_OTHER);
/* cannot access STM_SEGMENT or STM_PSEGMENT from here ! */
/* Broadcast C_ABORTED to wake up contention.c */
@@ -668,7 +672,7 @@
if (STM_PSEGMENT->transaction_state == TS_REGULAR) {
dprintf(("become_inevitable: %s\n", msg));
- wait_for_end_of_inevitable_transaction(true);
+ wait_for_end_of_inevitable_transaction(NULL);
STM_PSEGMENT->transaction_state = TS_INEVITABLE;
STM_SEGMENT->jmpbuf_ptr = NULL;
clear_callbacks_on_abort();
diff --git a/c7/stm/core.h b/c7/stm/core.h
--- a/c7/stm/core.h
+++ b/c7/stm/core.h
@@ -121,7 +121,7 @@
/* Start time: to know approximately for how long a transaction has
been running, in contention management */
- uint64_t start_time;
+ double start_time;
/* This is the number stored in the overflowed objects (a multiple of
GCFLAG_OVERFLOW_NUMBER_bit0). It is incremented when the
diff --git a/c7/stm/gcpage.c b/c7/stm/gcpage.c
--- a/c7/stm/gcpage.c
+++ b/c7/stm/gcpage.c
@@ -134,11 +134,15 @@
if (is_major_collection_requested()) { /* if still true */
+ enum stm_time_e oldstate = change_timing_state(STM_TIME_MAJOR_GC);
+
synchronize_all_threads(STOP_OTHERS_UNTIL_MUTEX_UNLOCK);
if (is_major_collection_requested()) { /* if *still* true */
major_collection_now_at_safe_point();
}
+
+ change_timing_state(oldstate);
}
s_mutex_unlock();
diff --git a/c7/stm/nursery.c b/c7/stm/nursery.c
--- a/c7/stm/nursery.c
+++ b/c7/stm/nursery.c
@@ -318,7 +318,11 @@
stm_safe_point();
+ change_timing_state(STM_TIME_MINOR_GC);
+
_do_minor_collection(commit);
+
+ change_timing_state(commit ? STM_TIME_BOOKKEEPING : STM_TIME_RUN_CURRENT);
}
void stm_collect(long level)
diff --git a/c7/stm/setup.c b/c7/stm/setup.c
--- a/c7/stm/setup.c
+++ b/c7/stm/setup.c
@@ -169,6 +169,8 @@
num = tl->prev->associated_segment_num;
}
tl->thread_local_obj = NULL;
+ tl->_timing_cur_state = STM_TIME_OUTSIDE_TRANSACTION;
+ tl->_timing_cur_start = get_stm_time();
/* assign numbers consecutively, but that's for tests; we could also
assign the same number to all of them and they would get their own
diff --git a/c7/stm/sync.c b/c7/stm/sync.c
--- a/c7/stm/sync.c
+++ b/c7/stm/sync.c
@@ -31,7 +31,6 @@
pthread_cond_t cond[_C_TOTAL];
/* some additional pieces of global state follow */
uint8_t in_use1[NB_SEGMENTS]; /* 1 if running a pthread */
- uint64_t global_time;
};
char reserved[192];
} sync_ctl __attribute__((aligned(64)));
@@ -120,13 +119,14 @@
/************************************************************/
-static void wait_for_end_of_inevitable_transaction(bool can_abort)
+static void wait_for_end_of_inevitable_transaction(
+ stm_thread_local_t *tl_or_null_if_can_abort)
{
long i;
restart:
for (i = 1; i <= NB_SEGMENTS; i++) {
if (get_priv_segment(i)->transaction_state == TS_INEVITABLE) {
- if (can_abort) {
+ if (tl_or_null_if_can_abort == NULL) {
/* handle this case like a contention: it will either
abort us (not the other thread, which is inevitable),
or wait for a while. If we go past this call, then we
@@ -137,7 +137,11 @@
else {
/* wait for stm_commit_transaction() to finish this
inevitable transaction */
+ change_timing_state_tl(tl_or_null_if_can_abort,
+ STM_TIME_WAIT_INEVITABLE);
cond_wait(C_INEVITABLE);
+ /* don't bother changing the timing state again: the caller
+ will very soon go to STM_TIME_RUN_CURRENT */
}
goto restart;
}
@@ -188,7 +192,6 @@
assert(STM_SEGMENT->segment_num == num);
assert(STM_SEGMENT->running_thread == NULL);
STM_SEGMENT->running_thread = tl;
- STM_PSEGMENT->start_time = ++sync_ctl.global_time;
return true;
}
diff --git a/c7/stm/sync.h b/c7/stm/sync.h
--- a/c7/stm/sync.h
+++ b/c7/stm/sync.h
@@ -28,7 +28,7 @@
static bool acquire_thread_segment(stm_thread_local_t *tl);
static void release_thread_segment(stm_thread_local_t *tl);
-static void wait_for_end_of_inevitable_transaction(bool can_abort);
+static void wait_for_end_of_inevitable_transaction(stm_thread_local_t *);
enum sync_type_e {
STOP_OTHERS_UNTIL_MUTEX_UNLOCK,
diff --git a/c7/stm/timing.c b/c7/stm/timing.c
new file mode 100644
--- /dev/null
+++ b/c7/stm/timing.c
@@ -0,0 +1,44 @@
+#ifndef _STM_CORE_H_
+# error "must be compiled via stmgc.c"
+#endif
+
+
+static inline void add_timing(stm_thread_local_t *tl, enum stm_time_e category,
+ double elapsed)
+{
+ tl->timing[category] += elapsed;
+}
+
+#define TIMING_CHANGE(tl, newstate) \
+ double curtime = get_stm_time(); \
+ double elasped = curtime - tl->_timing_cur_start; \
+ enum stm_time_e oldstate = tl->_timing_cur_state; \
+ add_timing(tl, oldstate, elasped); \
+ tl->_timing_cur_state = newstate; \
+ tl->_timing_cur_start = curtime
+
+static enum stm_time_e change_timing_state(enum stm_time_e newstate)
+{
+ stm_thread_local_t *tl = STM_SEGMENT->running_thread;
+ TIMING_CHANGE(tl, newstate);
+ return oldstate;
+}
+
+static void change_timing_state_tl(stm_thread_local_t *tl,
+ enum stm_time_e newstate)
+{
+ TIMING_CHANGE(tl, newstate);
+}
+
+static void timing_end_transaction(enum stm_time_e attribute_to)
+{
+ stm_thread_local_t *tl = STM_SEGMENT->running_thread;
+ TIMING_CHANGE(tl, STM_TIME_OUTSIDE_TRANSACTION);
+ add_timing(tl, attribute_to, tl->timing[STM_TIME_RUN_CURRENT]);
+ tl->timing[STM_TIME_RUN_CURRENT] = 0.0f;
+}
+
+void stm_flush_timing(stm_thread_local_t *tl)
+{
+ change_timing_state_tl(tl, tl->_timing_cur_state);
+}
diff --git a/c7/stm/timing.h b/c7/stm/timing.h
new file mode 100644
--- /dev/null
+++ b/c7/stm/timing.h
@@ -0,0 +1,14 @@
+#include <time.h>
+
+static inline double get_stm_time(void)
+{
+ struct timespec tp;
+ clock_gettime(CLOCK_MONOTONIC, &tp);
+ return tp.tv_sec + tp.tv_nsec * 0.000000001;
+}
+
+static enum stm_time_e change_timing_state(enum stm_time_e newstate);
+static void change_timing_state_tl(stm_thread_local_t *tl,
+ enum stm_time_e newstate);
+
+static void timing_end_transaction(enum stm_time_e attribute_to);
diff --git a/c7/stmgc.c b/c7/stmgc.c
--- a/c7/stmgc.c
+++ b/c7/stmgc.c
@@ -13,6 +13,7 @@
#include "stm/extra.h"
#include "stm/fprintcolor.h"
#include "stm/weakref.h"
+#include "stm/timing.h"
#include "stm/misc.c"
#include "stm/list.c"
@@ -31,3 +32,4 @@
#include "stm/extra.c"
#include "stm/fprintcolor.c"
#include "stm/weakref.c"
+#include "stm/timing.c"
diff --git a/c7/stmgc.h b/c7/stmgc.h
--- a/c7/stmgc.h
+++ b/c7/stmgc.h
@@ -54,6 +54,25 @@
object_t *ss;
};
+enum stm_time_e {
+ STM_TIME_OUTSIDE_TRANSACTION,
+ STM_TIME_RUN_CURRENT,
+ STM_TIME_RUN_COMMITTED,
+ STM_TIME_RUN_ABORTED_WRITE_WRITE,
+ STM_TIME_RUN_ABORTED_WRITE_READ,
+ STM_TIME_RUN_ABORTED_INEVITABLE,
+ STM_TIME_RUN_ABORTED_OTHER,
+ STM_TIME_WAIT_FREE_SEGMENT,
+ STM_TIME_WAIT_WRITE_WRITE,
+ STM_TIME_WAIT_WRITE_READ,
+ STM_TIME_WAIT_INEVITABLE,
+ STM_TIME_BOOKKEEPING,
+ STM_TIME_MINOR_GC,
+ STM_TIME_MAJOR_GC,
+ STM_TIME_SYNC_PAUSE,
+ _STM_TIME_N
+};
+
typedef struct stm_thread_local_s {
/* every thread should handle the shadow stack itself */
struct stm_shadowentry_s *shadowstack, *shadowstack_base;
@@ -66,6 +85,10 @@
/* after an abort, some details about the abort are stored there.
(these fields are not modified on a successful commit) */
long last_abort__bytes_in_nursery;
+ /* timing information, accumulated */
+ float timing[_STM_TIME_N];
+ double _timing_cur_start;
+ enum stm_time_e _timing_cur_state;
/* the next fields are handled internally by the library */
int associated_segment_num;
struct stm_thread_local_s *prev, *next;
@@ -336,6 +359,10 @@
const char *msg);
+/* Temporary? */
+void stm_flush_timing(stm_thread_local_t *);
+
+
/* ==================== END ==================== */
#endif
diff --git a/c7/test/support.py b/c7/test/support.py
--- a/c7/test/support.py
+++ b/c7/test/support.py
@@ -24,6 +24,7 @@
size_t mem_bytes_to_clear_on_abort;
long last_abort__bytes_in_nursery;
int associated_segment_num;
+ float timing[];
...;
} stm_thread_local_t;
@@ -98,6 +99,24 @@
int stm_can_move(object_t *);
void stm_call_on_abort(stm_thread_local_t *, void *key, void callback(void *));
+
+#define STM_TIME_OUTSIDE_TRANSACTION ...
+#define STM_TIME_RUN_CURRENT ...
+#define STM_TIME_RUN_COMMITTED ...
+#define STM_TIME_RUN_ABORTED_WRITE_WRITE ...
+#define STM_TIME_RUN_ABORTED_WRITE_READ ...
+#define STM_TIME_RUN_ABORTED_INEVITABLE ...
+#define STM_TIME_RUN_ABORTED_OTHER ...
+#define STM_TIME_WAIT_FREE_SEGMENT ...
+#define STM_TIME_WAIT_WRITE_WRITE ...
+#define STM_TIME_WAIT_WRITE_READ ...
+#define STM_TIME_WAIT_INEVITABLE ...
+#define STM_TIME_BOOKKEEPING ...
+#define STM_TIME_MINOR_GC ...
+#define STM_TIME_MAJOR_GC ...
+#define STM_TIME_SYNC_PAUSE ...
+
+void stm_flush_timing(stm_thread_local_t *);
""")
@@ -261,6 +280,7 @@
undef_macros=['NDEBUG'],
include_dirs=[parent_dir],
extra_compile_args=['-g', '-O0', '-Werror', '-ferror-limit=1'],
+ extra_link_args=['-g', '-lrt'],
force_generic_engine=True)
diff --git a/c7/test/test_timing.py b/c7/test/test_timing.py
new file mode 100644
--- /dev/null
+++ b/c7/test/test_timing.py
@@ -0,0 +1,37 @@
+from support import *
+import py, time
+
+
+class TestTiming(BaseTest):
+
+ def gettimer(self, n):
+ tl = self.tls[self.current_thread]
+ lib.stm_flush_timing(tl)
+ return tl.timing[n]
+
+ def expect_timer(self, n, expected_value):
+ real = self.gettimer(n)
+ print 'timer %d is %s, expecting %s' % (n, real, expected_value)
+ assert abs(real - expected_value) < 0.09
+
+ def test_time_outside_transaction(self):
+ time.sleep(0.2)
+ self.start_transaction()
+ self.commit_transaction()
+ self.expect_timer(lib.STM_TIME_OUTSIDE_TRANSACTION, 0.2)
+
+ def test_time_run_current(self):
+ self.start_transaction()
+ time.sleep(0.1)
+ self.expect_timer(lib.STM_TIME_RUN_CURRENT, 0.1)
+ time.sleep(0.1)
+ self.expect_timer(lib.STM_TIME_RUN_CURRENT, 0.2)
+ self.commit_transaction()
+ self.expect_timer(lib.STM_TIME_RUN_CURRENT, 0.0)
+
+ def test_time_run_committed(self):
+ self.start_transaction()
+ time.sleep(0.2)
+ self.expect_timer(lib.STM_TIME_RUN_COMMITTED, 0.0)
+ self.commit_transaction()
+ self.expect_timer(lib.STM_TIME_RUN_COMMITTED, 0.2)
diff --git a/duhton/Makefile b/duhton/Makefile
--- a/duhton/Makefile
+++ b/duhton/Makefile
@@ -3,34 +3,36 @@
C7HEADERS = ../c7/stmgc.h ../c7/stm/*.h
+COMMON = -pthread -lrt -g -Wall
-all: duhton_debug duhton
+
+all: duhton_debug duhton
duhton: *.c *.h $(C7SOURCES) $(C7HEADERS)
- clang -pthread -g -O2 -o duhton *.c ../c7/stmgc.c -Wall
+ clang $(COMMON) -O2 -o duhton *.c ../c7/stmgc.c
duhton_release: *.c *.h $(C7SOURCES) $(C7HEADERS)
- clang -pthread -g -DNDEBUG -O2 -o duhton_release *.c ../c7/stmgc.c -Wall
+ clang $(COMMON) -DNDEBUG -O2 -o duhton_release *.c ../c7/stmgc.c
duhton_debug: *.c *.h $(C7SOURCES) $(C7HEADERS)
- clang -DSTM_DEBUGPRINT -pthread -g -DDu_DEBUG -o duhton_debug *.c ../c7/stmgc.c -Wall
+ clang -DSTM_DEBUGPRINT $(COMMON) -DDu_DEBUG -o duhton_debug *.c ../c7/stmgc.c
duhton_nostm: *.c *.h ../gil-c7/stmgc.?
- clang -pthread -g -DNDEBUG -O2 -o duhton_nostm *.c ../gil-c7/stmgc.c -Wall -DUSE_GIL
+ clang $(COMMON) -DNDEBUG -O2 -o duhton_nostm *.c ../gil-c7/stmgc.c -DUSE_GIL
duhton_debug_nostm: *.c *.h ../gil-c7/stmgc.?
- clang -DSTM_DEBUGPRINT -pthread -g -DDu_DEBUG -o duhton_debug_nostm *.c ../gil-c7/stmgc.c -Wall -DUSE_GIL -ferror-limit=1
+ clang -DSTM_DEBUGPRINT $(COMMON) -DDu_DEBUG -o duhton_debug_nostm *.c ../gil-c7/stmgc.c -DUSE_GIL -ferror-limit=1
duhton_htm: *.c *.h ../htm-c7/stmgc.? ../htm-c7/htm.h
- clang -pthread -g -DNDEBUG -O2 -o duhton_htm *.c ../htm-c7/stmgc.c -Wall -DUSE_HTM
+ clang $(COMMON) -DNDEBUG -O2 -o duhton_htm *.c ../htm-c7/stmgc.c -DUSE_HTM
duhton_debug_htm: *.c *.h ../htm-c7/stmgc.? ../htm-c7/htm.h
- clang -DSTM_DEBUGPRINT -pthread -g -DDu_DEBUG -o duhton_debug_htm *.c ../htm-c7/stmgc.c -Wall -DUSE_HTM -ferror-limit=1
+ clang -DSTM_DEBUGPRINT $(COMMON) -DDu_DEBUG -o duhton_debug_htm *.c ../htm-c7/stmgc.c -DUSE_HTM -ferror-limit=1
clean:
More information about the pypy-commit
mailing list