From f59dc8bfc45d9e025855d9c747947c11c5903699 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 0cd04c296b4a6b..97846781e945ac 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 81f5f4a539f971cf91eeb3abeb7896e47ce6248c 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 046046a2734f66..5bebd6af0cff3b 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 f0b14851771a34..5984570223d266 100644 --- a/wt-status-deserialize.c +++ b/wt-status-deserialize.c @@ -6,6 +6,23 @@ #include "wt-status.h" #include "pkt-line.h" #include "trace.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); @@ -53,6 +70,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; } @@ -60,6 +78,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, @@ -85,10 +104,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; @@ -144,6 +165,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; @@ -227,6 +249,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; } @@ -242,19 +265,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; } @@ -341,6 +368,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", @@ -482,6 +510,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); @@ -489,6 +518,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); @@ -522,6 +552,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; } @@ -543,6 +574,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; } @@ -563,6 +595,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; } @@ -573,6 +606,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; } @@ -589,20 +623,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; } @@ -636,19 +674,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; } @@ -737,15 +779,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 @@ -770,6 +815,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); @@ -795,6 +846,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 { @@ -805,8 +858,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 6bc21e7d47b6b092d07285e5ed46ac14692aceac 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 67c96266ebe34d..9da66835c6e64f 100644 --- a/wt-status-serialize.c +++ b/wt-status-serialize.c @@ -6,6 +6,7 @@ #include "wt-status.h" #include "pkt-line.h" #include "trace.h" +#include "trace2.h" static struct trace_key trace_serialize = TRACE_KEY_INIT(SERIALIZE); @@ -302,6 +303,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. */ @@ -335,4 +338,6 @@ void wt_status_serialize_v1(int fd, struct wt_status *s) } packet_flush(fd); } + + trace2_region_leave("status", "serialize", the_repository); } From 58b200566e9d9d62c720660c6b207007bd54643a 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 | 39 +++++++++++++++++++++++++++++++++++++-- 1 file changed, 37 insertions(+), 2 deletions(-) diff --git a/virtualfilesystem.c b/virtualfilesystem.c index 52afa554b41585..f98f654ee6454e 100644 --- a/virtualfilesystem.c +++ b/virtualfilesystem.c @@ -1,6 +1,8 @@ #include "git-compat-util.h" #include "environment.h" #include "gettext.h" +#include "repository.h" +#include "trace2.h" #include "cache.h" #include "config.h" #include "dir.h" @@ -257,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; @@ -274,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++; } @@ -291,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 538d7ea511e92eae62cd2757771498ca8a9bba81 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 588da2f3cb0ee7..26f220c35294be 100644 --- a/compat/mingw.c +++ b/compat/mingw.c @@ -4016,6 +4016,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 50d96ab0b5ef4ed8a87503608c67ce6256b5ff8f 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 8b9d95a4ff5fa1..14a863f94881b1 100644 --- a/unpack-trees.c +++ b/unpack-trees.c @@ -1780,6 +1780,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 a00f36485ea0cea68b94e623b669a90e52ab7af2 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 277197d41d9cb0..c9cc7863a31e7d 100644 --- a/builtin/checkout.c +++ b/builtin/checkout.c @@ -1018,8 +1018,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 73eeb3af357ab7f3d603cbc156fde1a47a23fdb4 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 548bd3703a67249d4e79f38d6b6c8e20eeb85661 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 fa0a48fa3856d21beaa1b97c20c1c30668edf3e6 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 f98f654ee6454e..21c3736ebe33d9 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 a1e819df90547f52021196377b3b040822e6a96d 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 14a863f94881b1..b2a8f19e4b3aee 100644 --- a/unpack-trees.c +++ b/unpack-trees.c @@ -1903,6 +1903,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); @@ -2107,6 +2109,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 aa479b21091212a6e1bb18d269b2a78eb6293734 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 4e18eb0ade1c2730f93043ca663d753c847c013b 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 c9cc7863a31e7d..dcf26551aa800d 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" @@ -1019,8 +1020,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 b2a8f19e4b3aee..c0d7f6e9e8843f 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" @@ -1890,6 +1891,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"); @@ -1904,6 +1906,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); @@ -2109,6 +2112,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 c8a9d8be014b1562b7a5e192297f99f808184eb8 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 53091781eca5dc..a2db65d4e37f93 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