* [Virtio-fs] debug log timestamp idea
@ 2020-12-07 17:39 Laszlo Ersek
2020-12-07 18:33 ` Dr. David Alan Gilbert
0 siblings, 1 reply; 3+ messages in thread
From: Laszlo Ersek @ 2020-12-07 17:39 UTC (permalink / raw)
To: Miklos Szeredi; +Cc: virtio-fs
Hi again :)
I find the current debug log hard to associate with actions I perform in
the client; primarily because the timestamps are not human-readable, and
so I can't easily notice time boundaries between actions.
For comparison:
[2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Got queue event on Queue 1
[2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Queue 1 gave evalue: 1 available: in: 16 out: 64
[2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Waiting for Queue 1 event
[2020-12-07 18:11:35.51+0100] [ID: 00000006] fv_queue_worker: elem 0: with 2 out desc of length 64
[2020-12-07 18:11:35.51+0100] [ID: 00000006] unique: 108, opcode: RELEASEDIR (29), nodeid: 1, insize: 64, pid: 1
[2020-12-07 18:11:35.51+0100] [ID: 00000006] unique: 108, success, outsize: 16
[2020-12-07 18:11:35.51+0100] [ID: 00000006] virtio_send_msg: elem 0: with 1 in desc of length 16
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] fv_queue_set_started: qidx=1 started=0
[2020-12-07 18:17:54.82+0100] [ID: 00000003] fv_queue_thread: kill event on queue 1 - quitting
[2020-12-07 18:17:54.82+0100] [ID: 00000001] fv_remove_watch: TODO! fd=9
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
[2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
[2020-12-07 18:17:54.85+0100] [ID: 00000001] virtio_loop: Unexpected poll revents 11
[2020-12-07 18:17:54.85+0100] [ID: 00000001] virtio_loop: Exit
I think this is nicer; note the clear visual jump between "18:11:35" and
"18:17:54"
The patch:
> diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
> index 0e4c7ddce0a8..5522f96d33d0 100644
> --- a/tools/virtiofsd/passthrough_ll.c
> +++ b/tools/virtiofsd/passthrough_ll.c
> @@ -3302,9 +3302,19 @@ static void log_func(enum fuse_log_level level, const char *fmt, va_list ap)
> }
>
> if (current_log_level == FUSE_LOG_DEBUG) {
> - if (!use_syslog) {
> - localfmt = g_strdup_printf("[%" PRId64 "] [ID: %08ld] %s",
> - get_clock(), syscall(__NR_gettid), fmt);
> + struct timespec ts;
> + if (!use_syslog && clock_gettime (CLOCK_REALTIME, &ts) == 0) {
> + struct tm tm;
> + char sec_fmt[20];
> + char zone_fmt[6];
> +
> + localtime_r(&ts.tv_sec, &tm);
> + strftime(sec_fmt, sizeof sec_fmt, "%Y-%m-%d %H:%M:%S", &tm);
> + strftime(zone_fmt, sizeof zone_fmt, "%z", &tm);
> +
> + 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 {
> localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid),
> fmt);
> @@ -3428,6 +3438,8 @@ int main(int argc, char *argv[])
> struct lo_map_elem *reserve_elem;
> int ret = -1;
>
> + tzset();
> +
> /* Don't mask creation mode, kernel already did that */
> umask(0);
The patch probably violates a bunch of QEMU standards (such as referring
to CLOCK_REALTIME, using localtime_r() which may not be available on
Windows (?), etc). I'm OK to carry it myself for debugging, I just
thought I'd ask for opinions.
Thanks
Laszlo
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [Virtio-fs] debug log timestamp idea
2020-12-07 17:39 [Virtio-fs] debug log timestamp idea Laszlo Ersek
@ 2020-12-07 18:33 ` Dr. David Alan Gilbert
2020-12-08 2:19 ` Laszlo Ersek
0 siblings, 1 reply; 3+ messages in thread
From: Dr. David Alan Gilbert @ 2020-12-07 18:33 UTC (permalink / raw)
To: Laszlo Ersek; +Cc: virtio-fs
* Laszlo Ersek (lersek@redhat.com) wrote:
> Hi again :)
>
> I find the current debug log hard to associate with actions I perform in
> the client; primarily because the timestamps are not human-readable, and
> so I can't easily notice time boundaries between actions.
>
> For comparison:
>
> [2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Got queue event on Queue 1
> [2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Queue 1 gave evalue: 1 available: in: 16 out: 64
> [2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Waiting for Queue 1 event
> [2020-12-07 18:11:35.51+0100] [ID: 00000006] fv_queue_worker: elem 0: with 2 out desc of length 64
> [2020-12-07 18:11:35.51+0100] [ID: 00000006] unique: 108, opcode: RELEASEDIR (29), nodeid: 1, insize: 64, pid: 1
> [2020-12-07 18:11:35.51+0100] [ID: 00000006] unique: 108, success, outsize: 16
> [2020-12-07 18:11:35.51+0100] [ID: 00000006] virtio_send_msg: elem 0: with 1 in desc of length 16
> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
> [2020-12-07 18:17:54.82+0100] [ID: 00000001] fv_queue_set_started: qidx=1 started=0
> [2020-12-07 18:17:54.82+0100] [ID: 00000003] fv_queue_thread: kill event on queue 1 - quitting
> [2020-12-07 18:17:54.82+0100] [ID: 00000001] fv_remove_watch: TODO! fd=9
> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
> [2020-12-07 18:17:54.85+0100] [ID: 00000001] virtio_loop: Unexpected poll revents 11
> [2020-12-07 18:17:54.85+0100] [ID: 00000001] virtio_loop: Exit
So, you don't think in Unix time, hmmmmm....
> I think this is nicer; note the clear visual jump between "18:11:35" and
> "18:17:54"
>
> The patch:
>
> > diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
> > index 0e4c7ddce0a8..5522f96d33d0 100644
> > --- a/tools/virtiofsd/passthrough_ll.c
> > +++ b/tools/virtiofsd/passthrough_ll.c
> > @@ -3302,9 +3302,19 @@ static void log_func(enum fuse_log_level level, const char *fmt, va_list ap)
> > }
> >
> > if (current_log_level == FUSE_LOG_DEBUG) {
> > - if (!use_syslog) {
> > - localfmt = g_strdup_printf("[%" PRId64 "] [ID: %08ld] %s",
> > - get_clock(), syscall(__NR_gettid), fmt);
> > + struct timespec ts;
> > + if (!use_syslog && clock_gettime (CLOCK_REALTIME, &ts) == 0) {
> > + struct tm tm;
> > + char sec_fmt[20];
Are you sure that shouldn't be 21?
> > + char zone_fmt[6];
> > +
> > + localtime_r(&ts.tv_sec, &tm);
> > + strftime(sec_fmt, sizeof sec_fmt, "%Y-%m-%d %H:%M:%S", &tm);
> > + strftime(zone_fmt, sizeof zone_fmt, "%z", &tm);
> > +
> > + localfmt = g_strdup_printf("[%s.%02ld%s] [ID: %08ld] %s", sec_fmt,
> > + ts.tv_nsec / (10L * 1000 * 1000),
> > + zone_fmt, syscall(__NR_gettid), fmt);
I wonder about using:
https://developer.gnome.org/glib/stable/glib-GDateTime.html#g-date-time-format-iso8601
instead?
> > } else {
> > localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid),
> > fmt);
> > @@ -3428,6 +3438,8 @@ int main(int argc, char *argv[])
> > struct lo_map_elem *reserve_elem;
> > int ret = -1;
> >
> > + tzset();
> > +
> > /* Don't mask creation mode, kernel already did that */
> > umask(0);
>
> The patch probably violates a bunch of QEMU standards (such as referring
> to CLOCK_REALTIME, using localtime_r() which may not be available on
> Windows (?), etc). I'm OK to carry it myself for debugging, I just
> thought I'd ask for opinions.
I don't think any of those things are problems to stop a patch going in
- virtiofsd is only built on Linux (I think) - if you send a patch that
passes qemu's scripts/checkpatch.pl or has a reasonable reason why not
then I'd be fine with that.
Dave
> Thanks
> Laszlo
>
> _______________________________________________
> Virtio-fs mailing list
> Virtio-fs@redhat.com
> https://www.redhat.com/mailman/listinfo/virtio-fs
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [Virtio-fs] debug log timestamp idea
2020-12-07 18:33 ` Dr. David Alan Gilbert
@ 2020-12-08 2:19 ` Laszlo Ersek
0 siblings, 0 replies; 3+ messages in thread
From: Laszlo Ersek @ 2020-12-08 2:19 UTC (permalink / raw)
To: Dr. David Alan Gilbert; +Cc: virtio-fs
On 12/07/20 19:33, Dr. David Alan Gilbert wrote:
> * Laszlo Ersek (lersek@redhat.com) wrote:
>> Hi again :)
>>
>> I find the current debug log hard to associate with actions I perform in
>> the client; primarily because the timestamps are not human-readable, and
>> so I can't easily notice time boundaries between actions.
>>
>> For comparison:
>>
>> [2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Got queue event on Queue 1
>> [2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Queue 1 gave evalue: 1 available: in: 16 out: 64
>> [2020-12-07 18:11:35.51+0100] [ID: 00000003] fv_queue_thread: Waiting for Queue 1 event
>> [2020-12-07 18:11:35.51+0100] [ID: 00000006] fv_queue_worker: elem 0: with 2 out desc of length 64
>> [2020-12-07 18:11:35.51+0100] [ID: 00000006] unique: 108, opcode: RELEASEDIR (29), nodeid: 1, insize: 64, pid: 1
>> [2020-12-07 18:11:35.51+0100] [ID: 00000006] unique: 108, success, outsize: 16
>> [2020-12-07 18:11:35.51+0100] [ID: 00000006] virtio_send_msg: elem 0: with 1 in desc of length 16
>> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
>> [2020-12-07 18:17:54.82+0100] [ID: 00000001] fv_queue_set_started: qidx=1 started=0
>> [2020-12-07 18:17:54.82+0100] [ID: 00000003] fv_queue_thread: kill event on queue 1 - quitting
>> [2020-12-07 18:17:54.82+0100] [ID: 00000001] fv_remove_watch: TODO! fd=9
>> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
>> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
>> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
>> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Got VU event
>> [2020-12-07 18:17:54.82+0100] [ID: 00000001] virtio_loop: Waiting for VU event
>> [2020-12-07 18:17:54.85+0100] [ID: 00000001] virtio_loop: Unexpected poll revents 11
>> [2020-12-07 18:17:54.85+0100] [ID: 00000001] virtio_loop: Exit
>
> So, you don't think in Unix time, hmmmmm....
At least not in nanosecond precision :)
>
>> I think this is nicer; note the clear visual jump between "18:11:35" and
>> "18:17:54"
>>
>> The patch:
>>
>>> diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
>>> index 0e4c7ddce0a8..5522f96d33d0 100644
>>> --- a/tools/virtiofsd/passthrough_ll.c
>>> +++ b/tools/virtiofsd/passthrough_ll.c
>>> @@ -3302,9 +3302,19 @@ static void log_func(enum fuse_log_level level, const char *fmt, va_list ap)
>>> }
>>>
>>> if (current_log_level == FUSE_LOG_DEBUG) {
>>> - if (!use_syslog) {
>>> - localfmt = g_strdup_printf("[%" PRId64 "] [ID: %08ld] %s",
>>> - get_clock(), syscall(__NR_gettid), fmt);
>>> + struct timespec ts;
>>> + if (!use_syslog && clock_gettime (CLOCK_REALTIME, &ts) == 0) {
>>> + struct tm tm;
>>> + char sec_fmt[20];
>
> Are you sure that shouldn't be 21?
Yes, sure:
$ wc -L <<< "2020-12-07 18:17:54"
19
(But it would be more defensive to check the return value of strftime(),
yes.)
>
>>> + char zone_fmt[6];
>>> +
>>> + localtime_r(&ts.tv_sec, &tm);
>>> + strftime(sec_fmt, sizeof sec_fmt, "%Y-%m-%d %H:%M:%S", &tm);
>>> + strftime(zone_fmt, sizeof zone_fmt, "%z", &tm);
>>> +
>>> + localfmt = g_strdup_printf("[%s.%02ld%s] [ID: %08ld] %s", sec_fmt,
>>> + ts.tv_nsec / (10L * 1000 * 1000),
>>> + zone_fmt, syscall(__NR_gettid), fmt);
>
> I wonder about using:
> https://developer.gnome.org/glib/stable/glib-GDateTime.html#g-date-time-format-iso8601
>
> instead?
I've known of that format; I just can't befriend the capital T stuck in
the middle. Makes for a difficult reading:
https://en.wikipedia.org/wiki/ISO_8601#Combined_date_and_time_representations
"2007-04-05T14:30"
Well, wikipedia says, "Separating date and time parts with other
characters such as space is not allowed in ISO 8601, but allowed in its
profile RFC 3339".
Hmm.... yes it seems mentioned at the end of this paragraph:
<https://tools.ietf.org/html/rfc3339#section-5.6>:
NOTE: ISO 8601 defines date and time separated by "T".
Applications using this syntax may choose, for the sake of
readability, to specify a full-date and full-time separated by
(say) a space character.
I'm glad I'm not alone with the opinion that the "T" makes for a hard
reading.
Not sure if g_date_time_format_iso8601() supports RFC 3339 though.
>
>>> } else {
>>> localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid),
>>> fmt);
>>> @@ -3428,6 +3438,8 @@ int main(int argc, char *argv[])
>>> struct lo_map_elem *reserve_elem;
>>> int ret = -1;
>>>
>>> + tzset();
>>> +
>>> /* Don't mask creation mode, kernel already did that */
>>> umask(0);
>>
>> The patch probably violates a bunch of QEMU standards (such as referring
>> to CLOCK_REALTIME, using localtime_r() which may not be available on
>> Windows (?), etc). I'm OK to carry it myself for debugging, I just
>> thought I'd ask for opinions.
>
> I don't think any of those things are problems to stop a patch going in
> - virtiofsd is only built on Linux (I think) - if you send a patch that
> passes qemu's scripts/checkpatch.pl or has a reasonable reason why not
> then I'd be fine with that.
Should virtiofsd patches be cross-posted to this list and qemu-devel, or
posted just to this list (and then a maintainer submits a pull request
to qemu-devel later)?
Thanks!
Laszlo
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2020-12-08 2:19 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-12-07 17:39 [Virtio-fs] debug log timestamp idea Laszlo Ersek
2020-12-07 18:33 ` Dr. David Alan Gilbert
2020-12-08 2:19 ` Laszlo Ersek
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.