From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-13.6 required=3.0 tests=BAYES_00,DKIM_INVALID, DKIM_SIGNED,HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 344D6C433FE for ; Tue, 8 Dec 2020 17:03:02 +0000 (UTC) Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id 9B51F23B01 for ; Tue, 8 Dec 2020 17:03:01 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 9B51F23B01 Authentication-Results: mail.kernel.org; dmarc=fail (p=none dis=none) header.from=redhat.com Authentication-Results: mail.kernel.org; spf=pass smtp.mailfrom=qemu-devel-bounces+qemu-devel=archiver.kernel.org@nongnu.org Received: from localhost ([::1]:57730 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1kmgOC-0002j4-5v for qemu-devel@archiver.kernel.org; Tue, 08 Dec 2020 12:03:00 -0500 Received: from eggs.gnu.org ([2001:470:142:3::10]:41074) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1kmgJL-00070a-1f for qemu-devel@nongnu.org; Tue, 08 Dec 2020 11:57:59 -0500 Received: from us-smtp-delivery-124.mimecast.com ([63.128.21.124]:54259) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.90_1) (envelope-from ) id 1kmgJI-0002g0-4d for qemu-devel@nongnu.org; Tue, 08 Dec 2020 11:57:58 -0500 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1607446675; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: in-reply-to:in-reply-to:references:references; bh=emUhub5ZcelmZKUodwT7ETznqLzH0PmVzF9N4PVrqSM=; b=fqLdIChPdLzSo5h+oN38WTQXmsuXkAhOnKvupphH6RPQRt0yNQJhU+2D8lhpmjeYSUQxVP 4oVOcOvlDkxr/ldpbBmMa6E/k1ZsSH1vqdmVBog5Fskqsrd1f6RUAEtEmgdjYWI391IA7C oZARNFHXZwj5dJKu8QbUU+iz2V8mMyc= Received: from mimecast-mx01.redhat.com (mimecast-mx01.redhat.com [209.132.183.4]) (Using TLS) by relay.mimecast.com with ESMTP id us-mta-290-ZjJTswkGNyaUkOHNejY9UA-1; Tue, 08 Dec 2020 11:57:53 -0500 X-MC-Unique: ZjJTswkGNyaUkOHNejY9UA-1 Received: from smtp.corp.redhat.com (int-mx03.intmail.prod.int.phx2.redhat.com [10.5.11.13]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id 13E0880EDA9 for ; Tue, 8 Dec 2020 16:57:26 +0000 (UTC) Received: from horse.redhat.com (ovpn-116-241.rdu2.redhat.com [10.10.116.241]) by smtp.corp.redhat.com (Postfix) with ESMTP id D72866E521; Tue, 8 Dec 2020 16:57:25 +0000 (UTC) Received: by horse.redhat.com (Postfix, from userid 10451) id 6AF42220BCF; Tue, 8 Dec 2020 11:57:25 -0500 (EST) Date: Tue, 8 Dec 2020 11:57:25 -0500 From: Vivek Goyal To: Laszlo Ersek Subject: Re: [Virtio-fs] [PATCH] virtiofsd: make the debug log timestamp on stderr more human-readable Message-ID: <20201208165725.GB20722@redhat.com> References: <20201208055043.31548-1-lersek@redhat.com> MIME-Version: 1.0 In-Reply-To: <20201208055043.31548-1-lersek@redhat.com> X-Scanned-By: MIMEDefang 2.79 on 10.5.11.13 Authentication-Results: relay.mimecast.com; auth=pass smtp.auth=CUSA124A263 smtp.mailfrom=vgoyal@redhat.com X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Received-SPF: pass client-ip=63.128.21.124; envelope-from=vgoyal@redhat.com; helo=us-smtp-delivery-124.mimecast.com X-Spam_score_int: -20 X-Spam_score: -2.1 X-Spam_bar: -- X-Spam_report: (-2.1 / 5.0 requ) BAYES_00=-1.9, DKIMWL_WL_HIGH=-0.001, DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, RCVD_IN_DNSWL_NONE=-0.0001, RCVD_IN_MSPIKE_H4=0.001, RCVD_IN_MSPIKE_WL=0.001, SPF_HELO_NONE=0.001, SPF_PASS=-0.001 autolearn=ham autolearn_force=no X-Spam_action: no action X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: virtio-fs@redhat.com, qemu-devel@nongnu.org Errors-To: qemu-devel-bounces+qemu-devel=archiver.kernel.org@nongnu.org Sender: "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" > Cc: Stefan Hajnoczi > Signed-off-by: Laszlo Ersek > --- > 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