From ebe6f19dd3466d69cab5a08a202e23b57b7c1d01 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 7a9574c09e17be..5144a339a8fd2b 100644 --- a/object-file.c +++ b/object-file.c @@ -41,6 +41,7 @@ #include "loose.h" #include "object-file-convert.h" #include "trace.h" +#include "trace2.h" #include "hook.h" #include "sigchain.h" #include "sub-process.h" @@ -1065,6 +1066,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, @@ -1081,13 +1084,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); @@ -1136,6 +1142,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 701b87cd1079f33cddf02de611b3becbf7a51ea6 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 b66eafac515736..b552c940ee2ee7 100644 --- a/builtin/commit.c +++ b/builtin/commit.c @@ -165,6 +165,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; @@ -228,7 +229,7 @@ static int opt_parse_deserialize(const struct option *opt UNUSED, const char *ar } 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 { /* @@ -1601,6 +1602,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; } @@ -1754,6 +1757,17 @@ struct repository *repo UNUSED) 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 && @@ -1797,6 +1811,7 @@ struct repository *repo UNUSED) 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; @@ -1814,6 +1829,7 @@ struct repository *repo UNUSED) fd = -1; } + trace2_cmd_mode("collect"); wt_status_collect(&s); if (0 <= fd) @@ -1828,6 +1844,7 @@ struct repository *repo UNUSED) 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 0dde6a451aea98..1e851afec4616b 100644 --- a/wt-status-deserialize.c +++ b/wt-status-deserialize.c @@ -9,6 +9,23 @@ #include "statinfo.h" #include "hex.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); @@ -55,6 +72,7 @@ static int my_validate_index(const char *path, const struct cache_time *mtime_re 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; } @@ -62,6 +80,7 @@ static int my_validate_index(const char *path, const struct cache_time *mtime_re 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, @@ -87,10 +106,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; @@ -146,6 +167,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; @@ -229,6 +251,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; } @@ -244,19 +267,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; } @@ -343,6 +370,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", @@ -484,6 +512,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); @@ -491,6 +520,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); @@ -524,6 +554,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; } @@ -595,20 +629,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; } @@ -642,19 +680,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; } @@ -742,15 +784,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 @@ -775,6 +820,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); @@ -800,6 +851,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 { @@ -810,8 +863,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 b6cf4531fe56a4..03c25186491990 100644 --- a/wt-status.h +++ b/wt-status.h @@ -246,6 +246,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 c7735387c549f791def0a0bd60f055a3990c67a1 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 beaa7bd565cf2c..d5f8baa63efd66 100644 --- a/wt-status-serialize.c +++ b/wt-status-serialize.c @@ -9,6 +9,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); @@ -305,6 +306,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. */ @@ -338,4 +341,6 @@ void wt_status_serialize_v1(int fd, struct wt_status *s) } packet_flush(fd); } + + trace2_region_leave("status", "serialize", the_repository); } From ce0dd9a06d8436ebcf4683f39b5a7720a6d2d23d 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 ae191ad05adf4c..20810c541558ce 100644 --- a/virtualfilesystem.c +++ b/virtualfilesystem.c @@ -3,6 +3,7 @@ #include "git-compat-util.h" #include "environment.h" #include "gettext.h" +#include "trace2.h" #include "config.h" #include "dir.h" #include "hashmap.h" @@ -260,6 +261,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 (!repo_config_get_virtualfilesystem(istate->repo)) return; @@ -277,16 +283,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++; } @@ -294,18 +305,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 2df249a84434199635095a4b0f5566afbbb601b6 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 be0c7a7a24621e..a119ea51326003 100644 --- a/compat/mingw.c +++ b/compat/mingw.c @@ -4095,6 +4095,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 3c09592d02e0cf9b09e18238fc64de86198229a0 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 982f97114ec8a1..dd2577ce15dd2b 100644 --- a/unpack-trees.c +++ b/unpack-trees.c @@ -1790,6 +1790,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 3b76c51dd7b4fab5a06387258b0c99d6dffbb9aa 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 0a5fe8c639c320..b389f74784712e 100644 --- a/builtin/checkout.c +++ b/builtin/checkout.c @@ -1047,8 +1047,11 @@ static void update_refs_for_switch(const struct checkout_opts *opts, strbuf_release(&msg); if (!opts->quiet && !opts->force_detach && - (new_branch_info->path || !strcmp(new_branch_info->name, "HEAD"))) + (new_branch_info->path || !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, const char *referent UNUSED, From cdfaedd21f9c71f4cde9a51f1445cdefee8b377f 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 3fa311f27cdfc6..aa5ac10206c6b9 100644 --- a/read-cache.c +++ b/read-cache.c @@ -2053,6 +2053,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. @@ -2129,12 +2140,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; } @@ -2304,7 +2320,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 55e10e0ae2a1baa8c6744b2fe546b1e2367246ff 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 aa5ac10206c6b9..72d1ac81094c26 100644 --- a/read-cache.c +++ b/read-cache.c @@ -1763,7 +1763,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); @@ -3050,9 +3053,13 @@ static int do_write_index(struct index_state *istate, struct tempfile *tempfile, !drop_cache_tree && istate->cache_tree) { strbuf_reset(&sb); + 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); + if (err) { ret = -1; goto out; From 4c4bae9b0c884a9262b67702b52fdf526daf89f5 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 20810c541558ce..bb7c2549481a74 100644 --- a/virtualfilesystem.c +++ b/virtualfilesystem.c @@ -270,6 +270,8 @@ void apply_virtualfilesystem(struct index_state *istate) if (!repo_config_get_virtualfilesystem(istate->repo)) return; + trace2_region_enter("vfs", "apply", the_repository); + if (!virtual_filesystem_data.len) get_virtual_filesystem_data(istate->repo, &virtual_filesystem_data); @@ -340,6 +342,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 a1f32969a439edc1c5fa727700e5b272f7f39ca5 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 dd2577ce15dd2b..28db5284a42b6c 100644 --- a/unpack-trees.c +++ b/unpack-trees.c @@ -1913,6 +1913,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); @@ -2122,6 +2124,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 edf9d8a593b91dbe0239642a0119bd32ab16ec3c 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 69ca9dcd17c0ba..c628dd932531fe 100644 --- a/cache-tree.c +++ b/cache-tree.c @@ -233,7 +233,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) @@ -241,7 +241,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; @@ -252,6 +252,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 fc351808ce7942051f8479d2e96dad2e6e9691f4 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 b389f74784712e..0ca12417fa6684 100644 --- a/builtin/checkout.c +++ b/builtin/checkout.c @@ -18,6 +18,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" @@ -1048,8 +1049,13 @@ static void update_refs_for_switch(const struct checkout_opts *opts, if (!opts->quiet && !opts->force_detach && (new_branch_info->path || !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 df4ba677197193..c3346197a08a2c 100644 --- a/packfile.c +++ b/packfile.c @@ -1678,6 +1678,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) { @@ -1691,6 +1698,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 0f7865822916ff..33efd0d4c0bfe1 100644 --- a/packfile.h +++ b/packfile.h @@ -214,4 +214,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 28db5284a42b6c..e21758308f21c8 100644 --- a/unpack-trees.c +++ b/unpack-trees.c @@ -16,6 +16,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" @@ -1900,6 +1901,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"); @@ -1914,6 +1916,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); @@ -2124,6 +2127,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 5b432948d3ccfa345bf91e9f2ebb4c3273425220 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 45b0850a5ec5c8..04f2e5390bc749 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