@matheusbsbs / matheus-bagliano / commits / c46c406ae1

trace.h: support nested performance tracing

Performance measurements are listed right now as a flat list, which is fine when we measure big blocks. But when we start adding more and more measurements, some of them could be just part of a bigger measurement and a flat list gives a wrong impression that they are executed at the same level instead of nested. Add trace_performance_enter() and trace_performance_leave() to allow indent these nested measurements. For now it does not help much because the only nested thing is (lazy) name hash initialization (e.g. called in diff-index from "git status"). This will help more because I'm going to add some more tracing that's actually nested. Signed-off-by: Nguyễn Thái Ngọc Duy <pclouds@gmail.com> Signed-off-by: Junio C Hamano <gitster@pobox.com>

Nguyễn Thái Ngọc Duy committed Aug 18, 2018 at 16:41 UTC c46c406ae1ee30f64a13083edfa5683d2685fd61

7 files changed +96 -20

diff-lib.c

+2 -2

@@ -518,11 +518,11 @@ static int diff_cache(struct rev_info *revs,

518 int run_diff_index(struct rev_info *revs, int cached)

519 {

520 struct object_array_entry *ent;

521 - uint64_t start = getnanotime();

521

522 if (revs->pending.nr != 1)

523 BUG("run_diff_index must be passed exactly one tree");

524

525 + trace_performance_enter();

526 ent = revs->pending.objects;

527 if (diff_cache(revs, &ent->item->oid, ent->name, cached))

528 exit(128);

@@ -531,7 +531,7 @@ int run_diff_index(struct rev_info *revs, int cached)

531 diffcore_fix_diff_index(&revs->diffopt);

532 diffcore_std(&revs->diffopt);

533 diff_flush(&revs->diffopt);

534 - trace_performance_since(start, "diff-index");

534 + trace_performance_leave("diff-index");

535 return 0;

536 }

537

dir.c

+6 -3

@@ -2263,10 +2263,13 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,

2263 const char *path, int len, const struct pathspec *pathspec)

2264 {

2265 struct untracked_cache_dir *untracked;

2266 - uint64_t start = getnanotime();

2266

2268 - if (has_symlink_leading_path(path, len))

2267 + trace_performance_enter();

2268 +

2269 + if (has_symlink_leading_path(path, len)) {

2270 + trace_performance_leave("read directory %.*s", len, path);

2271 return dir->nr;

2272 + }

2273

2274 untracked = validate_untracked_cache(dir, len, pathspec);

2275 if (!untracked)

@@ -2302,7 +2305,7 @@ int read_directory(struct dir_struct *dir, struct index_state *istate,

2305 dir->nr = i;

2306 }

2307

2305 - trace_performance_since(start, "read directory %.*s", len, path);

2308 + trace_performance_leave("read directory %.*s", len, path);

2309 if (dir->untracked) {

2310 static int force_untracked_cache = -1;

2311 static struct trace_key trace_untracked_stats = TRACE_KEY_INIT(UNTRACKED_STATS);

name-hash.c

+2 -2

@@ -578,10 +578,10 @@ static void threaded_lazy_init_name_hash(

578

579 static void lazy_init_name_hash(struct index_state *istate)

580 {

581 - uint64_t start = getnanotime();

581

582 if (istate->name_hash_initialized)

583 return;

584 + trace_performance_enter();

585 hashmap_init(&istate->name_hash, cache_entry_cmp, NULL, istate->cache_nr);

586 hashmap_init(&istate->dir_hash, dir_entry_cmp, NULL, istate->cache_nr);

587

@@ -602,7 +602,7 @@ static void lazy_init_name_hash(struct index_state *istate)

602 }

603

604 istate->name_hash_initialized = 1;

605 - trace_performance_since(start, "initialize name hash");

605 + trace_performance_leave("initialize name hash");

606 }

607

608 /*

preload-index.c

+2 -2

@@ -78,7 +78,6 @@ static void preload_index(struct index_state *index,

78 {

79 int threads, i, work, offset;

80 struct thread_data data[MAX_PARALLEL];

81 - uint64_t start = getnanotime();

82 if (!core_preload_index)

83 return;

@@ -88,6 +87,7 @@ static void preload_index(struct index_state *index,

87 threads = 2;

88 if (threads < 2)

89 return;

90 + trace_performance_enter();

91 if (threads > MAX_PARALLEL)

92 threads = MAX_PARALLEL;

93 offset = 0;

@@ -109,7 +109,7 @@ static void preload_index(struct index_state *index,

109 if (pthread_join(p->pthread, NULL))

110 die("unable to join threaded lstat");

111 }

112 - trace_performance_since(start, "preload index");

112 + trace_performance_leave("preload index");

113 }

114 #endif

115

read-cache.c

+6 -5

@@ -1476,8 +1476,8 @@ int refresh_index(struct index_state *istate, unsigned int flags,

1476 const char *typechange_fmt;

1477 const char *added_fmt;

1478 const char *unmerged_fmt;

1479 - uint64_t start = getnanotime();

1479

1480 + trace_performance_enter();

1481 modified_fmt = (in_porcelain ? "M\t%s\n" : "%s: needs update\n");

1482 deleted_fmt = (in_porcelain ? "D\t%s\n" : "%s: needs update\n");

1483 typechange_fmt = (in_porcelain ? "T\t%s\n" : "%s needs update\n");

@@ -1547,7 +1547,7 @@ int refresh_index(struct index_state *istate, unsigned int flags,

1547

1548 replace_index_entry(istate, i, new_entry);

1549 }

1550 - trace_performance_since(start, "refresh index");

1550 + trace_performance_leave("refresh index");

1551 return has_errors;

1552 }

1553

@@ -2002,7 +2002,6 @@ static void freshen_shared_index(const char *shared_index, int warn)

2002 int read_index_from(struct index_state *istate, const char *path,

2003 const char *gitdir)

2004 {

2005 - uint64_t start = getnanotime();

2005 struct split_index *split_index;

2006 int ret;

2007 char *base_oid_hex;

@@ -2012,8 +2011,9 @@ int read_index_from(struct index_state *istate, const char *path,

2011 if (istate->initialized)

2012 return istate->cache_nr;

2013

2014 + trace_performance_enter();

2015 ret = do_read_index(istate, path, 0);

2016 - trace_performance_since(start, "read cache %s", path);

2016 + trace_performance_leave("read cache %s", path);

2017

2018 split_index = istate->split_index;

2019 if (!split_index || is_null_oid(&split_index->base_oid)) {

@@ -2021,6 +2021,7 @@ int read_index_from(struct index_state *istate, const char *path,

2021 return ret;

2022 }

2023

2024 + trace_performance_enter();

2025 if (split_index->base)

2026 discard_index(split_index->base);

2027 else

@@ -2037,8 +2038,8 @@ int read_index_from(struct index_state *istate, const char *path,

2038 freshen_shared_index(base_path, 0);

2039 merge_base_index(istate);

2040 post_read_index_from(istate);

2040 - trace_performance_since(start, "read cache %s", base_path);

2041 free(base_path);

2042 + trace_performance_leave("read cache %s", base_path);

2043 return ret;

2044 }

2045

trace.c

+63 -6

@@ -176,10 +176,30 @@ void trace_strbuf_fl(const char *file, int line, struct trace_key *key,

176 strbuf_release(&buf);

177 }

178

179 +static uint64_t perf_start_times[10];

180 +static int perf_indent;

181 +

182 +uint64_t trace_performance_enter(void)

183 +{

184 + uint64_t now;

185 +

186 + if (!trace_want(&trace_perf_key))

187 + return 0;

188 +

189 + now = getnanotime();

190 + perf_start_times[perf_indent] = now;

191 + if (perf_indent + 1 < ARRAY_SIZE(perf_start_times))

192 + perf_indent++;

193 + else

194 + BUG("Too deep indentation");

195 + return now;

196 +}

197 +

198 static void trace_performance_vprintf_fl(const char *file, int line,

199 uint64_t nanos, const char *format,

200 va_list ap)

201 {

202 + static const char space[] = " ";

203 struct strbuf buf = STRBUF_INIT;

204

205 if (!prepare_trace_line(file, line, &trace_perf_key, &buf))

@@ -188,7 +208,10 @@ static void trace_performance_vprintf_fl(const char *file, int line,

208 strbuf_addf(&buf, "performance: %.9f s", (double) nanos / 1000000000);

209

210 if (format && *format) {

191 - strbuf_addstr(&buf, ": ");

211 + if (perf_indent >= strlen(space))

212 + BUG("Too deep indentation");

213 +

214 + strbuf_addf(&buf, ":%.*s ", perf_indent, space);

215 strbuf_vaddf(&buf, format, ap);

216 }

217

@@ -244,6 +267,24 @@ void trace_performance_since(uint64_t start, const char *format, ...)

267 va_end(ap);

268 }

269

270 +void trace_performance_leave(const char *format, ...)

271 +{

272 + va_list ap;

273 + uint64_t since;

274 +

275 + if (perf_indent)

276 + perf_indent--;

277 +

278 + if (!format) /* Allow callers to leave without tracing anything */

279 + return;

280 +

281 + since = perf_start_times[perf_indent];

282 + va_start(ap, format);

283 + trace_performance_vprintf_fl(NULL, 0, getnanotime() - since,

284 + format, ap);

285 + va_end(ap);

286 +}

287 +

288 #else

289

290 void trace_printf_key_fl(const char *file, int line, struct trace_key *key,

@@ -273,6 +314,24 @@ void trace_performance_fl(const char *file, int line, uint64_t nanos,

314 va_end(ap);

315 }

316

317 +void trace_performance_leave_fl(const char *file, int line,

318 + uint64_t nanos, const char *format, ...)

319 +{

320 + va_list ap;

321 + uint64_t since;

322 +

323 + if (perf_indent)

324 + perf_indent--;

325 +

326 + if (!format) /* Allow callers to leave without tracing anything */

327 + return;

328 +

329 + since = perf_start_times[perf_indent];

330 + va_start(ap, format);

331 + trace_performance_vprintf_fl(file, line, nanos - since, format, ap);

332 + va_end(ap);

333 +}

334 +

335 #endif /* HAVE_VARIADIC_MACROS */

336

337

@@ -411,13 +470,11 @@ uint64_t getnanotime(void)

470 }

471 }

472

414 -static uint64_t command_start_time;

473 static struct strbuf command_line = STRBUF_INIT;

474

475 static void print_command_performance_atexit(void)

476 {

419 - trace_performance_since(command_start_time, "git command:%s",

420 - command_line.buf);

477 + trace_performance_leave("git command:%s", command_line.buf);

478 }

479

480 void trace_command_performance(const char **argv)

@@ -425,10 +482,10 @@ void trace_command_performance(const char **argv)

482 if (!trace_want(&trace_perf_key))

483 return;

484

428 - if (!command_start_time)

485 + if (!command_line.len)

486 atexit(print_command_performance_atexit);

487

488 strbuf_reset(&command_line);

489 sq_quote_argv_pretty(&command_line, argv);

433 - command_start_time = getnanotime();

490 + trace_performance_enter();

491 }

trace.h

+15

@@ -23,6 +23,7 @@ extern void trace_disable(struct trace_key *key);

23 extern uint64_t getnanotime(void);

24 extern void trace_command_performance(const char **argv);

25 extern void trace_verbatim(struct trace_key *key, const void *buf, unsigned len);

26 +uint64_t trace_performance_enter(void);

28 #ifndef HAVE_VARIADIC_MACROS

@@ -45,6 +46,9 @@ extern void trace_performance(uint64_t nanos, const char *format, ...);

46 __attribute__((format (printf, 2, 3)))

47 extern void trace_performance_since(uint64_t start, const char *format, ...);

49 +__attribute__((format (printf, 1, 2)))

50 +void trace_performance_leave(const char *format, ...);

51 +

52 #else

54 /*

@@ -118,6 +122,14 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);

122 __VA_ARGS__); \

123 } while (0)

124

125 +#define trace_performance_leave(...) \

126 + do { \

127 + if (trace_pass_fl(&trace_perf_key)) \

128 + trace_performance_leave_fl(TRACE_CONTEXT, __LINE__, \

129 + getnanotime(), \

130 + __VA_ARGS__); \

131 + } while (0)

132 +

133 /* backend functions, use non-*fl macros instead */

134 __attribute__((format (printf, 4, 5)))

135 extern void trace_printf_key_fl(const char *file, int line, struct trace_key *key,

@@ -130,6 +142,9 @@ extern void trace_strbuf_fl(const char *file, int line, struct trace_key *key,

142 __attribute__((format (printf, 4, 5)))

143 extern void trace_performance_fl(const char *file, int line,

144 uint64_t nanos, const char *fmt, ...);

145 +__attribute__((format (printf, 4, 5)))

146 +extern void trace_performance_leave_fl(const char *file, int line,

147 + uint64_t nanos, const char *fmt, ...);

148 static inline int trace_pass_fl(struct trace_key *key)

149 {

150 return key->fd || !key->initialized;