analyze: Add "timespan" command to dump time span in usec #10411

cdown · 2018-10-15T16:54:42Z

This is useful for a couple of cases, I'm mostly interested in case #1:

Verifying "reasonable" values in a trivially scriptable way
Debugging unexpected time span parsing directly

Test Plan:

% build/systemd-analyze timespan 20
Original: 20
      μs: 20
   Human: 20us
% build/systemd-analyze timespan 20ms
Original: 20ms
      μs: 20000
   Human: 20ms
% build/systemd-analyze timespan 20z
Failed to parse time span '20z': Invalid argument
% build/systemd-analyze timespan 20ms 30ms 50ms
Original: 20ms
      μs: 20000
   Human: 20ms

Original: 30ms
      μs: 30000
   Human: 30ms

Original: 50ms
      μs: 50000
   Human: 50ms

poettering · 2018-10-15T19:15:40Z

Shouldn't the output show both the time in raw µs (as your patch does it) and normalized in pretty printed way? (i.e. with format_timestamp())?

I am a bit puzzled why this takes two arguments? I mean "systemd-analyze timespan 5 s" is the same as "systemd-analyze timestamp 5s" in this way, no? hence why have it at all? sounds like the second argument shouldn't really be there if we parse it from user passed data anyway, because then it's really redundant, as the user might just add the unit to the first argument instead and things are much simpler then

poettering · 2018-10-15T19:41:52Z

src/analyze/analyze.c

+
+        if (argc == 3) {
+                char **multiplier = argv + 2;
+                extract_multiplier(*multiplier, &default_unit);


this would be a bit sloppy, because specifiyng "sec foobarxxxxyzzzz" would be parsed cleanly, even though it really shouldn't...

For this one, do you have a suggestion on how the multiplier specification should be handled if it is to be kept? That is, as you mention, I notice that extract_multiplier currently has no way to return match/no match status because currently in the way it interacts with parse_time it doesn't have to, but in this case to avoid this I think we have to know whether we actually matched something by returning int and changing the return to happen as a mutable argument, perhaps?

(Also, I was somewhat surprised that extract_multiplier checks "starts with" instead of doing direct equality matching.)

well, extract_multipler() is an internal call so far, that is used exclusively while we iteratively parse a time specification. i.e. when we parse a string such as "5s 153ms 5us" we use it to parse the "s", the "ms" and the "us", and each time we need to continue parsing right after, hence it works the way it works, that it uses startswith() and returns where we left of.

That said, I am still not convinced that specifying the default unit is really useful. Where's the benefit of being able to write "5" "s" in two arguments rather than requiring "5s" in one?

poettering · 2018-10-15T19:42:23Z

src/analyze/analyze.c

+        r = parse_time(*input_timespan, &output_usecs, default_unit);
+        if (r < 0) {
+                ret = log_error_errno(r, "Failed to parse time span '%s': %m", *input_timespan);
+                return ret;


why use "ret" here instead of returning log_error_errno() directly?

poettering · 2018-10-15T19:42:43Z

src/analyze/analyze.c

+
+        printf("%" PRIu64 "\n", output_usecs);
+
+        return ret;


maybe drop "ret" entirely, and instead do "return EXIT_SUCCESS" here?

cdown · 2018-10-15T20:12:42Z

Agreed with all the points, thanks. Only a couple of things to clarify:

I am a bit puzzled why this takes two arguments? I mean "systemd-analyze timespan 5 s" is the same as "systemd-analyze timestamp 5s" in this way, no? hence why have it at all?

What if one wants to debug (as an example) a directive with an implied default unit magnitude? Then one no longer can copy and paste and think about the default unit separately, but they have to find the default unit and manually edit it in. This isn't a massive deal, but seems non-ideal.

I think the current approach avoids the pitfalls of each approach individually since you can also do this now just by doing what you said and not having to pass any unit magnitude, but you can also do it the other way if you prefer to not have to find/edit in the magnitude directly.

Shouldn't the output show both the time in raw µs (as your patch does it) and normalized in pretty printed way?

Sure, I'll add that.

poettering · 2018-10-15T20:48:41Z

What if one wants to debug (as an example) a directive with an implied default unit magnitude? Then one no longer can copy and paste and think about the default unit separately, but they have to find the default unit and manually edit it in. This isn't a massive deal, but seems non-ideal.

hmm, example?

i mean, if i want to check what "565" means on an configuration item that uses "us" as default unit. So with your current proposal i could write that as systemd-analyze timespan 565 us. But instead we could just say: write it as systemd-analyze timespan 565us instead, or even systemd-analyze timespan "565 us", which has the same effect really...

or we could even take it one notch further: if multiple arguments are specified, let's just strv_join() them, i.e. so that systemd-analyze timespan 565 us would result in the two arguments 565 and us being concatenated into one string, which would make things work pretty much the same way as you suggest, except things are a ton more powerful

cdown · 2018-10-15T20:55:28Z

Ah, wait, you're right. Since only the last number can be the one without a unit, it makes no difference at all. In which case maybe we should even ban numbers without any unit specified from this. I'll make the changes.

cdown · 2018-10-22T14:37:48Z

I believe all comments are now resolved. :-)

poettering

looks pretty good already, but some points

poettering · 2018-10-22T19:07:57Z

man/systemd-analyze.xml


+    <para><command>systemd-analyze timespan</command> parses a time span and outputs the equivalent value in microseconds.
+    The time span should adhere to the same syntax documented in <citerefentry><refentrytitle>systemd.time</refentrytitle><manvolnum>7</manvolnum></citerefentry>.
+    Values without associated magnitudes are parsed as microseconds.</para>


almost all our time settings default to second magnitude. I think this should too, to be least surprising.

poettering · 2018-10-22T19:08:32Z

src/analyze/analyze.c

+        char ft_buf[FORMAT_TIMESPAN_MAX];
+
+        STRV_FOREACH(input_timespan, strv_skip(argv, 1)) {
+            r = parse_time(*input_timespan, &output_usecs, usec_magnitude);


Please follow CODING_STYLE, indentation by multiples of 8ch only

poettering · 2018-10-22T19:08:50Z

src/analyze/analyze.c

+            r = parse_time(*input_timespan, &output_usecs, usec_magnitude);
+            if (r < 0) {
+                    return log_error_errno(r, "Failed to parse time span '%s': %m", *input_timespan);
+            }


please follow CODING_STYLE, no {} around single-line if blocks, please

poettering · 2018-10-22T19:10:09Z

src/analyze/analyze.c

+        int r;
+        char **input_timespan;
+        usec_t usec_magnitude = 1, output_usecs;
+        char ft_buf[FORMAT_TIMESPAN_MAX];


please move all variables only used in the loop into the loop. We usually define all variables at the innermost scope they are used (though r is usually defined on the outermost, given that we pretty much always have that, as it is our usual variable for storing return codes that might be errors)

poettering · 2018-10-22T19:11:14Z

src/analyze/analyze.c

+            }
+
+            printf("Original: %s\n", *input_timespan);
+            printf("      μs: %" PRIu64 "\n", output_usecs);


I like the use of unicode, but I figure this needs to be added to the special_glyph() logic, see locale-util.[ch] for details, so that it has an ASCII fallback (µ → u)...

poettering · 2018-10-22T19:12:17Z

src/analyze/analyze.c

+            printf("      μs: %" PRIu64 "\n", output_usecs);
+            printf("   Human: %s\n", format_timespan(ft_buf, sizeof(ft_buf), output_usecs, usec_magnitude));
+
+            if (*(input_timespan + 1))


I think if (input_timespan[1]) is a tiny bit more readable, but doesn't matter

This is useful for a couple of cases, I'm mostly interested in case systemd#1: 1. Verifying "reasonable" values in a trivially scriptable way 2. Debugging unexpected time span parsing directly Test Plan: ``` % build/systemd-analyze timespan 20 Original: 20 μs: 20 Human: 20us % build/systemd-analyze timespan 20ms Original: 20ms μs: 20000 Human: 20ms % build/systemd-analyze timespan 20z Failed to parse time span '20z': Invalid argument ```

cdown · 2018-10-23T09:31:58Z

Thanks, all resolved now I think.

poettering · 2018-10-23T09:54:20Z

excellent! thanks! lgtm!

cdown · 2018-10-23T11:27:23Z

i386 test failure looks unrelated:

======================================================================
ERROR: test_lightdm (__main__.ServicesTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/tmp/autopkgtest.87oEW8/build.aLd/debian/debian/tests/boot-and-services", line 65, in test_lightdm
    out = subprocess.check_output(['ps', 'u', '-C', 'lightdm'])
  File "/usr/lib/python3.6/subprocess.py", line 336, in check_output
    **kwargs).stdout
  File "/usr/lib/python3.6/subprocess.py", line 418, in run
    output=stdout, stderr=stderr)
subprocess.CalledProcessError: Command '['ps', 'u', '-C', 'lightdm']' returned non-zero exit status 1.

evverx · 2018-10-23T12:43:43Z

I'm not sure how to interpret the following output:

./build/systemd-analyze timespan '1111111111111111111y'
Original: 1111111111111111111y
      μs: 10816682103480387584
   Human: 342759y 11month 2w 6d 8h 8min 387.584ms

Something has overflowed somewhere apparently :-)

evverx · 2018-10-23T12:44:48Z

The command itself is very handy. Thank you!

cdown · 2018-10-24T13:33:37Z

Something has overflowed somewhere apparently :-)

That's interesting, because on mine ERANGE is successfully returned from parse_time:

systemd parse_time % ./build/systemd-analyze timespan '1111111111111111111y'
Failed to parse time span '1111111111111111111y': Numerical result out of range

Maybe something in the checks is resulting in UB?

evverx · 2018-10-24T13:47:32Z

@yuwata fixed the overflow in #10493, so If 8079c90 is included in the build, then ERANGE is expected. If it isn't, then it's indeed interesting.

Summary: Rebase two fixes onto the version merged upstream: systemd/systemd#10507 systemd/systemd#10567 and backport a few more: systemd/systemd#10411 systemd/systemd#10493 systemd/systemd#10757 systemd/systemd#10876 These are almost all cgroup2 related. Reviewed By: cdown Differential Revision: D13351498 fbshipit-source-id: 87c8428d48dbb0eb2ae7d34f7381fff88f83872f

cdown force-pushed the analyze-timespan-2 branch from 4b0f2eb to 5fcb2cb Compare October 15, 2018 16:58

cdown changed the title ~~[analyze] Add "timespan" command to dump time span in usec~~ analyze: Add "timespan" command to dump time span in usec Oct 15, 2018

poettering reviewed Oct 15, 2018

View reviewed changes

poettering added analyze reviewed/needs-rework 🔨 PR has been reviewed and needs another round of reworks labels Oct 15, 2018

cdown force-pushed the analyze-timespan-2 branch 4 times, most recently from a3957b2 to b0860e0 Compare October 22, 2018 14:36

cdown force-pushed the analyze-timespan-2 branch 2 times, most recently from 39bd9f2 to ec7bf58 Compare October 22, 2018 15:01

poettering requested changes Oct 22, 2018

View reviewed changes

cdown force-pushed the analyze-timespan-2 branch from ec7bf58 to 1d7145f Compare October 23, 2018 09:31

poettering approved these changes Oct 23, 2018

View reviewed changes

poettering added good-to-merge/waiting-for-ci 👍 PR is good to merge, but CI hasn't passed at time of review. Please merge if you see CI has passed and removed reviewed/needs-rework 🔨 PR has been reviewed and needs another round of reworks labels Oct 23, 2018

poettering merged commit 3f1c128 into systemd:master Oct 23, 2018

yuwata mentioned this pull request Oct 23, 2018

util: check overflow in parse_time() and parse_nsec() #10493

Merged

Uh oh!

analyze: Add "timespan" command to dump time span in usec #10411

analyze: Add "timespan" command to dump time span in usec #10411

Uh oh!

Conversation

cdown commented Oct 15, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

poettering commented Oct 15, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cdown Oct 15, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cdown commented Oct 15, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

poettering commented Oct 15, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cdown commented Oct 15, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cdown commented Oct 22, 2018

Uh oh!

poettering left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

poettering Oct 22, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cdown commented Oct 23, 2018

Uh oh!

poettering commented Oct 23, 2018

Uh oh!

cdown commented Oct 23, 2018

Uh oh!

evverx commented Oct 23, 2018

Uh oh!

evverx commented Oct 23, 2018

Uh oh!

cdown commented Oct 24, 2018

Uh oh!

evverx commented Oct 24, 2018

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

3 participants

cdown commented Oct 15, 2018 •

edited

Loading

cdown Oct 15, 2018 •

edited

Loading

cdown commented Oct 15, 2018 •

edited

Loading

poettering commented Oct 15, 2018 •

edited

Loading

cdown commented Oct 15, 2018 •

edited

Loading

poettering Oct 22, 2018 •

edited

Loading