From 935075a712e38428c361db37e982f94243c1c3ac Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Wed, 26 Sep 2018 12:29:26 -0400 Subject: [PATCH 01/16] gvfs:trace2:data: add trace2 tracing around read_object_process Add trace2 region around read_object_process to collect time spent waiting for missing objects to be dynamically fetched. Signed-off-by: Jeff Hostetler --- object-file.c | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/object-file.c b/object-file.c index df2cbe4a785894..e053c886f90e20 100644 --- a/object-file.c +++ b/object-file.c @@ -44,6 +44,7 @@ #include "submodule.h" #include "fsck.h" #include "trace.h" +#include "trace2.h" #include "hook.h" #include "sigchain.h" #include "sub-process.h" @@ -999,6 +1000,8 @@ static int read_object_process(const struct object_id *oid) start = getnanotime(); + trace2_region_enter("subprocess", "read_object", the_repository); + if (!subprocess_map_initialized) { subprocess_map_initialized = 1; hashmap_init(&subprocess_map, (hashmap_cmp_fn)cmd2process_cmp, @@ -1015,13 +1018,16 @@ static int read_object_process(const struct object_id *oid) if (subprocess_start(&subprocess_map, &entry->subprocess, cmd, start_read_object_fn)) { free(entry); - return -1; + err = -1; + goto leave_region; } } process = &entry->subprocess.process; - if (!(CAP_GET & entry->supported_capabilities)) - return -1; + if (!(CAP_GET & entry->supported_capabilities)) { + err = -1; + goto leave_region; + } sigchain_push(SIGPIPE, SIG_IGN); @@ -1070,6 +1076,10 @@ static int read_object_process(const struct object_id *oid) trace_performance_since(start, "read_object_process"); +leave_region: + trace2_region_leave_printf("subprocess", "read_object", the_repository, + "result %d", err); + return err; } From a3a21ee47f52e0d7035fd7dbdfc253a34621e4cf Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Wed, 26 Sep 2018 11:21:22 -0400 Subject: [PATCH 02/16] gvfs:trace2:data: status deserialization information Add trace2 region and data events describing attempts to deserialize status data using a status cache. A category:status, label:deserialize region is pushed around the deserialize code. Deserialization results when reading from a file are: category:status, path = category:status, polled = category:status, result = "ok" | "reject" When reading from STDIN are: category:status, path = "STDIN" category:status, result = "ok" | "reject" Status will fallback and run a normal status scan when a "reject" is reported (unless "--deserialize-wait=fail"). If "ok" is reported, status was able to use the status cache and avoid scanning the workdir. Additionally, a cmd_mode is emitted for each step: collection, deserialization, and serialization. For example, if deserialization is attempted and fails and status falls back to actually computing the status, a cmd_mode message containing "deserialize" is issued and then a cmd_mode for "collect" is issued. Also, if deserialization fails, a data message containing the rejection reason is emitted. Signed-off-by: Jeff Hostetler --- builtin/commit.c | 19 +++++++++++- wt-status-deserialize.c | 67 ++++++++++++++++++++++++++++++++++++++--- wt-status.h | 2 ++ 3 files changed, 83 insertions(+), 5 deletions(-) diff --git a/builtin/commit.c b/builtin/commit.c index 1feecaa534b2d2..5d567faf7c0a06 100644 --- a/builtin/commit.c +++ b/builtin/commit.c @@ -179,6 +179,7 @@ static int opt_parse_porcelain(const struct option *opt, const char *arg, int un static int do_serialize = 0; static char *serialize_path = NULL; +static int reject_implicit = 0; static int do_implicit_deserialize = 0; static int do_explicit_deserialize = 0; static char *deserialize_path = NULL; @@ -242,7 +243,7 @@ static int opt_parse_deserialize(const struct option *opt, const char *arg, int } if (!deserialize_path || !*deserialize_path) do_explicit_deserialize = 1; /* read stdin */ - else if (access(deserialize_path, R_OK) == 0) + else if (wt_status_deserialize_access(deserialize_path, R_OK) == 0) do_explicit_deserialize = 1; /* can read from this file */ else { /* @@ -1591,6 +1592,8 @@ static int git_status_config(const char *k, const char *v, if (v && *v && access(v, R_OK) == 0) { do_implicit_deserialize = 1; deserialize_path = xstrdup(v); + } else { + reject_implicit = 1; } return 0; } @@ -1745,6 +1748,17 @@ int cmd_status(int argc, const char **argv, const char *prefix) if (try_deserialize) goto skip_init; + /* + * If we implicitly received a status cache pathname from the config + * and the file does not exist, we silently reject it and do the normal + * status "collect". Fake up some trace2 messages to reflect this and + * assist post-processors know this case is different. + */ + if (!do_serialize && reject_implicit) { + trace2_cmd_mode("implicit-deserialize"); + trace2_data_string("status", the_repository, "deserialize/reject", + "status-cache/access"); + } enable_fscache(0); if (status_format != STATUS_FORMAT_PORCELAIN && @@ -1788,6 +1802,7 @@ int cmd_status(int argc, const char **argv, const char *prefix) if (s.relative_paths) s.prefix = prefix; + trace2_cmd_mode("deserialize"); result = wt_status_deserialize(&s, deserialize_path, dw); if (result == DESERIALIZE_OK) return 0; @@ -1805,6 +1820,7 @@ int cmd_status(int argc, const char **argv, const char *prefix) fd = -1; } + trace2_cmd_mode("collect"); wt_status_collect(&s); if (0 <= fd) @@ -1819,6 +1835,7 @@ int cmd_status(int argc, const char **argv, const char *prefix) if (fd_serialize < 0) die_errno(_("could not serialize to '%s'"), serialize_path); + trace2_cmd_mode("serialize"); wt_status_serialize_v1(fd_serialize, &s); close(fd_serialize); } diff --git a/wt-status-deserialize.c b/wt-status-deserialize.c index 46e655488d6bcb..4d85cc2ac9d02e 100644 --- a/wt-status-deserialize.c +++ b/wt-status-deserialize.c @@ -7,6 +7,23 @@ #include "trace.h" #include "statinfo.h" #include "path.h" +#include "trace2.h" + +static void set_deserialize_reject_reason(const char *reason) +{ + trace2_data_string("status", the_repository, "deserialize/reject", + reason); +} + +int wt_status_deserialize_access(const char *path, int mode) +{ + int a = access(path, mode); + + if (a != 0) + set_deserialize_reject_reason("status-cache/access"); + + return a; +} static struct trace_key trace_deserialize = TRACE_KEY_INIT(DESERIALIZE); @@ -54,6 +71,7 @@ static int my_validate_index(const struct cache_time *mtime_reported) struct cache_time mtime_observed_on_disk; if (lstat(path, &st)) { + set_deserialize_reject_reason("index/not-found"); trace_printf_key(&trace_deserialize, "could not stat index"); return DESERIALIZE_ERR; } @@ -61,6 +79,7 @@ static int my_validate_index(const struct cache_time *mtime_reported) mtime_observed_on_disk.nsec = ST_MTIME_NSEC(st); if ((mtime_observed_on_disk.sec != mtime_reported->sec) || (mtime_observed_on_disk.nsec != mtime_reported->nsec)) { + set_deserialize_reject_reason("index/mtime-changed"); trace_printf_key(&trace_deserialize, "index mtime changed [des %d %d][obs %d %d]", mtime_reported->sec, mtime_reported->nsec, @@ -86,10 +105,12 @@ static int my_validate_excludes(const char *path, const char *key, const char *l r = (strcmp(line, sb.buf) ? DESERIALIZE_ERR : DESERIALIZE_OK); - if (r == DESERIALIZE_ERR) + if (r == DESERIALIZE_ERR) { + set_deserialize_reject_reason("excludes/changed"); trace_printf_key(&trace_deserialize, "%s changed [cached '%s'][observed '%s']", key, line, sb.buf); + } strbuf_release(&sb); return r; @@ -145,6 +166,7 @@ static int wt_deserialize_v1_header(struct wt_status *s, int fd) &index_mtime.sec, &index_mtime.nsec); if (nr_fields != 2) { + set_deserialize_reject_reason("v1-header/invalid-index-mtime"); trace_printf_key(&trace_deserialize, "invalid index_mtime (%d) '%s'", nr_fields, line); return DESERIALIZE_ERR; @@ -228,6 +250,7 @@ static int wt_deserialize_v1_header(struct wt_status *s, int fd) /* status_format */ if (skip_prefix(line, "sha1_commit ", &arg)) { if (get_oid_hex(arg, &s->oid_commit)) { + set_deserialize_reject_reason("v1-header/invalid-commit-sha"); trace_printf_key(&trace_deserialize, "invalid sha1_commit"); return DESERIALIZE_ERR; } @@ -243,19 +266,23 @@ static int wt_deserialize_v1_header(struct wt_status *s, int fd) } /* prefix */ + set_deserialize_reject_reason("v1-header/unexpected-line"); trace_printf_key(&trace_deserialize, "unexpected line '%s'", line); return DESERIALIZE_ERR; } if (!have_required_index_mtime) { + set_deserialize_reject_reason("v1-header/missing-index-mtime"); trace_printf_key(&trace_deserialize, "missing '%s'", "index_mtime"); return DESERIALIZE_ERR; } if (!have_required_core_excludes) { + set_deserialize_reject_reason("v1-header/missing-core-excludes"); trace_printf_key(&trace_deserialize, "missing '%s'", "core_excludes"); return DESERIALIZE_ERR; } if (!have_required_repo_excludes) { + set_deserialize_reject_reason("v1-header/missing-repo-excludes"); trace_printf_key(&trace_deserialize, "missing '%s'", "repo_excludes"); return DESERIALIZE_ERR; } @@ -342,6 +369,7 @@ static int wt_deserialize_v1_changed_items(const struct wt_status *cmd_s, * So we reject the status cache and let the fallback * code run. */ + set_deserialize_reject_reason("v1-data/unmerged"); trace_printf_key( &trace_deserialize, "reject: V2 format and umerged file: %s", @@ -483,6 +511,7 @@ static int wt_deserialize_v1(const struct wt_status *cmd_s, struct wt_status *s, * the serialized data */ if (validate_untracked_files_arg(cmd_s->show_untracked_files, &s->show_untracked_files, &untracked_strategy)) { + set_deserialize_reject_reason("args/untracked-files"); trace_printf_key(&trace_deserialize, "reject: show_untracked_file: command: %d, serialized : %d", cmd_s->show_untracked_files, s->show_untracked_files); @@ -490,6 +519,7 @@ static int wt_deserialize_v1(const struct wt_status *cmd_s, struct wt_status *s, } if (validate_ignored_files_arg(cmd_s->show_ignored_mode, s->show_ignored_mode, &ignored_strategy)) { + set_deserialize_reject_reason("args/ignored-mode"); trace_printf_key(&trace_deserialize, "reject: show_ignored_mode: command: %d, serialized: %d", cmd_s->show_ignored_mode, s->show_ignored_mode); @@ -523,6 +553,7 @@ static int wt_deserialize_v1(const struct wt_status *cmd_s, struct wt_status *s, return DESERIALIZE_ERR; continue; } + set_deserialize_reject_reason("v1-data/unexpected-line"); trace_printf_key(&trace_deserialize, "unexpected line '%s'", line); return DESERIALIZE_ERR; } @@ -544,6 +575,7 @@ static int wt_deserialize_parse(const struct wt_status *cmd_s, struct wt_status if (version == 1) return wt_deserialize_v1(cmd_s, s, fd); } + set_deserialize_reject_reason("status-cache/unsupported-version"); trace_printf_key(&trace_deserialize, "missing/unsupported version"); return DESERIALIZE_ERR; } @@ -564,6 +596,7 @@ static int wt_deserialize_fd(const struct wt_status *cmd_s, struct wt_status *de * Check the path spec on the current command */ if (cmd_s->pathspec.nr > 1) { + set_deserialize_reject_reason("args/multiple-pathspecs"); trace_printf_key(&trace_deserialize, "reject: multiple pathspecs"); return DESERIALIZE_ERR; } @@ -574,6 +607,7 @@ static int wt_deserialize_fd(const struct wt_status *cmd_s, struct wt_status *de */ if (cmd_s->pathspec.nr == 1 && my_strcmp_null(cmd_s->pathspec.items[0].match, "")) { + set_deserialize_reject_reason("args/root-pathspec"); trace_printf_key(&trace_deserialize, "reject: pathspec"); return DESERIALIZE_ERR; } @@ -590,20 +624,24 @@ static int wt_deserialize_fd(const struct wt_status *cmd_s, struct wt_status *de * or "--ignored" settings). */ if (cmd_s->is_initial != des_s->is_initial) { + set_deserialize_reject_reason("args/is-initial-changed"); trace_printf_key(&trace_deserialize, "reject: is_initial"); return DESERIALIZE_ERR; } if (my_strcmp_null(cmd_s->branch, des_s->branch)) { + set_deserialize_reject_reason("args/branch-changed"); trace_printf_key(&trace_deserialize, "reject: branch"); return DESERIALIZE_ERR; } if (my_strcmp_null(cmd_s->reference, des_s->reference)) { + set_deserialize_reject_reason("args/reference-changed"); trace_printf_key(&trace_deserialize, "reject: reference"); return DESERIALIZE_ERR; } /* verbose */ /* amend */ if (cmd_s->whence != des_s->whence) { + set_deserialize_reject_reason("args/whence-changed"); trace_printf_key(&trace_deserialize, "reject: whence"); return DESERIALIZE_ERR; } @@ -637,19 +675,23 @@ static int wt_deserialize_fd(const struct wt_status *cmd_s, struct wt_status *de /* hints */ /* ahead_behind_flags */ if (cmd_s->detect_rename != des_s->detect_rename) { + set_deserialize_reject_reason("args/detect-rename-changed"); trace_printf_key(&trace_deserialize, "reject: detect_rename"); return DESERIALIZE_ERR; } if (cmd_s->rename_score != des_s->rename_score) { + set_deserialize_reject_reason("args/rename-score-changed"); trace_printf_key(&trace_deserialize, "reject: rename_score"); return DESERIALIZE_ERR; } if (cmd_s->rename_limit != des_s->rename_limit) { + set_deserialize_reject_reason("args/rename-limit-changed"); trace_printf_key(&trace_deserialize, "reject: rename_limit"); return DESERIALIZE_ERR; } /* status_format */ if (!oideq(&cmd_s->oid_commit, &des_s->oid_commit)) { + set_deserialize_reject_reason("args/commit-changed"); trace_printf_key(&trace_deserialize, "reject: sha1_commit"); return DESERIALIZE_ERR; } @@ -738,15 +780,18 @@ static int try_deserialize_read_from_file(const struct wt_status *cmd_s, enum wt_status_deserialize_wait dw, struct wt_status *des_s) { - int k, limit; + int k = 0; + int limit; int result = DESERIALIZE_ERR; /* * For "fail" or "no", try exactly once to read the status cache. * Return an error if the file is stale. */ - if (dw == DESERIALIZE_WAIT__FAIL || dw == DESERIALIZE_WAIT__NO) - return try_deserialize_read_from_file_1(cmd_s, path, des_s); + if (dw == DESERIALIZE_WAIT__FAIL || dw == DESERIALIZE_WAIT__NO) { + result = try_deserialize_read_from_file_1(cmd_s, path, des_s); + goto done; + } /* * Wait for the status cache file to refresh. Wait duration can @@ -771,6 +816,12 @@ static int try_deserialize_read_from_file(const struct wt_status *cmd_s, sleep_millisec(100); } +done: + trace2_data_string("status", the_repository, "deserialize/path", path); + trace2_data_intmax("status", the_repository, "deserialize/polled", k); + trace2_data_string("status", the_repository, "deserialize/result", + ((result == DESERIALIZE_OK) ? "ok" : "reject")); + trace_printf_key(&trace_deserialize, "wait polled=%d result=%d '%s'", k, result, path); @@ -796,6 +847,8 @@ int wt_status_deserialize(const struct wt_status *cmd_s, struct wt_status des_s; int result; + trace2_region_enter("status", "deserialize", the_repository); + if (path && *path && strcmp(path, "0")) { result = try_deserialize_read_from_file(cmd_s, path, dw, &des_s); } else { @@ -806,8 +859,14 @@ int wt_status_deserialize(const struct wt_status *cmd_s, * term, since we cannot read stdin multiple times. */ result = wt_deserialize_fd(cmd_s, &des_s, 0); + + trace2_data_string("status", the_repository, "deserialize/path", "STDIN"); + trace2_data_string("status", the_repository, "deserialize/result", + ((result == DESERIALIZE_OK) ? "ok" : "reject")); } + trace2_region_leave("status", "deserialize", the_repository); + if (result == DESERIALIZE_OK) { wt_status_get_state(cmd_s->repo, &des_s.state, des_s.branch && !strcmp(des_s.branch, "HEAD")); diff --git a/wt-status.h b/wt-status.h index e6843d86068990..522e1236463a58 100644 --- a/wt-status.h +++ b/wt-status.h @@ -243,6 +243,8 @@ int wt_status_deserialize(const struct wt_status *cmd_s, const char *path, enum wt_status_deserialize_wait dw); +int wt_status_deserialize_access(const char *path, int mode); + /* * A helper routine for serialize and deserialize to compute * metadata for the user-global and repo-local excludes files. From 2e91a37d443d2dd5dea7725e954c1c7232f7ee23 Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Mon, 7 Jan 2019 12:45:48 -0500 Subject: [PATCH 03/16] gvfs:trace2:data: status serialization Add trace information around status serialization. Signed-off-by: Jeff Hostetler --- wt-status-serialize.c | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/wt-status-serialize.c b/wt-status-serialize.c index 036979f30ad026..7ca62d9085ca86 100644 --- a/wt-status-serialize.c +++ b/wt-status-serialize.c @@ -7,6 +7,7 @@ #include "trace.h" #include "read-cache-ll.h" #include "path.h" +#include "trace2.h" static struct trace_key trace_serialize = TRACE_KEY_INIT(SERIALIZE); @@ -303,6 +304,8 @@ void wt_status_serialize_v1(int fd, struct wt_status *s) struct string_list_item *iter; int k; + trace2_region_enter("status", "serialize", the_repository); + /* * version header must be first line. */ @@ -336,4 +339,6 @@ void wt_status_serialize_v1(int fd, struct wt_status *s) } packet_flush(fd); } + + trace2_region_leave("status", "serialize", the_repository); } From 5bbf10969e7d1bbbbc090d9396cf0344e28fa4a6 Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Mon, 19 Nov 2018 16:26:37 -0500 Subject: [PATCH 04/16] gvfs:trace2:data: add vfs stats Report virtual filesystem summary data. Signed-off-by: Jeff Hostetler --- virtualfilesystem.c | 38 ++++++++++++++++++++++++++++++++++++-- 1 file changed, 36 insertions(+), 2 deletions(-) diff --git a/virtualfilesystem.c b/virtualfilesystem.c index 99f5d24155a1bd..06204f956b3427 100644 --- a/virtualfilesystem.c +++ b/virtualfilesystem.c @@ -1,6 +1,7 @@ #include "git-compat-util.h" #include "environment.h" #include "gettext.h" +#include "trace2.h" #include "config.h" #include "dir.h" #include "hashmap.h" @@ -258,6 +259,11 @@ void apply_virtualfilesystem(struct index_state *istate) { char *buf, *entry; int i; + int nr_unknown = 0; + int nr_vfs_dirs = 0; + int nr_vfs_rows = 0; + int nr_bulk_skip = 0; + int nr_explicit_skip = 0; if (!git_config_get_virtualfilesystem()) return; @@ -275,16 +281,21 @@ void apply_virtualfilesystem(struct index_state *istate) if (buf[i] == '\0') { int pos, len; + nr_vfs_rows++; + len = buf + i - entry; /* look for a directory wild card (ie "dir1/") */ if (buf[i - 1] == '/') { + nr_vfs_dirs++; if (ignore_case) adjust_dirname_case(istate, entry); pos = index_name_pos(istate, entry, len); if (pos < 0) { pos = -pos - 1; while (pos < istate->cache_nr && !fspathncmp(istate->cache[pos]->name, entry, len)) { + if (istate->cache[pos]->ce_flags & CE_SKIP_WORKTREE) + nr_bulk_skip++; istate->cache[pos]->ce_flags &= ~CE_SKIP_WORKTREE; pos++; } @@ -292,18 +303,41 @@ void apply_virtualfilesystem(struct index_state *istate) } else { if (ignore_case) { struct cache_entry *ce = index_file_exists(istate, entry, len, ignore_case); - if (ce) + if (ce) { + if (ce->ce_flags & CE_SKIP_WORKTREE) + nr_explicit_skip++; ce->ce_flags &= ~CE_SKIP_WORKTREE; + } + else { + nr_unknown++; + } } else { int pos = index_name_pos(istate, entry, len); - if (pos >= 0) + if (pos >= 0) { + if (istate->cache[pos]->ce_flags & CE_SKIP_WORKTREE) + nr_explicit_skip++; istate->cache[pos]->ce_flags &= ~CE_SKIP_WORKTREE; + } + else { + nr_unknown++; + } } } entry += len + 1; } } + + if (nr_vfs_rows > 0) { + trace2_data_intmax("vfs", the_repository, "apply/tracked", nr_bulk_skip + nr_explicit_skip); + + trace2_data_intmax("vfs", the_repository, "apply/vfs_rows", nr_vfs_rows); + trace2_data_intmax("vfs", the_repository, "apply/vfs_dirs", nr_vfs_dirs); + + trace2_data_intmax("vfs", the_repository, "apply/nr_unknown", nr_unknown); + trace2_data_intmax("vfs", the_repository, "apply/nr_bulk_skip", nr_bulk_skip); + trace2_data_intmax("vfs", the_repository, "apply/nr_explicit_skip", nr_explicit_skip); + } } /* From 510763f4edab060ee0ed55dbb6967daa636d2b16 Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Mon, 15 Apr 2019 13:39:43 -0700 Subject: [PATCH 05/16] trace2: refactor setting process starting time Create trace2_initialize_clock() and call from main() to capture process start time in isolation and before other sub-systems are ready. Signed-off-by: Jeff Hostetler Signed-off-by: Junio C Hamano --- compat/mingw.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/compat/mingw.c b/compat/mingw.c index 41831e88163ee2..d11193a8c086e3 100644 --- a/compat/mingw.c +++ b/compat/mingw.c @@ -4026,6 +4026,8 @@ int wmain(int argc, const wchar_t **wargv) SetConsoleCtrlHandler(handle_ctrl_c, TRUE); + trace2_initialize_clock(); + maybe_redirect_std_handles(); adjust_symlink_flags(); fsync_object_files = 1; From 58348c1bd229bb7e4042a74af28e1abe8ef95307 Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Tue, 30 Apr 2019 14:12:51 -0400 Subject: [PATCH 06/16] trace2:gvfs:experiment: clear_ce_flags_1 Signed-off-by: Jeff Hostetler --- unpack-trees.c | 1 + 1 file changed, 1 insertion(+) diff --git a/unpack-trees.c b/unpack-trees.c index d5457fe218c339..0a0e71593d191e 100644 --- a/unpack-trees.c +++ b/unpack-trees.c @@ -1785,6 +1785,7 @@ static int clear_ce_flags(struct index_state *istate, xsnprintf(label, sizeof(label), "clear_ce_flags(0x%08lx,0x%08lx)", (unsigned long)select_mask, (unsigned long)clear_mask); trace2_region_enter("unpack_trees", label, the_repository); + rval = clear_ce_flags_1(istate, istate->cache, istate->cache_nr, From 31064cf26916b475c42579a438adcbcfe571df77 Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Tue, 30 Apr 2019 16:02:39 -0400 Subject: [PATCH 07/16] trace2:gvfs:experiment: report_tracking Signed-off-by: Jeff Hostetler --- builtin/checkout.c | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/builtin/checkout.c b/builtin/checkout.c index bff5caba03edc3..8a44bcba402c7b 100644 --- a/builtin/checkout.c +++ b/builtin/checkout.c @@ -1025,8 +1025,11 @@ static void update_refs_for_switch(const struct checkout_opts *opts, remove_branch_state(the_repository, !opts->quiet); strbuf_release(&msg); if (!opts->quiet && - (new_branch_info->path || (!opts->force_detach && !strcmp(new_branch_info->name, "HEAD")))) + (new_branch_info->path || (!opts->force_detach && !strcmp(new_branch_info->name, "HEAD")))) { + trace2_region_enter("exp", "report_tracking", the_repository); report_tracking(new_branch_info); + trace2_region_leave("exp", "report_tracking", the_repository); + } } static int add_pending_uninteresting_ref(const char *refname, From 2d205169eda400f4da8be6303c522484c5570a54 Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Fri, 14 Jun 2019 12:38:31 -0400 Subject: [PATCH 08/16] trace2:gvfs:experiment: read_cache: annotate thread usage in read-cache Add trace2_thread_start() and trace2_thread_exit() events to the worker threads used to read the index. This gives per-thread perf data. These workers were introduced in: abb4bb83845 read-cache: load cache extensions on a worker thread 77ff1127a4c read-cache: load cache entries on worker threads Signed-off-by: Jeff Hostetler --- read-cache.c | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) diff --git a/read-cache.c b/read-cache.c index 960fe104d6446c..1cf7ba5e0dfe15 100644 --- a/read-cache.c +++ b/read-cache.c @@ -2056,6 +2056,17 @@ static void *load_index_extensions(void *_data) return NULL; } +static void *load_index_extensions_threadproc(void *_data) +{ + void *result; + + trace2_thread_start("load_index_extensions"); + result = load_index_extensions(_data); + trace2_thread_exit(); + + return result; +} + /* * A helper function that will load the specified range of cache entries * from the memory mapped file and add them to the given index. @@ -2132,12 +2143,17 @@ static void *load_cache_entries_thread(void *_data) struct load_cache_entries_thread_data *p = _data; int i; + trace2_thread_start("load_cache_entries"); + /* iterate across all ieot blocks assigned to this thread */ for (i = p->ieot_start; i < p->ieot_start + p->ieot_blocks; i++) { p->consumed += load_cache_entry_block(p->istate, p->ce_mem_pool, p->offset, p->ieot->entries[i].nr, p->mmap, p->ieot->entries[i].offset, NULL); p->offset += p->ieot->entries[i].nr; } + + trace2_thread_exit(); + return NULL; } @@ -2305,7 +2321,7 @@ int do_read_index(struct index_state *istate, const char *path, int must_exist) int err; p.src_offset = extension_offset; - err = pthread_create(&p.pthread, NULL, load_index_extensions, &p); + err = pthread_create(&p.pthread, NULL, load_index_extensions_threadproc, &p); if (err) die(_("unable to create load_index_extensions thread: %s"), strerror(err)); From 17a8386dd1aa5e1e69a399efdbce71e0f9151c8a Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Tue, 9 Jul 2019 14:43:47 -0400 Subject: [PATCH 09/16] trace2:gvfs:experiment: read-cache: time read/write of cache-tree extension Add regions around code to read and write the cache-tree extension when the index is read or written. This is an experiment and may be dropped in future releases if we don't need it anymore. This experiment demonstrates that it takes more time to parse and deserialize the cache-tree extension than it does to read the cache-entries. Commits [1] and [2] spreads cache-entry reading across N-1 cores and dedicates a single core to simultaneously read the index extensions. Local testing (on my machine) shows that reading the cache-tree extension takes ~0.28 seconds. The 11 cache-entry threads take ~0.08 seconds. The main thread is blocked for 0.15 to 0.20 seconds waiting for the extension thread to finish. Let's use this commit to gather some telemetry and confirm this. My point is that improvements, such as index V5 which makes the cache entries smaller, may improve performance, but the gains may be limited because of this extension. And that we may need to look inside the cache-tree extension to truly improve do_read_index() performance. [1] abb4bb83845 read-cache: load cache extensions on a worker thread [2] 77ff1127a4c read-cache: load cache entries on worker threads Signed-off-by: Jeff Hostetler --- read-cache.c | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/read-cache.c b/read-cache.c index 1cf7ba5e0dfe15..a08daf87dcd1ae 100644 --- a/read-cache.c +++ b/read-cache.c @@ -1767,7 +1767,10 @@ static int read_index_extension(struct index_state *istate, { switch (CACHE_EXT(ext)) { case CACHE_EXT_TREE: + trace2_region_enter("index", "read/extension/cache_tree", NULL); istate->cache_tree = cache_tree_read(data, sz); + trace2_data_intmax("index", NULL, "read/extension/cache_tree/bytes", (intmax_t)sz); + trace2_region_leave("index", "read/extension/cache_tree", NULL); break; case CACHE_EXT_RESOLVE_UNDO: istate->resolve_undo = resolve_undo_read(data, sz); @@ -3049,9 +3052,13 @@ static int do_write_index(struct index_state *istate, struct tempfile *tempfile, !drop_cache_tree && istate->cache_tree) { struct strbuf sb = STRBUF_INIT; + trace2_region_enter("index", "write/extension/cache_tree", NULL); cache_tree_write(&sb, istate->cache_tree); err = write_index_ext_header(f, eoie_c, CACHE_EXT_TREE, sb.len) < 0; hashwrite(f, sb.buf, sb.len); + trace2_data_intmax("index", NULL, "write/extension/cache_tree/bytes", (intmax_t)sb.len); + trace2_region_leave("index", "write/extension/cache_tree", NULL); + strbuf_release(&sb); if (err) return -1; From 6f0f0ade27298fd67fb6f77364f81052ff4b2cb2 Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Tue, 16 Jul 2019 09:09:53 -0400 Subject: [PATCH 10/16] trace2:gvfs:experiment: add region to apply_virtualfilesystem() Signed-off-by: Jeff Hostetler --- virtualfilesystem.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/virtualfilesystem.c b/virtualfilesystem.c index 06204f956b3427..4796c69d4c206f 100644 --- a/virtualfilesystem.c +++ b/virtualfilesystem.c @@ -268,6 +268,8 @@ void apply_virtualfilesystem(struct index_state *istate) if (!git_config_get_virtualfilesystem()) return; + trace2_region_enter("vfs", "apply", the_repository); + if (!virtual_filesystem_data.len) get_virtual_filesystem_data(&virtual_filesystem_data); @@ -338,6 +340,8 @@ void apply_virtualfilesystem(struct index_state *istate) trace2_data_intmax("vfs", the_repository, "apply/nr_bulk_skip", nr_bulk_skip); trace2_data_intmax("vfs", the_repository, "apply/nr_explicit_skip", nr_explicit_skip); } + + trace2_region_leave("vfs", "apply", the_repository); } /* From 94b9e74f03df3b9467a52064b27d2acc582ad13b Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Tue, 16 Jul 2019 10:08:08 -0400 Subject: [PATCH 11/16] trace2:gvfs:experiment: add region around unpack_trees() Signed-off-by: Jeff Hostetler --- unpack-trees.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/unpack-trees.c b/unpack-trees.c index 0a0e71593d191e..009f9812a8684d 100644 --- a/unpack-trees.c +++ b/unpack-trees.c @@ -1908,6 +1908,8 @@ int unpack_trees(unsigned len, struct tree_desc *t, struct unpack_trees_options if (o->df_conflict_entry) BUG("o->df_conflict_entry is an output only field"); + trace2_region_enter("exp", "unpack_trees", NULL); + trace_performance_enter(); trace2_region_enter("unpack_trees", "unpack_trees", the_repository); @@ -2112,6 +2114,7 @@ int unpack_trees(unsigned len, struct tree_desc *t, struct unpack_trees_options } trace2_region_leave("unpack_trees", "unpack_trees", the_repository); trace_performance_leave("unpack_trees"); + trace2_region_leave("exp", "unpack_trees", NULL); return ret; return_failed: From d08d303d65684f4dc6fa0871246e950eddce68c2 Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Tue, 16 Jul 2019 10:16:37 -0400 Subject: [PATCH 12/16] trace2:gvfs:experiment: add region to cache_tree_fully_valid() Signed-off-by: Jeff Hostetler --- cache-tree.c | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) diff --git a/cache-tree.c b/cache-tree.c index 8a61a2a8399511..e81571a16826a4 100644 --- a/cache-tree.c +++ b/cache-tree.c @@ -231,7 +231,7 @@ static void discard_unused_subtrees(struct cache_tree *it) } } -int cache_tree_fully_valid(struct cache_tree *it) +static int cache_tree_fully_valid_1(struct cache_tree *it) { int i; if (!it) @@ -239,7 +239,7 @@ int cache_tree_fully_valid(struct cache_tree *it) if (it->entry_count < 0 || !repo_has_object_file(the_repository, &it->oid)) return 0; for (i = 0; i < it->subtree_nr; i++) { - if (!cache_tree_fully_valid(it->down[i]->cache_tree)) + if (!cache_tree_fully_valid_1(it->down[i]->cache_tree)) return 0; } return 1; @@ -250,6 +250,17 @@ static int must_check_existence(const struct cache_entry *ce) return !(repo_has_promisor_remote(the_repository) && ce_skip_worktree(ce)); } +int cache_tree_fully_valid(struct cache_tree *it) +{ + int result; + + trace2_region_enter("cache_tree", "fully_valid", NULL); + result = cache_tree_fully_valid_1(it); + trace2_region_leave("cache_tree", "fully_valid", NULL); + + return result; +} + static int update_one(struct cache_tree *it, struct cache_entry **cache, int entries, From f2fa7a689befcf96d15f5ff5b6ff958508003c6f Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Tue, 16 Jul 2019 10:40:56 -0400 Subject: [PATCH 13/16] trace2:gvfs:experiment: add unpack_entry() counter to unpack_trees() and report_tracking() Signed-off-by: Jeff Hostetler --- builtin/checkout.c | 6 ++++++ packfile.c | 9 +++++++++ packfile.h | 5 +++++ unpack-trees.c | 5 +++++ 4 files changed, 25 insertions(+) diff --git a/builtin/checkout.c b/builtin/checkout.c index 8a44bcba402c7b..7e63fa8802887e 100644 --- a/builtin/checkout.c +++ b/builtin/checkout.c @@ -19,6 +19,7 @@ #include "merge-recursive.h" #include "object-name.h" #include "object-store-ll.h" +#include "packfile.h" #include "parse-options.h" #include "path.h" #include "preload-index.h" @@ -1026,8 +1027,13 @@ static void update_refs_for_switch(const struct checkout_opts *opts, strbuf_release(&msg); if (!opts->quiet && (new_branch_info->path || (!opts->force_detach && !strcmp(new_branch_info->name, "HEAD")))) { + unsigned long nr_unpack_entry_at_start; + trace2_region_enter("exp", "report_tracking", the_repository); + nr_unpack_entry_at_start = get_nr_unpack_entry(); report_tracking(new_branch_info); + trace2_data_intmax("exp", NULL, "report_tracking/nr_unpack_entries", + (intmax_t)(get_nr_unpack_entry() - nr_unpack_entry_at_start)); trace2_region_leave("exp", "report_tracking", the_repository); } } diff --git a/packfile.c b/packfile.c index 9cc0a2e37a83dd..cd3bb2fd390291 100644 --- a/packfile.c +++ b/packfile.c @@ -1666,6 +1666,13 @@ struct unpack_entry_stack_ent { unsigned long size; }; +static unsigned long g_nr_unpack_entry; + +unsigned long get_nr_unpack_entry(void) +{ + return g_nr_unpack_entry; +} + void *unpack_entry(struct repository *r, struct packed_git *p, off_t obj_offset, enum object_type *final_type, unsigned long *final_size) { @@ -1679,6 +1686,8 @@ void *unpack_entry(struct repository *r, struct packed_git *p, off_t obj_offset, int delta_stack_nr = 0, delta_stack_alloc = UNPACK_ENTRY_STACK_PREALLOC; int base_from_cache = 0; + g_nr_unpack_entry++; + write_pack_access_log(p, obj_offset); /* PHASE 1: drill down to the innermost base object */ diff --git a/packfile.h b/packfile.h index c3692308b8dc86..6d200c0ea82d08 100644 --- a/packfile.h +++ b/packfile.h @@ -208,4 +208,9 @@ int is_promisor_object(const struct object_id *oid); int load_idx(const char *path, const unsigned int hashsz, void *idx_map, size_t idx_size, struct packed_git *p); +/* + * Return the number of objects fetched from a packfile. + */ +unsigned long get_nr_unpack_entry(void); + #endif diff --git a/unpack-trees.c b/unpack-trees.c index 009f9812a8684d..d9cb063d71b82a 100644 --- a/unpack-trees.c +++ b/unpack-trees.c @@ -14,6 +14,7 @@ #include "tree-walk.h" #include "cache-tree.h" #include "unpack-trees.h" +#include "packfile.h" #include "progress.h" #include "refs.h" #include "attr.h" @@ -1895,6 +1896,7 @@ int unpack_trees(unsigned len, struct tree_desc *t, struct unpack_trees_options struct pattern_list pl; int free_pattern_list = 0; struct dir_struct dir = DIR_INIT; + unsigned long nr_unpack_entry_at_start; if (o->reset == UNPACK_RESET_INVALID) BUG("o->reset had a value of 1; should be UNPACK_TREES_*_UNTRACKED"); @@ -1909,6 +1911,7 @@ int unpack_trees(unsigned len, struct tree_desc *t, struct unpack_trees_options BUG("o->df_conflict_entry is an output only field"); trace2_region_enter("exp", "unpack_trees", NULL); + nr_unpack_entry_at_start = get_nr_unpack_entry(); trace_performance_enter(); trace2_region_enter("unpack_trees", "unpack_trees", the_repository); @@ -2114,6 +2117,8 @@ int unpack_trees(unsigned len, struct tree_desc *t, struct unpack_trees_options } trace2_region_leave("unpack_trees", "unpack_trees", the_repository); trace_performance_leave("unpack_trees"); + trace2_data_intmax("unpack_trees", NULL, "unpack_trees/nr_unpack_entries", + (intmax_t)(get_nr_unpack_entry() - nr_unpack_entry_at_start)); trace2_region_leave("exp", "unpack_trees", NULL); return ret; From cfee221115b76d92d00db6d1cac6c91cb37dc0db Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Thu, 25 Jul 2019 15:43:50 -0400 Subject: [PATCH 14/16] trace2:gvfs:experiment: increase default event depth for unpack-tree data --- trace2/tr2_tgt_event.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c index 59910a1a4f7c0f..3bd80b7236daf9 100644 --- a/trace2/tr2_tgt_event.c +++ b/trace2/tr2_tgt_event.c @@ -37,7 +37,7 @@ static struct tr2_dst tr2dst_event = { * event target. Use the TR2_SYSENV_EVENT_NESTING setting to increase * region details in the event target. */ -static int tr2env_event_max_nesting_levels = 2; +static int tr2env_event_max_nesting_levels = 4; /* * Use the TR2_SYSENV_EVENT_BRIEF to omit the