OpenE2K/qemu-e2k
13
4
Fork 0
Code Issues 4 Pull Requests Projects 2 Releases Activity

virtiofsd: make the debug log timestamp on stderr more human-readable

Browse Source 
The current timestamp format doesn't help me visually notice small jumps
in time ("small" as defined on human scale, such as a few seconds or a few
ten seconds). Replace it with a local time format where such differences
stand out.

Before:

> [13316826770337] [ID: 00000004] unique: 62, opcode: RELEASEDIR (29), nodeid: 1, insize: 64, pid: 1
> [13316826778175] [ID: 00000004]    unique: 62, success, outsize: 16
> [13316826781156] [ID: 00000004] virtio_send_msg: elem 0: with 1 in desc of length 16
> [15138279317927] [ID: 00000001] virtio_loop: Got VU event
> [15138279504884] [ID: 00000001] fv_queue_set_started: qidx=1 started=0
> [15138279519034] [ID: 00000003] fv_queue_thread: kill event on queue 1 - quitting
> [15138280876463] [ID: 00000001] fv_remove_watch: TODO! fd=9
> [15138280897381] [ID: 00000001] virtio_loop: Waiting for VU event
> [15138280946834] [ID: 00000001] virtio_loop: Got VU event
> [15138281175421] [ID: 00000001] virtio_loop: Waiting for VU event
> [15138281182387] [ID: 00000001] virtio_loop: Got VU event
> [15138281189474] [ID: 00000001] virtio_loop: Waiting for VU event
> [15138309321936] [ID: 00000001] virtio_loop: Unexpected poll revents 11
> [15138309434150] [ID: 00000001] virtio_loop: Exit

(Notice how you don't (easily) notice the gap in time after
"virtio_send_msg", and especially the amount of time passed is hard to
estimate.)

After:

> [2020-12-08 06:43:22.58+0100] [ID: 00000004] unique: 51, opcode: RELEASEDIR (29), nodeid: 1, insize: 64, pid: 1
> [2020-12-08 06:43:22.58+0100] [ID: 00000004]    unique: 51, success, outsize: 16
> [2020-12-08 06:43:22.58+0100] [ID: 00000004] virtio_send_msg: elem 0: with 1 in desc of length 16
> [2020-12-08 06:43:29.34+0100] [ID: 00000001] virtio_loop: Got VU event
> [2020-12-08 06:43:29.34+0100] [ID: 00000001] fv_queue_set_started: qidx=1 started=0
> [2020-12-08 06:43:29.34+0100] [ID: 00000003] fv_queue_thread: kill event on queue 1 - quitting
> [2020-12-08 06:43:29.34+0100] [ID: 00000001] fv_remove_watch: TODO! fd=9
> [2020-12-08 06:43:29.34+0100] [ID: 00000001] virtio_loop: Waiting for VU event
> [2020-12-08 06:43:29.34+0100] [ID: 00000001] virtio_loop: Got VU event
> [2020-12-08 06:43:29.34+0100] [ID: 00000001] virtio_loop: Waiting for VU event
> [2020-12-08 06:43:29.34+0100] [ID: 00000001] virtio_loop: Got VU event
> [2020-12-08 06:43:29.34+0100] [ID: 00000001] virtio_loop: Waiting for VU event
> [2020-12-08 06:43:29.37+0100] [ID: 00000001] virtio_loop: Unexpected poll revents 11
> [2020-12-08 06:43:29.37+0100] [ID: 00000001] virtio_loop: Exit

Cc: "Dr. David Alan Gilbert" <dgilbert@redhat.com>
Cc: Stefan Hajnoczi <stefanha@redhat.com>
Signed-off-by: Laszlo Ersek <lersek@redhat.com>
Message-Id: <20201208055043.31548-1-lersek@redhat.com>
Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
Signed-off-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
This commit is contained in:
Laszlo Ersek 2020-12-08 06:50:43 +01:00 committed by Dr. David Alan Gilbert
parent e49393a349
commit bebc3c24aa
1 changed files with 27 additions and 4 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

31
tools/virtiofsd/passthrough_ll.c
View File

@ -3284,18 +3284,38 @@ static void setup_nofile_rlimit(unsigned long rlimit_nofile)
static void log_func(enum fuse_log_level level, const char *fmt, va_list ap)
{
g_autofree char *localfmt = NULL;
struct timespec ts;
struct tm tm;
char sec_fmt[sizeof "2020-12-07 18:17:54"];
char zone_fmt[sizeof "+0100"];
if (current_log_level < level) {
return;
}
if (current_log_level == FUSE_LOG_DEBUG) {
if (!use_syslog) {
localfmt = g_strdup_printf("[%" PRId64 "] [ID: %08ld] %s",
get_clock(), syscall(__NR_gettid), fmt);
} else {
if (use_syslog) {
/* no timestamp needed */
localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid),
fmt);
} else {
/* try formatting a broken-down timestamp */
if (clock_gettime(CLOCK_REALTIME, &ts) != -1 &&
localtime_r(&ts.tv_sec, &tm) != NULL &&
strftime(sec_fmt, sizeof sec_fmt, "%Y-%m-%d %H:%M:%S",
&tm) != 0 &&
strftime(zone_fmt, sizeof zone_fmt, "%z", &tm) != 0) {
localfmt = g_strdup_printf("[%s.%02ld%s] [ID: %08ld] %s",
sec_fmt,
ts.tv_nsec / (10L * 1000 * 1000),
zone_fmt, syscall(__NR_gettid),
fmt);
} else {
/* fall back to a flat timestamp */
localfmt = g_strdup_printf("[%" PRId64 "] [ID: %08ld] %s",
get_clock(), syscall(__NR_gettid),
fmt);
}
}
fmt = localfmt;
}
@ -3416,6 +3436,9 @@ int main(int argc, char *argv[])
struct lo_map_elem *reserve_elem;
int ret = -1;
/* Initialize time conversion information for localtime_r(). */
tzset();
/* Don't mask creation mode, kernel already did that */
umask(0);