[v2] virtiofs daemon [all]

[PATCH v2 062/109] virtiofsd: Add timestamp to the log with FUSE_LOG_DEBUG level

Posted by Dr. David Alan Gilbert (git) 6 years ago

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>
---
 tools/virtiofsd/passthrough_ll.c | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
index 991de69334..a7fb34ac0c 100644
--- a/tools/virtiofsd/passthrough_ll.c
+++ b/tools/virtiofsd/passthrough_ll.c
@@ -35,6 +35,8 @@
  * \include passthrough_ll.c
  */
 
+#include "qemu/osdep.h"
+#include "qemu/timer.h"
 #include "fuse_virtio.h"
 #include "fuse_log.h"
 #include "fuse_lowlevel.h"
@@ -2275,7 +2277,13 @@ static void log_func(enum fuse_log_level level, const char *fmt, va_list ap)
     }
 
     if (current_log_level == FUSE_LOG_DEBUG) {
-        localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid), fmt);
+        if (!use_syslog) {
+            localfmt = g_strdup_printf("[%" PRId64 "] [ID: %08ld] %s",
+                                       get_clock(), syscall(__NR_gettid), fmt);
+        } else {
+            localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid),
+                                       fmt);
+        }
         fmt = localfmt;
     }
 
-- 
2.24.1

Re: [PATCH v2 062/109] virtiofsd: Add timestamp to the log with FUSE_LOG_DEBUG level

Posted by Philippe Mathieu-Daudé 6 years ago

On 1/21/20 1:23 PM, Dr. David Alan Gilbert (git) 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

First ']' is incorrect copy/pasting?

>    ...
>    [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>
> ---
>   tools/virtiofsd/passthrough_ll.c | 10 +++++++++-
>   1 file changed, 9 insertions(+), 1 deletion(-)
> 
> diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
> index 991de69334..a7fb34ac0c 100644
> --- a/tools/virtiofsd/passthrough_ll.c
> +++ b/tools/virtiofsd/passthrough_ll.c
> @@ -35,6 +35,8 @@
>    * \include passthrough_ll.c
>    */
>   
> +#include "qemu/osdep.h"

I think this include belongs to patch #011 "virtiofsd: Fix common header 
and define for QEMU builds".

Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>

> +#include "qemu/timer.h"
>   #include "fuse_virtio.h"
>   #include "fuse_log.h"
>   #include "fuse_lowlevel.h"
> @@ -2275,7 +2277,13 @@ static void log_func(enum fuse_log_level level, const char *fmt, va_list ap)
>       }
>   
>       if (current_log_level == FUSE_LOG_DEBUG) {
> -        localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid), fmt);
> +        if (!use_syslog) {
> +            localfmt = g_strdup_printf("[%" PRId64 "] [ID: %08ld] %s",
> +                                       get_clock(), syscall(__NR_gettid), fmt);
> +        } else {
> +            localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid),
> +                                       fmt);
> +        }
>           fmt = localfmt;
>       }
>   
>

Re: [PATCH v2 062/109] virtiofsd: Add timestamp to the log with FUSE_LOG_DEBUG level

Posted by Dr. David Alan Gilbert 6 years ago

* Philippe Mathieu-Daudé (philmd@redhat.com) wrote:
> On 1/21/20 1:23 PM, Dr. David Alan Gilbert (git) 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
> 
> First ']' is incorrect copy/pasting?

Oops yes, removed.

> >    ...
> >    [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>
> > ---
> >   tools/virtiofsd/passthrough_ll.c | 10 +++++++++-
> >   1 file changed, 9 insertions(+), 1 deletion(-)
> > 
> > diff --git a/tools/virtiofsd/passthrough_ll.c b/tools/virtiofsd/passthrough_ll.c
> > index 991de69334..a7fb34ac0c 100644
> > --- a/tools/virtiofsd/passthrough_ll.c
> > +++ b/tools/virtiofsd/passthrough_ll.c
> > @@ -35,6 +35,8 @@
> >    * \include passthrough_ll.c
> >    */
> > +#include "qemu/osdep.h"
> 
> I think this include belongs to patch #011 "virtiofsd: Fix common header and
> define for QEMU builds".

Moved.

> Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
> 

Thanks.

> > +#include "qemu/timer.h"
> >   #include "fuse_virtio.h"
> >   #include "fuse_log.h"
> >   #include "fuse_lowlevel.h"
> > @@ -2275,7 +2277,13 @@ static void log_func(enum fuse_log_level level, const char *fmt, va_list ap)
> >       }
> >       if (current_log_level == FUSE_LOG_DEBUG) {
> > -        localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid), fmt);
> > +        if (!use_syslog) {
> > +            localfmt = g_strdup_printf("[%" PRId64 "] [ID: %08ld] %s",
> > +                                       get_clock(), syscall(__NR_gettid), fmt);
> > +        } else {
> > +            localfmt = g_strdup_printf("[ID: %08ld] %s", syscall(__NR_gettid),
> > +                                       fmt);
> > +        }
> >           fmt = localfmt;
> >       }
> > 
> 
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK