* [PATCH] virtiofsd: make the debug log timestamp on stderr more human-readable
@ 2020-12-08 5:50 ` Laszlo Ersek
0 siblings, 0 replies; 6+ messages in thread
From: Laszlo Ersek @ 2020-12-08 5:50 UTC (permalink / raw)
To: qemu-devel, virtio-fs; +Cc: Dr. David Alan Gilbert, Stefan Hajnoczi
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>
---
tools/virtiofsd/passthrough_ll.c | 31 +++++++++++++++++++++++++++----
1 file changed, 27 insertions(+), 4 deletions(-)
diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
index 48a109d3f682..06543b20dcbb 100644
--- a/tools/virtiofsd/passthrough_ll.c
+++ b/tools/virtiofsd/passthrough_ll.c
@@ -3311,18 +3311,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;
}
@@ -3452,6 +3472,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);
--
2.19.1.3.g30247aa5d201
^ permalink raw reply related [flat|nested] 6+ messages in thread
* [Virtio-fs] [PATCH] virtiofsd: make the debug log timestamp on stderr more human-readable
@ 2020-12-08 5:50 ` Laszlo Ersek
0 siblings, 0 replies; 6+ messages in thread
From: Laszlo Ersek @ 2020-12-08 5:50 UTC (permalink / raw)
To: qemu-devel, virtio-fs
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>
---
tools/virtiofsd/passthrough_ll.c | 31 +++++++++++++++++++++++++++----
1 file changed, 27 insertions(+), 4 deletions(-)
diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
index 48a109d3f682..06543b20dcbb 100644
--- a/tools/virtiofsd/passthrough_ll.c
+++ b/tools/virtiofsd/passthrough_ll.c
@@ -3311,18 +3311,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;
}
@@ -3452,6 +3472,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);
--
2.19.1.3.g30247aa5d201
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [Virtio-fs] [PATCH] virtiofsd: make the debug log timestamp on stderr more human-readable
2020-12-08 5:50 ` [Virtio-fs] " Laszlo Ersek
(?)
@ 2020-12-08 16:57 ` Vivek Goyal
2020-12-10 7:55 ` Laszlo Ersek
-1 siblings, 1 reply; 6+ messages in thread
From: Vivek Goyal @ 2020-12-08 16:57 UTC (permalink / raw)
To: Laszlo Ersek; +Cc: virtio-fs, qemu-devel
On Tue, Dec 08, 2020 at 06:50:43AM +0100, Laszlo Ersek wrote:
> 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.
Switching to a human readable time stamp makes sense. That seems much
more helpful for debugging, IMHO.
Thanks
Vivek
>
> 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>
> ---
> tools/virtiofsd/passthrough_ll.c | 31 +++++++++++++++++++++++++++----
> 1 file changed, 27 insertions(+), 4 deletions(-)
>
> diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
> index 48a109d3f682..06543b20dcbb 100644
> --- a/tools/virtiofsd/passthrough_ll.c
> +++ b/tools/virtiofsd/passthrough_ll.c
> @@ -3311,18 +3311,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;
> }
> @@ -3452,6 +3472,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);
>
> --
> 2.19.1.3.g30247aa5d201
>
> _______________________________________________
> Virtio-fs mailing list
> Virtio-fs@redhat.com
> https://www.redhat.com/mailman/listinfo/virtio-fs
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Virtio-fs] [PATCH] virtiofsd: make the debug log timestamp on stderr more human-readable
2020-12-08 16:57 ` Vivek Goyal
@ 2020-12-10 7:55 ` Laszlo Ersek
0 siblings, 0 replies; 6+ messages in thread
From: Laszlo Ersek @ 2020-12-10 7:55 UTC (permalink / raw)
To: Vivek Goyal; +Cc: virtio-fs, qemu-devel
On 12/08/20 17:57, Vivek Goyal wrote:
> On Tue, Dec 08, 2020 at 06:50:43AM +0100, Laszlo Ersek wrote:
>> 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.
>
> Switching to a human readable time stamp makes sense. That seems much
> more helpful for debugging, IMHO.
Thanks! (for the other review as well)
laszlo
>
> Thanks
> Vivek
>
>>
>> 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>
>> ---
>> tools/virtiofsd/passthrough_ll.c | 31 +++++++++++++++++++++++++++----
>> 1 file changed, 27 insertions(+), 4 deletions(-)
>>
>> diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
>> index 48a109d3f682..06543b20dcbb 100644
>> --- a/tools/virtiofsd/passthrough_ll.c
>> +++ b/tools/virtiofsd/passthrough_ll.c
>> @@ -3311,18 +3311,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;
>> }
>> @@ -3452,6 +3472,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);
>>
>> --
>> 2.19.1.3.g30247aa5d201
>>
>> _______________________________________________
>> Virtio-fs mailing list
>> Virtio-fs@redhat.com
>> https://www.redhat.com/mailman/listinfo/virtio-fs
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH] virtiofsd: make the debug log timestamp on stderr more human-readable
2020-12-08 5:50 ` [Virtio-fs] " Laszlo Ersek
@ 2020-12-10 12:23 ` Dr. David Alan Gilbert
-1 siblings, 0 replies; 6+ messages in thread
From: Dr. David Alan Gilbert @ 2020-12-10 12:23 UTC (permalink / raw)
To: Laszlo Ersek; +Cc: virtio-fs, qemu-devel, Stefan Hajnoczi
* Laszlo Ersek (lersek@redhat.com) wrote:
> 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>
(I'd have probably not bothered with the day and given a few more digits
of the subseconds instead, but that's mostly just rpeference)
Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
and queued.
> ---
> tools/virtiofsd/passthrough_ll.c | 31 +++++++++++++++++++++++++++----
> 1 file changed, 27 insertions(+), 4 deletions(-)
>
> diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
> index 48a109d3f682..06543b20dcbb 100644
> --- a/tools/virtiofsd/passthrough_ll.c
> +++ b/tools/virtiofsd/passthrough_ll.c
> @@ -3311,18 +3311,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;
> }
> @@ -3452,6 +3472,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);
>
> --
> 2.19.1.3.g30247aa5d201
>
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [Virtio-fs] [PATCH] virtiofsd: make the debug log timestamp on stderr more human-readable
@ 2020-12-10 12:23 ` Dr. David Alan Gilbert
0 siblings, 0 replies; 6+ messages in thread
From: Dr. David Alan Gilbert @ 2020-12-10 12:23 UTC (permalink / raw)
To: Laszlo Ersek; +Cc: virtio-fs, qemu-devel
* Laszlo Ersek (lersek@redhat.com) wrote:
> 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>
(I'd have probably not bothered with the day and given a few more digits
of the subseconds instead, but that's mostly just rpeference)
Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
and queued.
> ---
> tools/virtiofsd/passthrough_ll.c | 31 +++++++++++++++++++++++++++----
> 1 file changed, 27 insertions(+), 4 deletions(-)
>
> diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
> index 48a109d3f682..06543b20dcbb 100644
> --- a/tools/virtiofsd/passthrough_ll.c
> +++ b/tools/virtiofsd/passthrough_ll.c
> @@ -3311,18 +3311,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;
> }
> @@ -3452,6 +3472,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);
>
> --
> 2.19.1.3.g30247aa5d201
>
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2020-12-10 13:01 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-12-08 5:50 [PATCH] virtiofsd: make the debug log timestamp on stderr more human-readable Laszlo Ersek
2020-12-08 5:50 ` [Virtio-fs] " Laszlo Ersek
2020-12-08 16:57 ` Vivek Goyal
2020-12-10 7:55 ` Laszlo Ersek
2020-12-10 12:23 ` Dr. David Alan Gilbert
2020-12-10 12:23 ` [Virtio-fs] " Dr. David Alan Gilbert
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.