util: make time formatting a bit smarter
Instead of outputting "5h 55s 50ms 3us" we'll now output "5h 55.050003s". Also, while outputting the accuracy is configurable. Basically we now try use "dot notation" for all time values > 1min. For >= 1s we use 's' as unit, otherwise for >= 1ms we use 'ms' as unit, and finally 'us'. This should give reasonably values in most cases.
This commit is contained in:
parent
911963f1a2
commit
2fa4092c28
|
@ -331,19 +331,19 @@ static int pretty_boot_time(DBusConnection *bus, char **_buf) {
|
|||
|
||||
size = strpcpyf(&ptr, size, "Startup finished in ");
|
||||
if (t->firmware_time)
|
||||
size = strpcpyf(&ptr, size, "%s (firmware) + ", format_timespan(ts, sizeof(ts), t->firmware_time - t->loader_time));
|
||||
size = strpcpyf(&ptr, size, "%s (firmware) + ", format_timespan(ts, sizeof(ts), t->firmware_time - t->loader_time, USEC_PER_MSEC));
|
||||
if (t->loader_time)
|
||||
size = strpcpyf(&ptr, size, "%s (loader) + ", format_timespan(ts, sizeof(ts), t->loader_time));
|
||||
size = strpcpyf(&ptr, size, "%s (loader) + ", format_timespan(ts, sizeof(ts), t->loader_time, USEC_PER_MSEC));
|
||||
if (t->kernel_time)
|
||||
size = strpcpyf(&ptr, size, "%s (kernel) + ", format_timespan(ts, sizeof(ts), t->kernel_done_time));
|
||||
size = strpcpyf(&ptr, size, "%s (kernel) + ", format_timespan(ts, sizeof(ts), t->kernel_done_time, USEC_PER_MSEC));
|
||||
if (t->initrd_time > 0)
|
||||
size = strpcpyf(&ptr, size, "%s (initrd) + ", format_timespan(ts, sizeof(ts), t->userspace_time - t->initrd_time));
|
||||
size = strpcpyf(&ptr, size, "%s (initrd) + ", format_timespan(ts, sizeof(ts), t->userspace_time - t->initrd_time, USEC_PER_MSEC));
|
||||
|
||||
size = strpcpyf(&ptr, size, "%s (userspace) ", format_timespan(ts, sizeof(ts), t->finish_time - t->userspace_time));
|
||||
size = strpcpyf(&ptr, size, "%s (userspace) ", format_timespan(ts, sizeof(ts), t->finish_time - t->userspace_time, USEC_PER_MSEC));
|
||||
if (t->kernel_time > 0)
|
||||
size = strpcpyf(&ptr, size, "= %s", format_timespan(ts, sizeof(ts), t->firmware_time + t->finish_time));
|
||||
size = strpcpyf(&ptr, size, "= %s", format_timespan(ts, sizeof(ts), t->firmware_time + t->finish_time, USEC_PER_MSEC));
|
||||
else
|
||||
size = strpcpyf(&ptr, size, "= %s", format_timespan(ts, sizeof(ts), t->finish_time - t->userspace_time));
|
||||
size = strpcpyf(&ptr, size, "= %s", format_timespan(ts, sizeof(ts), t->finish_time - t->userspace_time, USEC_PER_MSEC));
|
||||
|
||||
ptr = strdup(buf);
|
||||
if (!ptr)
|
||||
|
@ -530,7 +530,7 @@ static int analyze_plot(DBusConnection *bus) {
|
|||
b = u->ixt * SCALE_X > width * 2 / 3;
|
||||
if (u->time)
|
||||
svg_text(b, u->ixt, y, "%s (%s)",
|
||||
u->name, format_timespan(ts, sizeof(ts), u->time));
|
||||
u->name, format_timespan(ts, sizeof(ts), u->time, USEC_PER_MSEC));
|
||||
else
|
||||
svg_text(b, u->ixt, y, "%s", u->name);
|
||||
y++;
|
||||
|
@ -559,7 +559,7 @@ static int analyze_blame(DBusConnection *bus) {
|
|||
char ts[FORMAT_TIMESPAN_MAX];
|
||||
|
||||
if (times[i].time > 0)
|
||||
printf("%16s %s\n", format_timespan(ts, sizeof(ts), times[i].time), times[i].name);
|
||||
printf("%16s %s\n", format_timespan(ts, sizeof(ts), times[i].time, USEC_PER_MSEC), times[i].name);
|
||||
}
|
||||
|
||||
free_unit_times(times, (unsigned) n);
|
||||
|
|
|
@ -803,7 +803,7 @@ int main(int argc, char *argv[]) {
|
|||
else
|
||||
arg_delay += USEC_PER_SEC;
|
||||
|
||||
fprintf(stdout, "\nIncreased delay to %s.", format_timespan(h, sizeof(h), arg_delay));
|
||||
fprintf(stdout, "\nIncreased delay to %s.", format_timespan(h, sizeof(h), arg_delay, 0));
|
||||
fflush(stdout);
|
||||
sleep(1);
|
||||
break;
|
||||
|
@ -816,7 +816,7 @@ int main(int argc, char *argv[]) {
|
|||
else
|
||||
arg_delay -= USEC_PER_SEC;
|
||||
|
||||
fprintf(stdout, "\nDecreased delay to %s.", format_timespan(h, sizeof(h), arg_delay));
|
||||
fprintf(stdout, "\nDecreased delay to %s.", format_timespan(h, sizeof(h), arg_delay, 0));
|
||||
fflush(stdout);
|
||||
sleep(1);
|
||||
break;
|
||||
|
|
|
@ -1752,7 +1752,7 @@ int main(int argc, char *argv[]) {
|
|||
after_startup = now(CLOCK_MONOTONIC);
|
||||
log_full(arg_action == ACTION_TEST ? LOG_INFO : LOG_DEBUG,
|
||||
"Loaded units and determined initial transaction in %s.",
|
||||
format_timespan(timespan, sizeof(timespan), after_startup - before_startup));
|
||||
format_timespan(timespan, sizeof(timespan), after_startup - before_startup, 0));
|
||||
|
||||
if (arg_action == ACTION_TEST) {
|
||||
printf("-> By jobs:\n");
|
||||
|
|
|
@ -2415,10 +2415,10 @@ void manager_check_finished(Manager *m) {
|
|||
"INITRD_USEC=%llu", (unsigned long long) initrd_usec,
|
||||
"USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
|
||||
"MESSAGE=Startup finished in %s (kernel) + %s (initrd) + %s (userspace) = %s.",
|
||||
format_timespan(kernel, sizeof(kernel), kernel_usec),
|
||||
format_timespan(initrd, sizeof(initrd), initrd_usec),
|
||||
format_timespan(userspace, sizeof(userspace), userspace_usec),
|
||||
format_timespan(sum, sizeof(sum), total_usec),
|
||||
format_timespan(kernel, sizeof(kernel), kernel_usec, USEC_PER_MSEC),
|
||||
format_timespan(initrd, sizeof(initrd), initrd_usec, USEC_PER_MSEC),
|
||||
format_timespan(userspace, sizeof(userspace), userspace_usec, USEC_PER_MSEC),
|
||||
format_timespan(sum, sizeof(sum), total_usec, USEC_PER_MSEC),
|
||||
NULL);
|
||||
} else {
|
||||
kernel_usec = m->userspace_timestamp.monotonic - m->kernel_timestamp.monotonic;
|
||||
|
@ -2430,9 +2430,9 @@ void manager_check_finished(Manager *m) {
|
|||
"KERNEL_USEC=%llu", (unsigned long long) kernel_usec,
|
||||
"USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
|
||||
"MESSAGE=Startup finished in %s (kernel) + %s (userspace) = %s.",
|
||||
format_timespan(kernel, sizeof(kernel), kernel_usec),
|
||||
format_timespan(userspace, sizeof(userspace), userspace_usec),
|
||||
format_timespan(sum, sizeof(sum), total_usec),
|
||||
format_timespan(kernel, sizeof(kernel), kernel_usec, USEC_PER_MSEC),
|
||||
format_timespan(userspace, sizeof(userspace), userspace_usec, USEC_PER_MSEC),
|
||||
format_timespan(sum, sizeof(sum), total_usec, USEC_PER_MSEC),
|
||||
NULL);
|
||||
}
|
||||
} else {
|
||||
|
@ -2444,7 +2444,7 @@ void manager_check_finished(Manager *m) {
|
|||
MESSAGE_ID(SD_MESSAGE_STARTUP_FINISHED),
|
||||
"USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
|
||||
"MESSAGE=Startup finished in %s.",
|
||||
format_timespan(sum, sizeof(sum), total_usec),
|
||||
format_timespan(sum, sizeof(sum), total_usec, USEC_PER_MSEC),
|
||||
NULL);
|
||||
}
|
||||
|
||||
|
@ -2452,7 +2452,7 @@ void manager_check_finished(Manager *m) {
|
|||
|
||||
sd_notifyf(false,
|
||||
"READY=1\nSTATUS=Startup finished in %s.",
|
||||
format_timespan(sum, sizeof(sum), total_usec));
|
||||
format_timespan(sum, sizeof(sum), total_usec, USEC_PER_MSEC));
|
||||
}
|
||||
|
||||
static int create_generator_dir(Manager *m, char **generator, const char *name) {
|
||||
|
|
|
@ -423,7 +423,7 @@ int mount_setup(bool loaded_policy) {
|
|||
after_relabel = now(CLOCK_MONOTONIC);
|
||||
|
||||
log_info("Relabelled /dev and /run in %s.",
|
||||
format_timespan(timespan, sizeof(timespan), after_relabel - before_relabel));
|
||||
format_timespan(timespan, sizeof(timespan), after_relabel - before_relabel, 0));
|
||||
}
|
||||
|
||||
/* Create a few default symlinks, which are normally created
|
||||
|
|
|
@ -101,7 +101,7 @@ int selinux_setup(bool *loaded_policy) {
|
|||
after_load = now(CLOCK_MONOTONIC);
|
||||
|
||||
log_info("Successfully loaded SELinux policy in %s.",
|
||||
format_timespan(timespan, sizeof(timespan), after_load - before_load));
|
||||
format_timespan(timespan, sizeof(timespan), after_load - before_load, 0));
|
||||
|
||||
*loaded_policy = true;
|
||||
|
||||
|
|
|
@ -177,7 +177,7 @@ static void timer_dump(Unit *u, FILE *f, const char *prefix) {
|
|||
"%s%s: %s\n",
|
||||
prefix,
|
||||
timer_base_to_string(v->base),
|
||||
strna(format_timespan(timespan1, sizeof(timespan1), v->value)));
|
||||
strna(format_timespan(timespan1, sizeof(timespan1), v->value, 0)));
|
||||
}
|
||||
}
|
||||
}
|
||||
|
@ -330,7 +330,7 @@ static void timer_enter_waiting(Timer *t, bool initial) {
|
|||
log_debug_unit(UNIT(t)->id,
|
||||
"%s: Monotonic timer elapses in %s.",
|
||||
UNIT(t)->id,
|
||||
format_timespan(buf, sizeof(buf), t->next_elapse_monotonic > ts.monotonic ? t->next_elapse_monotonic - ts.monotonic : 0));
|
||||
format_timespan(buf, sizeof(buf), t->next_elapse_monotonic > ts.monotonic ? t->next_elapse_monotonic - ts.monotonic : 0, 0));
|
||||
|
||||
r = unit_watch_timer(UNIT(t), CLOCK_MONOTONIC, false, t->next_elapse_monotonic, &t->monotonic_watch);
|
||||
if (r < 0)
|
||||
|
|
|
@ -701,7 +701,7 @@ void unit_dump(Unit *u, FILE *f, const char *prefix) {
|
|||
fprintf(f, "%s\tDropIn Path: %s\n", prefix, *j);
|
||||
|
||||
if (u->job_timeout > 0)
|
||||
fprintf(f, "%s\tJob Timeout: %s\n", prefix, format_timespan(timespan, sizeof(timespan), u->job_timeout));
|
||||
fprintf(f, "%s\tJob Timeout: %s\n", prefix, format_timespan(timespan, sizeof(timespan), u->job_timeout, 0));
|
||||
|
||||
condition_dump_list(u->conditions, f, prefix);
|
||||
|
||||
|
|
|
@ -804,7 +804,7 @@ static int setup_keys(void) {
|
|||
fprintf(stderr,
|
||||
ANSI_HIGHLIGHT_OFF "\n"
|
||||
"The sealing key is automatically changed every %s.\n",
|
||||
format_timespan(tsb, sizeof(tsb), arg_interval));
|
||||
format_timespan(tsb, sizeof(tsb), arg_interval, 0));
|
||||
|
||||
hn = gethostname_malloc();
|
||||
|
||||
|
@ -878,10 +878,10 @@ static int verify(sd_journal *j) {
|
|||
log_info("=> Validated from %s to %s, final %s entries not sealed.",
|
||||
format_timestamp(a, sizeof(a), first),
|
||||
format_timestamp(b, sizeof(b), validated),
|
||||
format_timespan(c, sizeof(c), last > validated ? last - validated : 0));
|
||||
format_timespan(c, sizeof(c), last > validated ? last - validated : 0, 0));
|
||||
} else if (last > 0)
|
||||
log_info("=> No sealing yet, %s of entries not sealed.",
|
||||
format_timespan(c, sizeof(c), last - first));
|
||||
format_timespan(c, sizeof(c), last - first, 0));
|
||||
else
|
||||
log_info("=> No sealing yet, no entries in file.");
|
||||
}
|
||||
|
|
|
@ -117,7 +117,7 @@ int main(int argc, char *argv[]) {
|
|||
log_info("=> Validated from %s to %s, %s missing",
|
||||
format_timestamp(a, sizeof(a), from),
|
||||
format_timestamp(b, sizeof(b), to),
|
||||
format_timespan(c, sizeof(c), total > to ? total - to : 0));
|
||||
format_timespan(c, sizeof(c), total > to ? total - to : 0, 0));
|
||||
}
|
||||
|
||||
journal_file_close(f);
|
||||
|
|
|
@ -1097,7 +1097,7 @@ int generic_print_property(const char *name, DBusMessageIter *iter, bool all) {
|
|||
} else if (strstr(name, "USec")) {
|
||||
char timespan[FORMAT_TIMESPAN_MAX];
|
||||
|
||||
printf("%s=%s\n", name, format_timespan(timespan, sizeof(timespan), u));
|
||||
printf("%s=%s\n", name, format_timespan(timespan, sizeof(timespan), u, 0));
|
||||
} else
|
||||
printf("%s=%llu\n", name, (unsigned long long) u);
|
||||
|
||||
|
|
|
@ -82,7 +82,7 @@ int label_init(const char *prefix) {
|
|||
l = after_mallinfo.uordblks > before_mallinfo.uordblks ? after_mallinfo.uordblks - before_mallinfo.uordblks : 0;
|
||||
|
||||
log_debug("Successfully loaded SELinux database in %s, size on heap is %iK.",
|
||||
format_timespan(timespan, sizeof(timespan), after_timestamp - before_timestamp),
|
||||
format_timespan(timespan, sizeof(timespan), after_timestamp - before_timestamp, 0),
|
||||
(l+1023)/1024);
|
||||
}
|
||||
#endif
|
||||
|
|
|
@ -225,7 +225,7 @@ char *format_timestamp_relative(char *buf, size_t l, usec_t t) {
|
|||
return buf;
|
||||
}
|
||||
|
||||
char *format_timespan(char *buf, size_t l, usec_t t) {
|
||||
char *format_timespan(char *buf, size_t l, usec_t t, usec_t accuracy) {
|
||||
static const struct {
|
||||
const char *suffix;
|
||||
usec_t usec;
|
||||
|
@ -243,6 +243,7 @@ char *format_timespan(char *buf, size_t l, usec_t t) {
|
|||
|
||||
unsigned i;
|
||||
char *p = buf;
|
||||
bool something = false;
|
||||
|
||||
assert(buf);
|
||||
assert(l > 0);
|
||||
|
@ -250,17 +251,23 @@ char *format_timespan(char *buf, size_t l, usec_t t) {
|
|||
if (t == (usec_t) -1)
|
||||
return NULL;
|
||||
|
||||
if (t == 0) {
|
||||
snprintf(p, l, "0");
|
||||
p[l-1] = 0;
|
||||
return p;
|
||||
}
|
||||
|
||||
/* The result of this function can be parsed with parse_sec */
|
||||
|
||||
for (i = 0; i < ELEMENTSOF(table); i++) {
|
||||
int k;
|
||||
size_t n;
|
||||
bool done = false;
|
||||
usec_t a, b;
|
||||
|
||||
if (t == 0 || t < accuracy) {
|
||||
if (!something) {
|
||||
snprintf(p, l, "0");
|
||||
p[l-1] = 0;
|
||||
return p;
|
||||
}
|
||||
|
||||
break;
|
||||
}
|
||||
|
||||
if (t < table[i].usec)
|
||||
continue;
|
||||
|
@ -268,13 +275,55 @@ char *format_timespan(char *buf, size_t l, usec_t t) {
|
|||
if (l <= 1)
|
||||
break;
|
||||
|
||||
k = snprintf(p, l, "%s%llu%s", p > buf ? " " : "", (unsigned long long) (t / table[i].usec), table[i].suffix);
|
||||
a = t / table[i].usec;
|
||||
b = t % table[i].usec;
|
||||
|
||||
/* Let's see if we should shows this in dot notation */
|
||||
if (t < USEC_PER_MINUTE && b > 0) {
|
||||
usec_t cc;
|
||||
int j;
|
||||
|
||||
j = 0;
|
||||
for (cc = table[i].usec; cc > 1; cc /= 10)
|
||||
j++;
|
||||
|
||||
for (cc = accuracy; cc > 1; cc /= 10) {
|
||||
b /= 10;
|
||||
j--;
|
||||
}
|
||||
|
||||
if (j > 0) {
|
||||
k = snprintf(p, l,
|
||||
"%s%llu.%0*llu%s",
|
||||
p > buf ? " " : "",
|
||||
(unsigned long long) a,
|
||||
j,
|
||||
(unsigned long long) b,
|
||||
table[i].suffix);
|
||||
|
||||
t = 0;
|
||||
done = true;
|
||||
}
|
||||
}
|
||||
|
||||
/* No? Then let's show it normally */
|
||||
if (!done) {
|
||||
k = snprintf(p, l,
|
||||
"%s%llu%s",
|
||||
p > buf ? " " : "",
|
||||
(unsigned long long) a,
|
||||
table[i].suffix);
|
||||
|
||||
t = b;
|
||||
}
|
||||
|
||||
n = MIN((size_t) k, l);
|
||||
|
||||
l -= n;
|
||||
p += n;
|
||||
|
||||
t %= table[i].usec;
|
||||
|
||||
something = true;
|
||||
}
|
||||
|
||||
*p = 0;
|
||||
|
|
|
@ -74,7 +74,7 @@ struct timeval *timeval_store(struct timeval *tv, usec_t u);
|
|||
|
||||
char *format_timestamp(char *buf, size_t l, usec_t t);
|
||||
char *format_timestamp_relative(char *buf, size_t l, usec_t t);
|
||||
char *format_timespan(char *buf, size_t l, usec_t t);
|
||||
char *format_timespan(char *buf, size_t l, usec_t t, usec_t accuracy);
|
||||
|
||||
void dual_timestamp_serialize(FILE *f, const char *name, dual_timestamp *t);
|
||||
void dual_timestamp_deserialize(const char *value, dual_timestamp *t);
|
||||
|
|
|
@ -60,7 +60,7 @@ static int update_timeout(void) {
|
|||
}
|
||||
|
||||
watchdog_timeout = (usec_t) sec * USEC_PER_SEC;
|
||||
log_info("Set hardware watchdog to %s.", format_timespan(buf, sizeof(buf), watchdog_timeout));
|
||||
log_info("Set hardware watchdog to %s.", format_timespan(buf, sizeof(buf), watchdog_timeout, 0));
|
||||
|
||||
flags = WDIOS_ENABLECARD;
|
||||
r = ioctl(watchdog_fd, WDIOC_SETOPTIONS, &flags);
|
||||
|
|
|
@ -2944,8 +2944,8 @@ static int print_property(const char *name, DBusMessageIter *iter) {
|
|||
|
||||
printf("%s={ value=%s ; next_elapse=%s }\n",
|
||||
base,
|
||||
format_timespan(timespan1, sizeof(timespan1), value),
|
||||
format_timespan(timespan2, sizeof(timespan2), next_elapse));
|
||||
format_timespan(timespan1, sizeof(timespan1), value, 0),
|
||||
format_timespan(timespan2, sizeof(timespan2), next_elapse, 0));
|
||||
}
|
||||
|
||||
dbus_message_iter_next(&sub);
|
||||
|
|
|
@ -36,8 +36,8 @@ int main(int argc, char* argv[]) {
|
|||
return 1;
|
||||
}
|
||||
|
||||
log_info("Firmware began %s before kernel.", format_timespan(s, sizeof(s), fw.monotonic));
|
||||
log_info("Loader began %s before kernel.", format_timespan(s, sizeof(s), l.monotonic));
|
||||
log_info("Firmware began %s before kernel.", format_timespan(s, sizeof(s), fw.monotonic, 0));
|
||||
log_info("Loader began %s before kernel.", format_timespan(s, sizeof(s), l.monotonic, 0));
|
||||
|
||||
log_info("Firmware began %s.", format_timestamp(s, sizeof(s), fw.realtime));
|
||||
log_info("Loader began %s.", format_timestamp(s, sizeof(s), l.realtime));
|
||||
|
|
|
@ -79,8 +79,58 @@ static void test_parse_nsec(void) {
|
|||
assert_se(parse_nsec(".s ", &u) < 0);
|
||||
}
|
||||
|
||||
static void test_format_timespan_one(usec_t x, usec_t accuracy) {
|
||||
char *r;
|
||||
char l[FORMAT_TIMESPAN_MAX];
|
||||
usec_t y;
|
||||
|
||||
log_info("%llu (at accuracy %llu)", (unsigned long long) x, (unsigned long long) accuracy);
|
||||
|
||||
r = format_timespan(l, sizeof(l), x, accuracy);
|
||||
assert_se(r);
|
||||
|
||||
log_info(" = <%s>", l);
|
||||
|
||||
assert_se(parse_sec(l, &y) >= 0);
|
||||
|
||||
log_info(" = %llu", (unsigned long long) y);
|
||||
|
||||
if (accuracy <= 0)
|
||||
accuracy = 1;
|
||||
|
||||
assert_se(x / accuracy == y / accuracy);
|
||||
}
|
||||
|
||||
static void test_format_timespan(usec_t accuracy) {
|
||||
test_format_timespan_one(0, accuracy);
|
||||
test_format_timespan_one(1, accuracy);
|
||||
test_format_timespan_one(1*USEC_PER_SEC, accuracy);
|
||||
test_format_timespan_one(999*USEC_PER_MSEC, accuracy);
|
||||
test_format_timespan_one(1234567, accuracy);
|
||||
test_format_timespan_one(12, accuracy);
|
||||
test_format_timespan_one(123, accuracy);
|
||||
test_format_timespan_one(1234, accuracy);
|
||||
test_format_timespan_one(12345, accuracy);
|
||||
test_format_timespan_one(123456, accuracy);
|
||||
test_format_timespan_one(1234567, accuracy);
|
||||
test_format_timespan_one(12345678, accuracy);
|
||||
test_format_timespan_one(1200000, accuracy);
|
||||
test_format_timespan_one(1230000, accuracy);
|
||||
test_format_timespan_one(1230000, accuracy);
|
||||
test_format_timespan_one(1234000, accuracy);
|
||||
test_format_timespan_one(1234500, accuracy);
|
||||
test_format_timespan_one(1234560, accuracy);
|
||||
test_format_timespan_one(1234567, accuracy);
|
||||
test_format_timespan_one(986087, accuracy);
|
||||
test_format_timespan_one(500 * USEC_PER_MSEC, accuracy);
|
||||
test_format_timespan_one(9*USEC_PER_YEAR/5 - 23, accuracy);
|
||||
}
|
||||
|
||||
int main(int argc, char *argv[]) {
|
||||
test_parse_sec();
|
||||
test_parse_nsec();
|
||||
test_format_timespan(1);
|
||||
test_format_timespan(USEC_PER_MSEC);
|
||||
test_format_timespan(USEC_PER_SEC);
|
||||
return 0;
|
||||
}
|
||||
|
|
Loading…
Reference in New Issue