* [Virtio-fs] [PATCH 0/2] Add ID and timestamp to the log with FUSE_LOG_DEBUG level
@ 2019-11-06 19:06 Masayoshi Mizuma
2019-11-06 19:06 ` [Virtio-fs] [PATCH 1/2] virtiofsd: Add ID " Masayoshi Mizuma
2019-11-06 19:06 ` [Virtio-fs] [PATCH 2/2] virtiofsd: Add timestamp " Masayoshi Mizuma
0 siblings, 2 replies; 5+ messages in thread
From: Masayoshi Mizuma @ 2019-11-06 19:06 UTC (permalink / raw)
To: virtio-fs; +Cc: Masayoshi Mizuma
From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
For debugging purpose, this patch series add ID to specify the thread
and timestamp to check the time delta for each events.
Masayoshi Mizuma (2):
virtiofsd: Add ID to the log with FUSE_LOG_DEBUG level
virtiofsd: Add timestamp to the log with FUSE_LOG_DEBUG level
contrib/virtiofsd/passthrough_ll.c | 18 +++++++++++++++++-
1 file changed, 17 insertions(+), 1 deletion(-)
--
2.18.1
^ permalink raw reply [flat|nested] 5+ messages in thread
* [Virtio-fs] [PATCH 1/2] virtiofsd: Add ID to the log with FUSE_LOG_DEBUG level
2019-11-06 19:06 [Virtio-fs] [PATCH 0/2] Add ID and timestamp to the log with FUSE_LOG_DEBUG level Masayoshi Mizuma
@ 2019-11-06 19:06 ` Masayoshi Mizuma
2019-11-07 10:46 ` Dr. David Alan Gilbert
2019-11-06 19:06 ` [Virtio-fs] [PATCH 2/2] virtiofsd: Add timestamp " Masayoshi Mizuma
1 sibling, 1 reply; 5+ messages in thread
From: Masayoshi Mizuma @ 2019-11-06 19:06 UTC (permalink / raw)
To: virtio-fs; +Cc: Masayoshi Mizuma
From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
virtiofsd has some threads, so we see a lot of logs with debug option.
It would be useful for debugging if we can identify the specific thread
from the log.
Add ID, which is got by gettid(), to the log with FUSE_LOG_DEBUG level
so that we can grep the specific thread.
The log is like as:
]# ./virtiofsd -d -o vhost_user_socket=/tmp/vhostqemu0 -o source=/tmp/share0 -o cache=auto
...
[ID: 00000097] unique: 12696, success, outsize: 120
[ID: 00000097] virtio_send_msg: elem 18: with 2 in desc of length 120
[ID: 00000003] fv_queue_thread: Got queue event on Queue 1
[ID: 00000003] fv_queue_thread: Queue 1 gave evalue: 1 available: in: 65552 out: 80
[ID: 00000003] fv_queue_thread: Waiting for Queue 1 event
[ID: 00000071] fv_queue_worker: elem 33: with 2 out desc of length 80 bad_in_num=0 bad_out_num=0
[ID: 00000071] unique: 12694, opcode: READ (15), nodeid: 2, insize: 80, pid: 2014
[ID: 00000071] lo_read(ino=2, size=65536, off=131072)
Signed-off-by: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
---
contrib/virtiofsd/passthrough_ll.c | 11 ++++++++++-
1 file changed, 10 insertions(+), 1 deletion(-)
diff --git a/contrib/virtiofsd/passthrough_ll.c b/contrib/virtiofsd/passthrough_ll.c
index 6ad021d00d..0e85d5ea74 100644
--- a/contrib/virtiofsd/passthrough_ll.c
+++ b/contrib/virtiofsd/passthrough_ll.c
@@ -2849,11 +2849,17 @@ static void setup_nofile_rlimit(void)
}
static void log_func(enum fuse_log_level level,
- const char *fmt, va_list ap)
+ const char *_fmt, va_list ap)
{
+ char *fmt = (char *)_fmt;
+
if (current_log_level < level)
return;
+ if (current_log_level == FUSE_LOG_DEBUG)
+ fmt = g_strdup_printf("[ID: %08ld] %s",
+ syscall(__NR_gettid), _fmt);
+
if (use_syslog) {
int priority = LOG_ERR;
switch (level) {
@@ -2870,6 +2876,9 @@ static void log_func(enum fuse_log_level level,
} else {
vfprintf(stderr, fmt, ap);
}
+
+ if (current_log_level == FUSE_LOG_DEBUG)
+ g_free(fmt);
}
static void *ireg_do(void *data)
--
2.18.1
^ permalink raw reply related [flat|nested] 5+ messages in thread
* [Virtio-fs] [PATCH 2/2] virtiofsd: Add timestamp to the log with FUSE_LOG_DEBUG level
2019-11-06 19:06 [Virtio-fs] [PATCH 0/2] Add ID and timestamp to the log with FUSE_LOG_DEBUG level Masayoshi Mizuma
2019-11-06 19:06 ` [Virtio-fs] [PATCH 1/2] virtiofsd: Add ID " Masayoshi Mizuma
@ 2019-11-06 19:06 ` Masayoshi Mizuma
2019-11-07 10:52 ` Dr. David Alan Gilbert
1 sibling, 1 reply; 5+ messages in thread
From: Masayoshi Mizuma @ 2019-11-06 19:06 UTC (permalink / raw)
To: virtio-fs; +Cc: Masayoshi Mizuma
From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
virtiofsd has some threads, so we see a lot of logs with debug option.
It would be useful for debugging if we can see the timestamp.
Add nano second timestamp, which got by get_clock(), to the log with
FUSE_LOG_DEBUG level if the syslog option isn't set.
The log is like as:
]# ./virtiofsd -d -o vhost_user_socket=/tmp/vhostqemu0 -o source=/tmp/share0 -o cache=auto
...
[5365943125463727] [ID: 00000002] fv_queue_thread: Start for queue 0 kick_fd 9
[5365943125568644] [ID: 00000002] fv_queue_thread: Waiting for Queue 0 event
[5365943125573561] [ID: 00000002] fv_queue_thread: Got queue event on Queue 0
Signed-off-by: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
---
contrib/virtiofsd/passthrough_ll.c | 11 +++++++++--
1 file changed, 9 insertions(+), 2 deletions(-)
diff --git a/contrib/virtiofsd/passthrough_ll.c b/contrib/virtiofsd/passthrough_ll.c
index 0e85d5ea74..406f62ab37 100644
--- a/contrib/virtiofsd/passthrough_ll.c
+++ b/contrib/virtiofsd/passthrough_ll.c
@@ -37,6 +37,8 @@
#include "fuse_virtio.h"
#include "fuse_lowlevel.h"
#include "fuse_log.h"
+#include "qemu/osdep.h"
+#include "qemu/timer.h"
#include <unistd.h>
#include <stdlib.h>
#include <stdio.h>
@@ -2856,9 +2858,14 @@ static void log_func(enum fuse_log_level level,
if (current_log_level < level)
return;
- if (current_log_level == FUSE_LOG_DEBUG)
- fmt = g_strdup_printf("[ID: %08ld] %s",
+ if (current_log_level == FUSE_LOG_DEBUG) {
+ if (!use_syslog)
+ fmt = g_strdup_printf("[%ld] [ID: %08ld] %s",
+ get_clock(), syscall(__NR_gettid), _fmt);
+ else
+ fmt = g_strdup_printf("[ID: %08ld] %s",
syscall(__NR_gettid), _fmt);
+ }
if (use_syslog) {
int priority = LOG_ERR;
--
2.18.1
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [Virtio-fs] [PATCH 1/2] virtiofsd: Add ID to the log with FUSE_LOG_DEBUG level
2019-11-06 19:06 ` [Virtio-fs] [PATCH 1/2] virtiofsd: Add ID " Masayoshi Mizuma
@ 2019-11-07 10:46 ` Dr. David Alan Gilbert
0 siblings, 0 replies; 5+ messages in thread
From: Dr. David Alan Gilbert @ 2019-11-07 10:46 UTC (permalink / raw)
To: Masayoshi Mizuma; +Cc: virtio-fs, Masayoshi Mizuma
* Masayoshi Mizuma (msys.mizuma@gmail.com) wrote:
> From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
>
> virtiofsd has some threads, so we see a lot of logs with debug option.
> It would be useful for debugging if we can identify the specific thread
> from the log.
>
> Add ID, which is got by gettid(), to the log with FUSE_LOG_DEBUG level
> so that we can grep the specific thread.
>
> The log is like as:
>
> ]# ./virtiofsd -d -o vhost_user_socket=/tmp/vhostqemu0 -o source=/tmp/share0 -o cache=auto
> ...
> [ID: 00000097] unique: 12696, success, outsize: 120
> [ID: 00000097] virtio_send_msg: elem 18: with 2 in desc of length 120
> [ID: 00000003] fv_queue_thread: Got queue event on Queue 1
> [ID: 00000003] fv_queue_thread: Queue 1 gave evalue: 1 available: in: 65552 out: 80
> [ID: 00000003] fv_queue_thread: Waiting for Queue 1 event
> [ID: 00000071] fv_queue_worker: elem 33: with 2 out desc of length 80 bad_in_num=0 bad_out_num=0
> [ID: 00000071] unique: 12694, opcode: READ (15), nodeid: 2, insize: 80, pid: 2014
> [ID: 00000071] lo_read(ino=2, size=65536, off=131072)
>
> Signed-off-by: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
Yes, that's OK;
Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
> ---
> contrib/virtiofsd/passthrough_ll.c | 11 ++++++++++-
> 1 file changed, 10 insertions(+), 1 deletion(-)
>
> diff --git a/contrib/virtiofsd/passthrough_ll.c b/contrib/virtiofsd/passthrough_ll.c
> index 6ad021d00d..0e85d5ea74 100644
> --- a/contrib/virtiofsd/passthrough_ll.c
> +++ b/contrib/virtiofsd/passthrough_ll.c
> @@ -2849,11 +2849,17 @@ static void setup_nofile_rlimit(void)
> }
>
> static void log_func(enum fuse_log_level level,
> - const char *fmt, va_list ap)
> + const char *_fmt, va_list ap)
> {
> + char *fmt = (char *)_fmt;
> +
> if (current_log_level < level)
> return;
>
> + if (current_log_level == FUSE_LOG_DEBUG)
> + fmt = g_strdup_printf("[ID: %08ld] %s",
> + syscall(__NR_gettid), _fmt);
> +
> if (use_syslog) {
> int priority = LOG_ERR;
> switch (level) {
> @@ -2870,6 +2876,9 @@ static void log_func(enum fuse_log_level level,
> } else {
> vfprintf(stderr, fmt, ap);
> }
> +
> + if (current_log_level == FUSE_LOG_DEBUG)
> + g_free(fmt);
> }
>
> static void *ireg_do(void *data)
> --
> 2.18.1
>
> _______________________________________________
> 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] 5+ messages in thread
* Re: [Virtio-fs] [PATCH 2/2] virtiofsd: Add timestamp to the log with FUSE_LOG_DEBUG level
2019-11-06 19:06 ` [Virtio-fs] [PATCH 2/2] virtiofsd: Add timestamp " Masayoshi Mizuma
@ 2019-11-07 10:52 ` Dr. David Alan Gilbert
0 siblings, 0 replies; 5+ messages in thread
From: Dr. David Alan Gilbert @ 2019-11-07 10:52 UTC (permalink / raw)
To: Masayoshi Mizuma; +Cc: virtio-fs, Masayoshi Mizuma
* Masayoshi Mizuma (msys.mizuma@gmail.com) wrote:
> From: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
>
> virtiofsd has some threads, so we see a lot of logs with debug option.
> It would be useful for debugging if we can see the timestamp.
>
> Add nano second timestamp, which got by get_clock(), to the log with
> FUSE_LOG_DEBUG level if the syslog option isn't set.
>
> The log is like as:
>
> ]# ./virtiofsd -d -o vhost_user_socket=/tmp/vhostqemu0 -o source=/tmp/share0 -o cache=auto
> ...
> [5365943125463727] [ID: 00000002] fv_queue_thread: Start for queue 0 kick_fd 9
> [5365943125568644] [ID: 00000002] fv_queue_thread: Waiting for Queue 0 event
> [5365943125573561] [ID: 00000002] fv_queue_thread: Got queue event on Queue 0
>
> Signed-off-by: Masayoshi Mizuma <m.mizuma@jp.fujitsu.com>
Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
> ---
> contrib/virtiofsd/passthrough_ll.c | 11 +++++++++--
> 1 file changed, 9 insertions(+), 2 deletions(-)
>
> diff --git a/contrib/virtiofsd/passthrough_ll.c b/contrib/virtiofsd/passthrough_ll.c
> index 0e85d5ea74..406f62ab37 100644
> --- a/contrib/virtiofsd/passthrough_ll.c
> +++ b/contrib/virtiofsd/passthrough_ll.c
> @@ -37,6 +37,8 @@
> #include "fuse_virtio.h"
> #include "fuse_lowlevel.h"
> #include "fuse_log.h"
> +#include "qemu/osdep.h"
> +#include "qemu/timer.h"
> #include <unistd.h>
> #include <stdlib.h>
> #include <stdio.h>
> @@ -2856,9 +2858,14 @@ static void log_func(enum fuse_log_level level,
> if (current_log_level < level)
> return;
>
> - if (current_log_level == FUSE_LOG_DEBUG)
> - fmt = g_strdup_printf("[ID: %08ld] %s",
> + if (current_log_level == FUSE_LOG_DEBUG) {
> + if (!use_syslog)
> + fmt = g_strdup_printf("[%ld] [ID: %08ld] %s",
> + get_clock(), syscall(__NR_gettid), _fmt);
> + else
> + fmt = g_strdup_printf("[ID: %08ld] %s",
> syscall(__NR_gettid), _fmt);
> + }
>
> if (use_syslog) {
> int priority = LOG_ERR;
> --
> 2.18.1
>
> _______________________________________________
> 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] 5+ messages in thread
end of thread, other threads:[~2019-11-07 10:52 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-11-06 19:06 [Virtio-fs] [PATCH 0/2] Add ID and timestamp to the log with FUSE_LOG_DEBUG level Masayoshi Mizuma
2019-11-06 19:06 ` [Virtio-fs] [PATCH 1/2] virtiofsd: Add ID " Masayoshi Mizuma
2019-11-07 10:46 ` Dr. David Alan Gilbert
2019-11-06 19:06 ` [Virtio-fs] [PATCH 2/2] virtiofsd: Add timestamp " Masayoshi Mizuma
2019-11-07 10:52 ` 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.