[pypy-commit] stmgc c8-long-transactions: Merge overheads instrumentation
tobweber
pypy.commits at gmail.com
Mon Apr 10 04:33:47 EDT 2017
Author: Tobias Weber <tobias_weber89 at gmx.de>
Branch: c8-long-transactions
Changeset: r2038:1c544f12ca42
Date: 2017-04-10 10:32 +0200
http://bitbucket.org/pypy/stmgc/changeset/1c544f12ca42/
Log: Merge overheads instrumentation
diff --git a/c8/stm/core.c b/c8/stm/core.c
--- a/c8/stm/core.c
+++ b/c8/stm/core.c
@@ -158,6 +158,9 @@
{
/* returns true if we reached a valid state, or false if
we need to abort now */
+ start_timer();
+ stm_thread_local_t *thread_local_for_logging = STM_SEGMENT->running_thread;
+
dprintf(("_stm_validate() at cl=%p, rev=%lu\n", STM_PSEGMENT->last_commit_log_entry,
STM_PSEGMENT->last_commit_log_entry->rev_num));
/* go from last known entry in commit log to the
@@ -171,6 +174,11 @@
if (STM_PSEGMENT->transaction_state == TS_INEVITABLE) {
assert(first_cl->next == INEV_RUNNING);
+
+ if (thread_local_for_logging != NULL) {
+ stop_timer_and_publish_for_thread(
+ thread_local_for_logging, STM_DURATION_VALIDATION);
+ }
return true;
}
@@ -338,6 +346,11 @@
release_privatization_lock(my_segnum);
}
+ if (thread_local_for_logging != NULL) {
+ stop_timer_and_publish_for_thread(
+ thread_local_for_logging, STM_DURATION_VALIDATION);
+ }
+
return !needs_abort;
}
@@ -346,6 +359,8 @@
{
/* puts all modified_old_objects in a new commit log entry */
+ start_timer();
+
// we don't need the privatization lock, as we are only
// reading from modified_old_objs and nobody but us can change it
struct list_s *list = STM_PSEGMENT->modified_old_objects;
@@ -358,6 +373,9 @@
result->rev_num = -1; /* invalid */
result->written_count = count;
memcpy(result->written, list->items, count * sizeof(struct stm_undo_s));
+
+ stop_timer_and_publish(STM_DURATION_CREATE_CLE);
+
return result;
}
@@ -400,6 +418,8 @@
*/
static void _validate_and_attach(struct stm_commit_log_entry_s *new)
{
+ start_timer();
+
uintptr_t cle_length = 0;
struct stm_commit_log_entry_s *old;
@@ -412,10 +432,17 @@
soon_finished_or_inevitable_thread_segment();
retry_from_start:
+ pause_timer();
if (!_stm_validate()) {
+ continue_timer();
+
free_cle(new);
- stm_abort_transaction();
+
+ stop_timer_and_publish(STM_DURATION_VALIDATION);
+
+ stm_abort_transaction(); // leaves method by longjump
}
+ continue_timer();
if (cle_length != list_count(STM_PSEGMENT->modified_old_objects)) {
/* something changed the list of modified objs during _stm_validate; or
@@ -475,6 +502,8 @@
dprintf(("_validate_and_attach(%p) failed, retrying\n", new));
goto retry_from_start;
}
+
+ stop_timer_and_publish(STM_DURATION_VALIDATION);
}
/* This is called to do stm_validate() and then attach INEV_RUNNING to
@@ -495,6 +524,8 @@
static void _validate_and_add_to_commit_log(void)
{
+ start_timer();
+
struct stm_commit_log_entry_s *old, *new;
new = _create_commit_log_entry();
@@ -523,8 +554,12 @@
release_modification_lock_wr(STM_SEGMENT->segment_num);
}
else {
+ pause_timer();
_validate_and_attach(new);
+ continue_timer();
}
+
+ stop_timer_and_publish(STM_DURATION_VALIDATION);
}
/* ############# STM ############# */
@@ -817,6 +852,8 @@
static void write_slowpath_common(object_t *obj, bool mark_card)
{
+ start_timer();
+
assert(_seems_to_be_running_transaction());
assert(!_is_in_nursery(obj));
assert(obj->stm_flags & GCFLAG_WRITE_BARRIER);
@@ -826,6 +863,8 @@
part again: */
assert(!(obj->stm_flags & GCFLAG_WB_EXECUTED));
write_slowpath_overflow_obj(obj, mark_card);
+
+ stop_timer_and_publish(STM_DURATION_WRITE_GC_ONLY);
return;
}
@@ -893,11 +932,15 @@
}
DEBUG_EXPECT_SEGFAULT(true);
+
+ stop_timer_and_publish(STM_DURATION_WRITE_SLOWPATH);
}
void _stm_write_slowpath_card(object_t *obj, uintptr_t index)
{
+ start_timer();
+
dprintf_test(("write_slowpath_card(%p, %lu)\n",
obj, index));
@@ -906,9 +949,15 @@
card marking instead. */
if (!(obj->stm_flags & GCFLAG_CARDS_SET)) {
bool mark_card = obj_should_use_cards(STM_SEGMENT->segment_base, obj);
+
+ pause_timer();
write_slowpath_common(obj, mark_card);
- if (!mark_card)
+ continue_timer();
+
+ if (!mark_card) {
+ stop_timer_and_publish(STM_DURATION_WRITE_SLOWPATH);
return;
+ }
}
assert(obj_should_use_cards(STM_SEGMENT->segment_base, obj));
@@ -955,13 +1004,13 @@
dprintf(("mark %p index %lu, card:%lu with %d\n",
obj, index, get_index_to_card_index(index), CARD_MARKED));
+
+ stop_timer_and_publish(STM_DURATION_WRITE_SLOWPATH);
}
__attribute__((flatten))
void _stm_write_slowpath(object_t *obj) {
- start_timer()
write_slowpath_common(obj, /* mark_card */ false);
- stop_timer_and_publish(STM_DURATION_WRITE_BARRIER)
}
@@ -1021,6 +1070,8 @@
static void _do_start_transaction(stm_thread_local_t *tl)
{
+ start_timer();
+
assert(!_stm_in_transaction(tl));
tl->wait_event_emitted = 0;
@@ -1084,6 +1135,8 @@
reset_transaction_read_version();
}
+ stop_timer_and_publish(STM_DURATION_START_TRX);
+
stm_validate();
}
@@ -1208,6 +1261,9 @@
static void _core_commit_transaction(bool external)
{
+ start_timer();
+ stm_thread_local_t *thread_local_for_logging = STM_SEGMENT->running_thread;
+
exec_local_finalizers();
assert(!_has_mutex());
@@ -1226,11 +1282,17 @@
assert(STM_SEGMENT->running_thread->wait_event_emitted == 0);
dprintf(("> stm_commit_transaction(external=%d)\n", (int)external));
+
+ pause_timer();
minor_collection(/*commit=*/ true, external);
+ continue_timer();
+
if (!external && is_major_collection_requested()) {
s_mutex_lock();
if (is_major_collection_requested()) { /* if still true */
+ pause_timer();
major_collection_with_mutex();
+ continue_timer();
}
s_mutex_unlock();
}
@@ -1246,7 +1308,10 @@
stm_validate() at the start of a new transaction is happy even
if there is an inevitable tx running) */
bool was_inev = STM_PSEGMENT->transaction_state == TS_INEVITABLE;
+
+ pause_timer();
_validate_and_add_to_commit_log();
+ continue_timer();
if (external) {
/* from this point on, unlink the original 'stm_thread_local_t *'
@@ -1295,6 +1360,9 @@
s_mutex_unlock();
+ stop_timer_and_publish_for_thread(
+ thread_local_for_logging, STM_DURATION_COMMIT_EXCEPT_GC);
+
/* between transactions, call finalizers. this will execute
a transaction itself */
if (tl != NULL)
diff --git a/c8/stm/gcpage.c b/c8/stm/gcpage.c
--- a/c8/stm/gcpage.c
+++ b/c8/stm/gcpage.c
@@ -747,9 +747,13 @@
dprintf((" .----- major collection -----------------------\n"));
assert(_has_mutex());
+ stm_thread_local_t *thread_local_for_logging = STM_SEGMENT->running_thread;
+
/* first, force a minor collection in each of the other segments */
major_do_validation_and_minor_collections();
+ start_timer();
+
dprintf((" | used before collection: %ld\n",
(long)pages_ctl.total_allocated));
dprintf((" | commit log entries before: %ld\n",
@@ -779,9 +783,12 @@
dprintf((" | used after collection: %ld\n",
(long)pages_ctl.total_allocated));
dprintf((" `----------------------------------------------\n"));
+
+ stop_timer_and_publish_for_thread(
+ thread_local_for_logging, STM_DURATION_MAJOR_GC_LOG_ONLY);
+
if (must_abort())
abort_with_mutex();
-
return;
#endif
}
@@ -836,6 +843,10 @@
must abort, do it now. The others are in safe-points that will
abort if they need to. */
dprintf(("must abort?:%d\n", (int)must_abort()));
+
+ stop_timer_and_publish_for_thread(
+ thread_local_for_logging, STM_DURATION_MAJOR_GC_FULL);
+
if (must_abort())
abort_with_mutex();
}
diff --git a/c8/stm/nursery.c b/c8/stm/nursery.c
--- a/c8/stm/nursery.c
+++ b/c8/stm/nursery.c
@@ -534,6 +534,8 @@
static void _do_minor_collection(bool commit)
{
+ start_timer();
+
dprintf(("minor_collection commit=%d\n", (int)commit));
assert(!STM_SEGMENT->no_safe_point_here);
@@ -578,6 +580,8 @@
throw_away_nursery(get_priv_segment(STM_SEGMENT->segment_num));
assert(MINOR_NOTHING_TO_DO(STM_PSEGMENT));
+
+ stop_timer_and_publish(STM_DURATION_MINOR_GC);
}
static void minor_collection(bool commit, bool external)
diff --git a/c8/stm/timing.h b/c8/stm/timing.h
--- a/c8/stm/timing.h
+++ b/c8/stm/timing.h
@@ -1,32 +1,48 @@
#include <time.h>
+#define continue_timer() clock_gettime(CLOCK_MONOTONIC_RAW, &start);
+
/* Use raw monotonic time, i.e., solely based on local hardware (no NTP
adjustments) as in prof.c to obtain values comparable with total program
runtime. */
-#define start_timer() struct timespec start; \
- clock_gettime(CLOCK_MONOTONIC_RAW, &start);
+#define start_timer() struct timespec start, stop; \
+ struct timespec duration = { .tv_sec = 0, .tv_nsec = 0 };\
+ uint32_t nanosec_diff, sec_diff; \
+ continue_timer()
-#define stop_timer() struct timespec stop; \
- clock_gettime(CLOCK_MONOTONIC_RAW, &stop);
+/* Must use start_timer before using this macro. */
+#define get_duration() nanosec_diff = stop.tv_nsec - start.tv_nsec; \
+ sec_diff = stop.tv_sec - start.tv_sec; \
+ if (stop.tv_nsec < start.tv_nsec) { \
+ nanosec_diff += 1000000000; \
+ sec_diff -= 1; \
+ } \
+ duration.tv_sec += sec_diff; \
+ duration.tv_nsec += nanosec_diff; \
+ if (duration.tv_nsec >= 1000000000) { \
+ duration.tv_sec += 1; \
+ duration.tv_nsec -= 1000000000; \
+ }
-/* Must use start_timer and stop_timer before using this macro. */
-#define get_duration() struct timespec duration = { \
- stop.tv_sec - start.tv_sec, \
- stop.tv_nsec - start.tv_nsec \
- };
+#define pause_timer() clock_gettime(CLOCK_MONOTONIC_RAW, &stop); \
+ get_duration()
-#define stm_duration_payload(duration) \
- stm_timing_event_payload_data_t stm_duration_data = \
- { .duration = &duration }; \
- stm_timing_event_payload_t stm_duration_payload = \
+#define stm_duration_payload(duration) \
+ stm_timing_event_payload_data_t stm_duration_data = \
+ { .duration = &duration }; \
+ stm_timing_event_payload_t stm_duration_payload = \
{ STM_EVENT_PAYLOAD_DURATION, stm_duration_data };
-#define publish_event(event) \
- (timing_enabled() ? \
- stmcb_timing_event(STM_SEGMENT->running_thread, event, &stm_duration_payload) : \
+#define publish_event(thread_local, event) \
+ (timing_enabled() ? \
+ stmcb_timing_event(thread_local, event, &stm_duration_payload) : \
(void)0);
-#define stop_timer_and_publish(event) stop_timer() \
- get_duration() \
- stm_duration_payload(duration) \
- publish_event(event)
+#define stop_timer_and_publish_for_thread(thread_local, event) \
+ pause_timer() \
+ stm_duration_payload(duration) \
+ assert(thread_local != NULL); \
+ publish_event(thread_local, event)
+
+#define stop_timer_and_publish(event) \
+ stop_timer_and_publish_for_thread(STM_SEGMENT->running_thread, event)
diff --git a/c8/stmgc.h b/c8/stmgc.h
--- a/c8/stmgc.h
+++ b/c8/stmgc.h
@@ -575,33 +575,41 @@
STM_GC_MAJOR_DONE,
/* execution duration profiling events */
- STM_DURATION_WRITE_BARRIER,
+ STM_DURATION_START_TRX,
+ STM_DURATION_WRITE_GC_ONLY,
+ STM_DURATION_WRITE_SLOWPATH,
STM_DURATION_VALIDATION,
- STM_DURATION_COMMIT,
+ STM_DURATION_CREATE_CLE,
+ STM_DURATION_COMMIT_EXCEPT_GC,
STM_DURATION_MINOR_GC,
- STM_DURATION_MAJOR_GC,
+ STM_DURATION_MAJOR_GC_LOG_ONLY,
+ STM_DURATION_MAJOR_GC_FULL,
_STM_EVENT_N
};
-#define STM_EVENT_NAMES \
- "transaction start", \
- "transaction commit", \
- "transaction abort", \
- "contention write read", \
- "wait free segment", \
- "wait other inevitable", \
- "wait done", \
- "gc minor start", \
- "gc minor done", \
- "gc major start", \
- "gc major done", \
- /* names of duration events */ \
- "duration of write slowpath", \
- "duration of validation", \
- "duration of commit", \
- "duration of minor gc", \
- "duration of major gc"
+#define STM_EVENT_NAMES \
+ "transaction start", \
+ "transaction commit", \
+ "transaction abort", \
+ "contention write read", \
+ "wait free segment", \
+ "wait other inevitable", \
+ "wait done", \
+ "gc minor start", \
+ "gc minor done", \
+ "gc major start", \
+ "gc major done", \
+ /* names of duration events */ \
+ "duration of transaction start", \
+ "duration of gc due to write", \
+ "duration of write slowpath", \
+ "duration of validation", \
+ "duration of commit log entry creation", \
+ "duration of commit except gc", \
+ "duration of minor gc", \
+ "duration of major gc doing log clean up only", \
+ "duration of full major gc"
/* The markers pushed in the shadowstack are an odd number followed by a
regular object pointer. */
More information about the pypy-commit
mailing list