| Message ID | ce5258610ffbc2e498ff33336c5c89b69468d4fd.1553202340.git.steadmon@google.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | Write trace2 output to directories | expand |
On Thu, Mar 21 2019, Josh Steadmon wrote: > When the value of a trace2 environment variable is an absolute path > referring to an existing directory, write output to files (one per > process) underneath the given directory. Files will be named according > to the final component of the trace2 SID, followed by a counter to avoid > potential collisions. Is this "counter to avoid collisions" something you've seen the need to have in practice, or could we just squash this on top: diff --git a/trace2/tr2_dst.c b/trace2/tr2_dst.c index c3d82ca6a4..06cbef5837 100644 --- a/trace2/tr2_dst.c +++ b/trace2/tr2_dst.c @@ -13,11 +13,6 @@ */ #define TR2_ENVVAR_DST_DEBUG "GIT_TR2_DST_DEBUG" -/* - * How many attempts we will make at creating an automatically-named trace file. - */ -#define MAX_AUTO_ATTEMPTS 10 - static int tr2_dst_want_warning(void) { static int tr2env_dst_debug = -1; @@ -48,7 +43,6 @@ static int tr2_dst_try_auto_path(struct tr2_dst *dst, const char *tgt_prefix) const char *last_slash, *sid = tr2_sid_get(); struct strbuf path = STRBUF_INIT; size_t base_path_len; - unsigned attempt_count; last_slash = strrchr(sid, '/'); if (last_slash) @@ -60,17 +54,7 @@ static int tr2_dst_try_auto_path(struct tr2_dst *dst, const char *tgt_prefix) strbuf_addstr(&path, sid); base_path_len = path.len; - for (attempt_count = 0; attempt_count < MAX_AUTO_ATTEMPTS; attempt_count++) { - if (attempt_count > 0) { - strbuf_setlen(&path, base_path_len); - strbuf_addf(&path, ".%d", attempt_count); - } - - fd = open(path.buf, O_WRONLY | O_CREAT | O_EXCL, 0666); - if (fd != -1) - break; - } - + fd = open(path.buf, O_WRONLY | O_CREAT | O_EXCL, 0666); if (fd == -1) { if (tr2_dst_want_warning()) warning("trace2: could not open '%.*s' for '%s' tracing: %s", The reason I'm raising this is that it seems like sweeping an existing issue under the rug. We document that the "sid" is "unique", and it's just: <nanotime / 1000 (i.e. *nix time in microseconds)>-<pid> So that might be a lie, and in particular I can imagine that say if every machine at Google is logging traces into some magic mounted FS that there'll be collisions there. But then let's *fix that*, because we're also e.g. going to have other consumers of these traces using the sid's as primary keys in a logging system. I wonder if we should just make it a bit longer, human-readable, and include a hash of the hostname: perl -MTime::HiRes=gettimeofday -MSys::Hostname -MDigest::SHA=sha1_hex -MPOSIX=strftime -wE ' my ($t, $m) = gettimeofday; my $host_hex = substr sha1_hex(hostname()), 0, 8; my $htime = strftime("%Y%m%d%H%M%S", localtime); my $sid = sprintf("%s-%6d-%s-%s", $htime, $m, $host_hex, $$ & 0xFFFF, ); say $sid; ' Which gets you a SID like: 20190323213918-404788-c2f5b994-19027 I.e.: <YYYYMMDDHHMMSS>-<microsecond-offset>-<8 chars of sha1(hostname -f)>-<pid> There's obviously ways to make that more compact, but in this case I couldn't see a reason to, also using UTC would be a good idea. All the trace2 tests pass if I fake that up. Jeff H: Do you have anything that relies on the current format? > This makes it more convenient to collect traces for every git invocation > by unconditionally setting the relevant trace2 envvar to a constant > directory name. > > Signed-off-by: Josh Steadmon <steadmon@google.com> > --- > Documentation/technical/api-trace2.txt | 5 ++ > t/t0210-trace2-normal.sh | 15 ++++++ > trace2/tr2_dst.c | 63 +++++++++++++++++++++++++- > 3 files changed, 81 insertions(+), 2 deletions(-) > > diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt > index 2de565fa3d..d0948ba250 100644 > --- a/Documentation/technical/api-trace2.txt > +++ b/Documentation/technical/api-trace2.txt > @@ -109,6 +109,11 @@ values are recognized. > > Enables the target, opens and writes to the file in append mode. > > + If the target already exists and is a directory, the traces will be > + written to files (one per process) underneath the given directory. They > + will be named according to the last component of the SID (optionally > + followed by a counter to avoid filename collisions). > + > `af_unix:[<socket_type>:]<absolute-pathname>`:: > > Enables the target, opens and writes to a Unix Domain Socket > diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh > index 03a0aedb1d..819430658b 100755 > --- a/t/t0210-trace2-normal.sh > +++ b/t/t0210-trace2-normal.sh > @@ -80,6 +80,21 @@ test_expect_success 'normal stream, return code 1' ' > test_cmp expect actual > ' > > +test_expect_success 'automatic filename' ' > + test_when_finished "rm -r traces actual expect" && > + mkdir traces && > + GIT_TR2="$(pwd)/traces" test-tool trace2 001return 0 && > + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <"$(ls traces/*)" >actual && > + cat >expect <<-EOF && > + version $V > + start _EXE_ trace2 001return 0 > + cmd_name trace2 (trace2) > + exit elapsed:_TIME_ code:0 > + atexit elapsed:_TIME_ code:0 > + EOF > + test_cmp expect actual > +' > + > # Verb 002exit > # > # Explicit exit(code) from within cmd_<verb> propagates <code>. > diff --git a/trace2/tr2_dst.c b/trace2/tr2_dst.c > index fd490a43ad..c3d82ca6a4 100644 > --- a/trace2/tr2_dst.c > +++ b/trace2/tr2_dst.c > @@ -1,5 +1,6 @@ > #include "cache.h" > #include "trace2/tr2_dst.h" > +#include "trace2/tr2_sid.h" > > /* > * If a Trace2 target cannot be opened for writing, we should issue a > @@ -12,6 +13,11 @@ > */ > #define TR2_ENVVAR_DST_DEBUG "GIT_TR2_DST_DEBUG" > > +/* > + * How many attempts we will make at creating an automatically-named trace file. > + */ > +#define MAX_AUTO_ATTEMPTS 10 > + > static int tr2_dst_want_warning(void) > { > static int tr2env_dst_debug = -1; > @@ -36,6 +42,55 @@ void tr2_dst_trace_disable(struct tr2_dst *dst) > dst->need_close = 0; > } > > +static int tr2_dst_try_auto_path(struct tr2_dst *dst, const char *tgt_prefix) > +{ > + int fd; > + const char *last_slash, *sid = tr2_sid_get(); > + struct strbuf path = STRBUF_INIT; > + size_t base_path_len; > + unsigned attempt_count; > + > + last_slash = strrchr(sid, '/'); > + if (last_slash) > + sid = last_slash + 1; > + > + strbuf_addstr(&path, tgt_prefix); > + if (!is_dir_sep(path.buf[path.len - 1])) > + strbuf_addch(&path, '/'); > + strbuf_addstr(&path, sid); > + base_path_len = path.len; > + > + for (attempt_count = 0; attempt_count < MAX_AUTO_ATTEMPTS; attempt_count++) { > + if (attempt_count > 0) { > + strbuf_setlen(&path, base_path_len); > + strbuf_addf(&path, ".%d", attempt_count); > + } > + > + fd = open(path.buf, O_WRONLY | O_CREAT | O_EXCL, 0666); > + if (fd != -1) > + break; > + } > + > + if (fd == -1) { > + if (tr2_dst_want_warning()) > + warning("trace2: could not open '%.*s' for '%s' tracing: %s", > + (int) base_path_len, path.buf, > + dst->env_var_name, strerror(errno)); > + > + tr2_dst_trace_disable(dst); > + strbuf_release(&path); > + return 0; > + } > + > + strbuf_release(&path); > + > + dst->fd = fd; > + dst->need_close = 1; > + dst->initialized = 1; > + > + return dst->fd; > +} > + > static int tr2_dst_try_path(struct tr2_dst *dst, const char *tgt_value) > { > int fd = open(tgt_value, O_WRONLY | O_APPEND | O_CREAT, 0666); > @@ -202,8 +257,12 @@ int tr2_dst_get_trace_fd(struct tr2_dst *dst) > return dst->fd; > } > > - if (is_absolute_path(tgt_value)) > - return tr2_dst_try_path(dst, tgt_value); > + if (is_absolute_path(tgt_value)) { > + if (is_directory(tgt_value)) > + return tr2_dst_try_auto_path(dst, tgt_value); > + else > + return tr2_dst_try_path(dst, tgt_value); > + } > > #ifndef NO_UNIX_SOCKETS > if (starts_with(tgt_value, PREFIX_AF_UNIX))
Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes: > The reason I'm raising this is that it seems like sweeping an existing > issue under the rug. We document that the "sid" is "unique", and it's just: > > <nanotime / 1000 (i.e. *nix time in microseconds)>-<pid> If it is just that, then it cannot be unique, can it? Let's just fix the wrong doc and move on.
On Sun, Mar 24 2019, Junio C Hamano wrote: > Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes: > >> The reason I'm raising this is that it seems like sweeping an existing >> issue under the rug. We document that the "sid" is "unique", and it's just: >> >> <nanotime / 1000 (i.e. *nix time in microseconds)>-<pid> > > If it is just that, then it cannot be unique, can it? > > Let's just fix the wrong doc and move on. I don't see why we wouldn't just fix the SID generation & move on if we're already carrying code purely as a work-around for it not being unique enough. Of course nothing is *guaranteed* to be unique, not even a 128-bit UUID. The point is to pick something that's "unique enough" given the problem space, which is already one where we'll ignore I/O errors on writing the file unless you opt-in to a warning. And it's a very useful property to have the SID be a) unique enough like that so you can use a unique index for "git events" b) fixed-width (which the current one *isn't*), so you can use fixed-with indexes in some logging databases c) as a bonus, be human-readable at a glance, hence spending slightly more space on the the YYYMM.. format in my suggested SID format. I can write that patch, but first it's useful to know if this is a case Josh is running into, or if it's just a guard out of paranoia.
Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes: > On Sun, Mar 24 2019, Junio C Hamano wrote: > >> Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes: >> >>> The reason I'm raising this is that it seems like sweeping an existing >>> issue under the rug. We document that the "sid" is "unique", and it's just: >>> >>> <nanotime / 1000 (i.e. *nix time in microseconds)>-<pid> >> >> If it is just that, then it cannot be unique, can it? >> >> Let's just fix the wrong doc and move on. > > I don't see why we wouldn't just fix the SID generation & move on if > we're already carrying code purely as a work-around for it not being > unique enough. The thing is, the yardstick to determine "unique enough" depends on the caller. In this codepath, we want the uniqueness within the directory that was given to us, and one reasonable way, among the most sensible ones, is to ask open(O_CREAT|O_EXCL) and it makes 100% sense to fall back with suffix when "enough" thought by the callee turns out to be insufficient when judged by the caller. So I do not see the .%d suffix a work-around at all. I view it as an integral part of the whole package. By the way, is the "nanotime" implementation that may be in compat/ fine grained enough? > Of course nothing is *guaranteed* to be unique, not even a 128-bit > UUID. The point is to pick something that's "unique enough" given the > problem space, which is already one where we'll ignore I/O errors on > writing the file unless you opt-in to a warning. Yes, the point is to pick something that is unique enough and then give a reasonable fallback when it turns out insufficient. I think ".%d" suffix is one reasonable fallback, but I realize that it is not the only reasonable fallback. Another reasonable fallback could be "upon seeing a failure of open(O_CREAT|O_EXCL), we give up and do not leave a logfile, because this should be a rare enough event as our assumption is sid is unique enough for everyday operation". I could buy that, especially if the ".%d" suffix fallback is too expensive to carry and maintain into the future. And in such a case, it indeed would be a more reasonable workaround for a rare non-unique sid problem to ignore and discard the log. I just did not think the ".%d" suffix fallback is too expensive to carry.
On Mon, Mar 25 2019, Junio C Hamano wrote: > Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes: > >> On Sun, Mar 24 2019, Junio C Hamano wrote: >> >>> Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes: >>> >>>> The reason I'm raising this is that it seems like sweeping an existing >>>> issue under the rug. We document that the "sid" is "unique", and it's just: >>>> >>>> <nanotime / 1000 (i.e. *nix time in microseconds)>-<pid> >>> >>> If it is just that, then it cannot be unique, can it? >>> >>> Let's just fix the wrong doc and move on. >> >> I don't see why we wouldn't just fix the SID generation & move on if >> we're already carrying code purely as a work-around for it not being >> unique enough. > > The thing is, the yardstick to determine "unique enough" depends on > the caller. In this codepath, we want the uniqueness within the > directory that was given to us, and one reasonable way, among the > most sensible ones, is to ask open(O_CREAT|O_EXCL) and it makes 100% > sense to fall back with suffix when "enough" thought by the callee > turns out to be insufficient when judged by the caller. > > So I do not see the .%d suffix a work-around at all. I view it as > an integral part of the whole package. > > By the way, is the "nanotime" implementation that may be in compat/ > fine grained enough? > >> Of course nothing is *guaranteed* to be unique, not even a 128-bit >> UUID. The point is to pick something that's "unique enough" given the >> problem space, which is already one where we'll ignore I/O errors on >> writing the file unless you opt-in to a warning. > > Yes, the point is to pick something that is unique enough and then > give a reasonable fallback when it turns out insufficient. I think > ".%d" suffix is one reasonable fallback, but I realize that it is > not the only reasonable fallback. Another reasonable fallback could > be "upon seeing a failure of open(O_CREAT|O_EXCL), we give up and do > not leave a logfile, because this should be a rare enough event as > our assumption is sid is unique enough for everyday operation". > > I could buy that, especially if the ".%d" suffix fallback is too > expensive to carry and maintain into the future. And in such a > case, it indeed would be a more reasonable workaround for a rare > non-unique sid problem to ignore and discard the log. > > I just did not think the ".%d" suffix fallback is too expensive to > carry. Oh yeah, the SID.%d fallback is easy enough, and I'd 100% agree that if that was *all* it was this would all make sense. Let's just retry, just like a tempfile implementation will retry. But I'm not interested in using the SID-per-file format Josh is adding here, but *am* interested in having a logging system where over a bunch of machines I can expect the SID to be unique with a high degree of probability. So this open(O_CREAT|O_EXCL) code is revealing a problem that we're also going to have in a different form in the GIT_TR2_EVENT=/var/log/one-big-file-of.json format. It seems to me that the only reason both of these are an issue is something we can fix with the SID generation.
On 3/23/2019 4:44 PM, Ævar Arnfjörð Bjarmason wrote: > > On Thu, Mar 21 2019, Josh Steadmon wrote: > >> When the value of a trace2 environment variable is an absolute path >> referring to an existing directory, write output to files (one per >> process) underneath the given directory. Files will be named according >> to the final component of the trace2 SID, followed by a counter to avoid >> potential collisions. > [...] > > The reason I'm raising this is that it seems like sweeping an existing > issue under the rug. We document that the "sid" is "unique", and it's just: > > <nanotime / 1000 (i.e. *nix time in microseconds)>-<pid> > > So that might be a lie, and in particular I can imagine that say if > every machine at Google is logging traces into some magic mounted FS > that there'll be collisions there. > > But then let's *fix that*, because we're also e.g. going to have other > consumers of these traces using the sid's as primary keys in a logging > system. > > I wonder if we should just make it a bit longer, human-readable, and > include a hash of the hostname: > > perl -MTime::HiRes=gettimeofday -MSys::Hostname -MDigest::SHA=sha1_hex -MPOSIX=strftime -wE ' > my ($t, $m) = gettimeofday; > my $host_hex = substr sha1_hex(hostname()), 0, 8; > my $htime = strftime("%Y%m%d%H%M%S", localtime); > my $sid = sprintf("%s-%6d-%s-%s", > $htime, > $m, > $host_hex, > $$ & 0xFFFF, > ); > say $sid; > ' > > Which gets you a SID like: > > 20190323213918-404788-c2f5b994-19027 > > I.e.: > > <YYYYMMDDHHMMSS>-<microsecond-offset>-<8 chars of sha1(hostname -f)>-<pid> > > There's obviously ways to make that more compact, but in this case I > couldn't see a reason to, also using UTC would be a good idea. > > All the trace2 tests pass if I fake that up. Jeff H: Do you have > anything that relies on the current format? I'm using the SID hierarchy to track parent and child processes, but the actual format of an individual SID-component is mostly a black box. I used the microseconds+pid as unique enough. And events for new commands will mostly just append to an existing index, rather than being a random insert like you'd get for a GUID. I didn't use a GUID here because that seemed overkill and a little bit more expensive, but perhaps that was just premature optimization on my part. So, a new fixed width format like you suggested above would be fine. I wonder though, if we're moving towards a stronger SID, there's no reason to keep the PID in it. Which makes me wonder about the value of sha(hostname) too. Perhaps, just make it a GUID or some combination of the UTC date and a GUID ( <YYMMDDHHMMSS>-<microseconds>-<GUID> ) or something like that. If it helps, we can change how I'm reporting the SID between parent and child processes, so that the SID field in the JSON events is just the SID of the current process and have a peer field with the SID-hierarchy. This latter field would only need to be added to the "version" or "start" event. This might make post-processing a little easier. Not sure it matters one way or the other. I'm open to suggestions here. Jeff
diff --git a/Documentation/technical/api-trace2.txt b/Documentation/technical/api-trace2.txt index 2de565fa3d..d0948ba250 100644 --- a/Documentation/technical/api-trace2.txt +++ b/Documentation/technical/api-trace2.txt @@ -109,6 +109,11 @@ values are recognized. Enables the target, opens and writes to the file in append mode. + If the target already exists and is a directory, the traces will be + written to files (one per process) underneath the given directory. They + will be named according to the last component of the SID (optionally + followed by a counter to avoid filename collisions). + `af_unix:[<socket_type>:]<absolute-pathname>`:: Enables the target, opens and writes to a Unix Domain Socket diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh index 03a0aedb1d..819430658b 100755 --- a/t/t0210-trace2-normal.sh +++ b/t/t0210-trace2-normal.sh @@ -80,6 +80,21 @@ test_expect_success 'normal stream, return code 1' ' test_cmp expect actual ' +test_expect_success 'automatic filename' ' + test_when_finished "rm -r traces actual expect" && + mkdir traces && + GIT_TR2="$(pwd)/traces" test-tool trace2 001return 0 && + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <"$(ls traces/*)" >actual && + cat >expect <<-EOF && + version $V + start _EXE_ trace2 001return 0 + cmd_name trace2 (trace2) + exit elapsed:_TIME_ code:0 + atexit elapsed:_TIME_ code:0 + EOF + test_cmp expect actual +' + # Verb 002exit # # Explicit exit(code) from within cmd_<verb> propagates <code>. diff --git a/trace2/tr2_dst.c b/trace2/tr2_dst.c index fd490a43ad..c3d82ca6a4 100644 --- a/trace2/tr2_dst.c +++ b/trace2/tr2_dst.c @@ -1,5 +1,6 @@ #include "cache.h" #include "trace2/tr2_dst.h" +#include "trace2/tr2_sid.h" /* * If a Trace2 target cannot be opened for writing, we should issue a @@ -12,6 +13,11 @@ */ #define TR2_ENVVAR_DST_DEBUG "GIT_TR2_DST_DEBUG" +/* + * How many attempts we will make at creating an automatically-named trace file. + */ +#define MAX_AUTO_ATTEMPTS 10 + static int tr2_dst_want_warning(void) { static int tr2env_dst_debug = -1; @@ -36,6 +42,55 @@ void tr2_dst_trace_disable(struct tr2_dst *dst) dst->need_close = 0; } +static int tr2_dst_try_auto_path(struct tr2_dst *dst, const char *tgt_prefix) +{ + int fd; + const char *last_slash, *sid = tr2_sid_get(); + struct strbuf path = STRBUF_INIT; + size_t base_path_len; + unsigned attempt_count; + + last_slash = strrchr(sid, '/'); + if (last_slash) + sid = last_slash + 1; + + strbuf_addstr(&path, tgt_prefix); + if (!is_dir_sep(path.buf[path.len - 1])) + strbuf_addch(&path, '/'); + strbuf_addstr(&path, sid); + base_path_len = path.len; + + for (attempt_count = 0; attempt_count < MAX_AUTO_ATTEMPTS; attempt_count++) { + if (attempt_count > 0) { + strbuf_setlen(&path, base_path_len); + strbuf_addf(&path, ".%d", attempt_count); + } + + fd = open(path.buf, O_WRONLY | O_CREAT | O_EXCL, 0666); + if (fd != -1) + break; + } + + if (fd == -1) { + if (tr2_dst_want_warning()) + warning("trace2: could not open '%.*s' for '%s' tracing: %s", + (int) base_path_len, path.buf, + dst->env_var_name, strerror(errno)); + + tr2_dst_trace_disable(dst); + strbuf_release(&path); + return 0; + } + + strbuf_release(&path); + + dst->fd = fd; + dst->need_close = 1; + dst->initialized = 1; + + return dst->fd; +} + static int tr2_dst_try_path(struct tr2_dst *dst, const char *tgt_value) { int fd = open(tgt_value, O_WRONLY | O_APPEND | O_CREAT, 0666); @@ -202,8 +257,12 @@ int tr2_dst_get_trace_fd(struct tr2_dst *dst) return dst->fd; } - if (is_absolute_path(tgt_value)) - return tr2_dst_try_path(dst, tgt_value); + if (is_absolute_path(tgt_value)) { + if (is_directory(tgt_value)) + return tr2_dst_try_auto_path(dst, tgt_value); + else + return tr2_dst_try_path(dst, tgt_value); + } #ifndef NO_UNIX_SOCKETS if (starts_with(tgt_value, PREFIX_AF_UNIX))
When the value of a trace2 environment variable is an absolute path referring to an existing directory, write output to files (one per process) underneath the given directory. Files will be named according to the final component of the trace2 SID, followed by a counter to avoid potential collisions. This makes it more convenient to collect traces for every git invocation by unconditionally setting the relevant trace2 envvar to a constant directory name. Signed-off-by: Josh Steadmon <steadmon@google.com> --- Documentation/technical/api-trace2.txt | 5 ++ t/t0210-trace2-normal.sh | 15 ++++++ trace2/tr2_dst.c | 63 +++++++++++++++++++++++++- 3 files changed, 81 insertions(+), 2 deletions(-)