From 2a45a56602acf7aa5926efe40bb5c0bb7e0b044d Mon Sep 17 00:00:00 2001
From: Craig Tiller <craig.tiller@gmail.com>
Date: Mon, 4 May 2015 07:20:42 -0700
Subject: [PATCH] Thread local storage for profile data
---
src/core/iomgr/tcp_posix.c | 3 +
src/core/profiling/basic_timers.c | 74 +++++-------------------
src/core/profiling/timers.h | 4 +-
src/core/profiling/timers_preciseclock.h | 7 ++-
4 files changed, 23 insertions(+), 65 deletions(-)
diff --git a/src/core/iomgr/tcp_posix.c b/src/core/iomgr/tcp_posix.c
index 40897fb8f8..7dfedc8f36 100644
--- a/src/core/iomgr/tcp_posix.c
+++ b/src/core/iomgr/tcp_posix.c
@@ -438,6 +438,9 @@ static grpc_endpoint_write_status grpc_tcp_flush(grpc_tcp *tcp) {
msg.msg_controllen = 0;
msg.msg_flags = 0;
+ GRPC_TIMER_BEGIN(10000, 0);
+ GRPC_TIMER_END(10000, 0);
+
GRPC_TIMER_BEGIN(GRPC_PTAG_SENDMSG, 0);
do {
/* TODO(klempner): Cork if this is a partial write */
diff --git a/src/core/profiling/basic_timers.c b/src/core/profiling/basic_timers.c
index 0145ce208e..5176769919 100644
--- a/src/core/profiling/basic_timers.c
+++ b/src/core/profiling/basic_timers.c
@@ -53,7 +53,6 @@ typedef enum {
typedef struct grpc_timer_entry {
grpc_precise_clock tm;
- gpr_thd_id thd;
int tag;
marker_type type;
void* id;
@@ -61,71 +60,33 @@ typedef struct grpc_timer_entry {
int line;
} grpc_timer_entry;
-struct grpc_timers_log {
- gpr_mu mu;
- grpc_timer_entry* log;
- int num_entries;
- int capacity;
- int capacity_limit;
- FILE* fp;
-};
+#define MAX_COUNT (1024*1024/sizeof(grpc_timer_entry))
-grpc_timers_log* grpc_timers_log_global = NULL;
+static __thread grpc_timer_entry log[MAX_COUNT];
+static __thread int count;
-static grpc_timers_log* grpc_timers_log_create(int capacity_limit, FILE* dump) {
- grpc_timers_log* log = gpr_malloc(sizeof(*log));
-
- /* TODO (vpai): Allow allocation below limit */
- log->log = gpr_malloc(capacity_limit * sizeof(*log->log));
-
- /* TODO (vpai): Improve concurrency, do per-thread logging? */
- gpr_mu_init(&log->mu);
-
- log->num_entries = 0;
- log->capacity = log->capacity_limit = capacity_limit;
-
- log->fp = dump;
-
- return log;
-}
-
-static void log_report_locked(grpc_timers_log* log) {
- FILE* fp = log->fp;
+static void log_report() {
int i;
- for (i = 0; i < log->num_entries; i++) {
- grpc_timer_entry* entry = &(log->log[i]);
- fprintf(fp, "GRPC_LAT_PROF ");
- grpc_precise_clock_print(&entry->tm, fp);
- fprintf(fp, " %p %c %d %p %s %d\n", (void*)(gpr_intptr)entry->thd, entry->type, entry->tag,
+ for (i = 0; i < count; i++) {
+ grpc_timer_entry* entry = &(log[i]);
+ printf("GRPC_LAT_PROF " GRPC_PRECISE_CLOCK_FORMAT " %p %c %d %p %s %d\n", GRPC_PRECISE_CLOCK_PRINTF_ARGS(&entry->tm), (void*)(gpr_intptr)gpr_thd_currentid(), entry->type, entry->tag,
entry->id, entry->file, entry->line);
}
/* Now clear out the log */
- log->num_entries = 0;
-}
-
-static void grpc_timers_log_destroy(grpc_timers_log* log) {
- gpr_mu_lock(&log->mu);
- log_report_locked(log);
- gpr_mu_unlock(&log->mu);
-
- gpr_free(log->log);
- gpr_mu_destroy(&log->mu);
-
- gpr_free(log);
+ count = 0;
}
-static void grpc_timers_log_add(grpc_timers_log* log, int tag, marker_type type, void* id,
+static void grpc_timers_log_add(int tag, marker_type type, void* id,
const char* file, int line) {
grpc_timer_entry* entry;
/* TODO (vpai) : Improve concurrency */
- gpr_mu_lock(&log->mu);
- if (log->num_entries == log->capacity_limit) {
- log_report_locked(log);
+ if (count == MAX_COUNT) {
+ log_report();
}
- entry = &log->log[log->num_entries++];
+ entry = &log[count++];
grpc_precise_clock_now(&entry->tm);
entry->tag = tag;
@@ -133,37 +94,32 @@ static void grpc_timers_log_add(grpc_timers_log* log, int tag, marker_type type,
entry->id = id;
entry->file = file;
entry->line = line;
- entry->thd = gpr_thd_currentid();
-
- gpr_mu_unlock(&log->mu);
}
/* Latency profiler API implementation. */
void grpc_timer_add_mark(int tag, void* id, const char* file, int line) {
if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
- grpc_timers_log_add(grpc_timers_log_global, tag, MARK, id, file, line);
+ grpc_timers_log_add(tag, MARK, id, file, line);
}
}
void grpc_timer_begin(int tag, void* id, const char *file, int line) {
if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
- grpc_timers_log_add(grpc_timers_log_global, tag, BEGIN, id, file, line);
+ grpc_timers_log_add(tag, BEGIN, id, file, line);
}
}
void grpc_timer_end(int tag, void* id, const char *file, int line) {
if (tag < GRPC_PTAG_IGNORE_THRESHOLD) {
- grpc_timers_log_add(grpc_timers_log_global, tag, END, id, file, line);
+ grpc_timers_log_add(tag, END, id, file, line);
}
}
/* Basic profiler specific API functions. */
void grpc_timers_global_init(void) {
- grpc_timers_log_global = grpc_timers_log_create(100000, stdout);
}
void grpc_timers_global_destroy(void) {
- grpc_timers_log_destroy(grpc_timers_log_global);
}
diff --git a/src/core/profiling/timers.h b/src/core/profiling/timers.h
index d0b8286c03..df5882aa22 100644
--- a/src/core/profiling/timers.h
+++ b/src/core/profiling/timers.h
@@ -109,9 +109,7 @@ enum grpc_profiling_tags {
#endif /* GRPC_STAP_PROFILER */
#ifdef GRPC_BASIC_PROFILER
-typedef struct grpc_timers_log grpc_timers_log;
-
-extern grpc_timers_log *grpc_timers_log_global;
+/* Empty placeholder for now. */
#endif /* GRPC_BASIC_PROFILER */
#endif /* at least one profiler requested. */
diff --git a/src/core/profiling/timers_preciseclock.h b/src/core/profiling/timers_preciseclock.h
index 625db906e1..c9e2973149 100644
--- a/src/core/profiling/timers_preciseclock.h
+++ b/src/core/profiling/timers_preciseclock.h
@@ -71,9 +71,8 @@ static double grpc_precise_clock_scaling_factor() {
gpr_once_init(&precise_clock_init, grpc_precise_clock_init);
return 1e6 / cycles_per_second;
}
-static void grpc_precise_clock_print(const grpc_precise_clock* clk, FILE* fp) {
- fprintf(fp, "%f", *clk * grpc_precise_clock_scaling_factor());
-}
+#define GRPC_PRECISE_CLOCK_FORMAT "%f"
+#define GRPC_PRECISE_CLOCK_PRINTF_ARGS(clk) (*(clk) * grpc_precise_clock_scaling_factor())
#else
typedef struct grpc_precise_clock grpc_precise_clock;
struct grpc_precise_clock {
@@ -82,6 +81,8 @@ struct grpc_precise_clock {
static void grpc_precise_clock_now(grpc_precise_clock* clk) {
clk->clock = gpr_now();
}
+#define GRPC_PRECISE_CLOCK_FORMAT "%ld.%09d"
+#define GRPC_PRECISE_CLOCK_PRINTF_ARGS(clk) (clk)->clock.tv_sec, (clk)->clock.tv_nsec
static void grpc_precise_clock_print(const grpc_precise_clock* clk, FILE* fp) {
fprintf(fp, "%ld.%09d", clk->clock.tv_sec, clk->clock.tv_nsec);
}
--
GitLab