From: Rocco.Yue <rocco.yue@mediatek.com> To: Tetsuo Handa <penguin-kernel@i-love.sakura.ne.jp> Cc: Peter Enderborg <peter.enderborg@sony.com>, Thomas Gleixner <tglx@linutronix.de>, Anshuman Khandual <anshuman.khandual@arm.com>, "Vitor Massaru Iha" <vitor@massaru.org>, Sedat Dilek <sedat.dilek@gmail.com>, "Wei Yang" <richard.weiyang@gmail.com>, Cong Wang <cong.wang@bytedance.com>, "Di Zhu" <zhudi21@huawei.com>, Stephen Hemminger <stephen@networkplumber.org>, Francis Laniel <laniel_francis@privacyrequired.com>, Roopa Prabhu <roopa@cumulusnetworks.com>, Andrii Nakryiko <andrii@kernel.org>, <linux-kernel@vger.kernel.org>, <netdev@vger.kernel.org>, <linux-arm-kernel@lists.infradead.org>, <linux-mediatek@lists.infradead.org>, <wsd_upsream@mediatek.com>, "David S . Miller" <davem@davemloft.net>, "Jakub Kicinski" <kuba@kernel.org>, Masahiro Yamada <masahiroy@kernel.org>, "Matthias Brugger" <matthias.bgg@gmail.com>, Andrew Morton <akpm@linux-foundation.org>, Nick Desaulniers <ndesaulniers@google.com>, Andy Shevchenko <andriy.shevchenko@linux.intel.com>, <peterz@infradead.org> Subject: Re: [PATCH] rtnetlink: add rtnl_lock debug log Date: Sat, 8 May 2021 16:54:34 +0800 [thread overview] Message-ID: <1620464074.29475.77.camel@mbjsdccf07> (raw) In-Reply-To: <27fa19c9-81b2-3604-033c-b7fe5d14b620@i-love.sakura.ne.jp> > > +static void rtnl_print_btrace(struct timer_list *unused) > > +{ > > + pr_info("----------- %s start -----------\n", __func__); > > + pr_info("%s[%d][%c] hold rtnl_lock more than 2 sec, start time: %llu\n", > > + rtnl_instance.task->comm, > > + rtnl_instance.pid, > > + task_state_to_char(rtnl_instance.task), > > + rtnl_instance.start_time); > > + stack_trace_print(rtnl_instance.addrs, rtnl_instance.nr_entries, 0); > > Do we want to print same traces every 2 seconds? > > Since it is possible to stall for e.g. 30 seconds, printing either only upon > first call to rtnl_print_btrace() for each stalling duration or only upon > end of stalling duration (i.e. from rtnl_relase_btrace()) is better? > Thanks for your review, Tetsuo. rtnl_chk_timer is a one-shot timer, I don't rearm the timer after expire, therefore traces are only logged once after rtnl_lock was held for more than 2 seconds, rather than every 2 seconds. In this way, even if this rtnl_lock debug mechanism is enabled, the overhead is also affordable in the user load. As far as I understand it, there won't be the problem you mentioned. In my experience, it's more appropriate to print trace when call rtnl_print_btrace(), we can't expect that rtnl_lock will be released before kernel reboot. And after holding the rtnl_lock for more than 2s, we will print these logs, which is more helpful for us. > > + show_stack(rtnl_instance.task, NULL, KERN_DEBUG); > > Why KERN_DEBUG ? > > If you retrieve the output via dmesg, KERN_DEBUG would be fine. > But for syzkaller (which counts on printk() messages being printed to > consoles), KERN_INFO (or default) is expected. > KERN_INFO is expected, I will fix it in patch v2. > > + pr_info("------------ %s end -----------\n", __func__); > > +} > > + > > +static void rtnl_relase_btrace(void) > > +{ > > + rtnl_instance.end_time = sched_clock(); > > + > > You should del_timer_sync() here than > > > + if (rtnl_instance.end_time - rtnl_instance.start_time > 2000000000ULL) { > > + pr_info("rtnl_lock is held by [%d] from [%llu] to [%llu]\n", > > + rtnl_instance.pid, > > + rtnl_instance.start_time, > > + rtnl_instance.end_time); > > + } > > + > > + del_timer(&rtnl_chk_timer); > > here in order to make sure that end message is printed only after > rtnl_print_btrace() messages are printed. > Will have a separate patch for this. > > +} > > +#endif > > + > Best Regards Rocco _______________________________________________ Linux-mediatek mailing list Linux-mediatek@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-mediatek
WARNING: multiple messages have this Message-ID (diff)
From: Rocco.Yue <rocco.yue@mediatek.com> To: Tetsuo Handa <penguin-kernel@i-love.sakura.ne.jp> Cc: Peter Enderborg <peter.enderborg@sony.com>, Thomas Gleixner <tglx@linutronix.de>, Anshuman Khandual <anshuman.khandual@arm.com>, "Vitor Massaru Iha" <vitor@massaru.org>, Sedat Dilek <sedat.dilek@gmail.com>, "Wei Yang" <richard.weiyang@gmail.com>, Cong Wang <cong.wang@bytedance.com>, "Di Zhu" <zhudi21@huawei.com>, Stephen Hemminger <stephen@networkplumber.org>, Francis Laniel <laniel_francis@privacyrequired.com>, Roopa Prabhu <roopa@cumulusnetworks.com>, Andrii Nakryiko <andrii@kernel.org>, <linux-kernel@vger.kernel.org>, <netdev@vger.kernel.org>, <linux-arm-kernel@lists.infradead.org>, <linux-mediatek@lists.infradead.org>, <wsd_upsream@mediatek.com>, "David S . Miller" <davem@davemloft.net>, "Jakub Kicinski" <kuba@kernel.org>, Masahiro Yamada <masahiroy@kernel.org>, "Matthias Brugger" <matthias.bgg@gmail.com>, Andrew Morton <akpm@linux-foundation.org>, Nick Desaulniers <ndesaulniers@google.com>, Andy Shevchenko <andriy.shevchenko@linux.intel.com>, <peterz@infradead.org> Subject: Re: [PATCH] rtnetlink: add rtnl_lock debug log Date: Sat, 8 May 2021 16:54:34 +0800 [thread overview] Message-ID: <1620464074.29475.77.camel@mbjsdccf07> (raw) In-Reply-To: <27fa19c9-81b2-3604-033c-b7fe5d14b620@i-love.sakura.ne.jp> > > +static void rtnl_print_btrace(struct timer_list *unused) > > +{ > > + pr_info("----------- %s start -----------\n", __func__); > > + pr_info("%s[%d][%c] hold rtnl_lock more than 2 sec, start time: %llu\n", > > + rtnl_instance.task->comm, > > + rtnl_instance.pid, > > + task_state_to_char(rtnl_instance.task), > > + rtnl_instance.start_time); > > + stack_trace_print(rtnl_instance.addrs, rtnl_instance.nr_entries, 0); > > Do we want to print same traces every 2 seconds? > > Since it is possible to stall for e.g. 30 seconds, printing either only upon > first call to rtnl_print_btrace() for each stalling duration or only upon > end of stalling duration (i.e. from rtnl_relase_btrace()) is better? > Thanks for your review, Tetsuo. rtnl_chk_timer is a one-shot timer, I don't rearm the timer after expire, therefore traces are only logged once after rtnl_lock was held for more than 2 seconds, rather than every 2 seconds. In this way, even if this rtnl_lock debug mechanism is enabled, the overhead is also affordable in the user load. As far as I understand it, there won't be the problem you mentioned. In my experience, it's more appropriate to print trace when call rtnl_print_btrace(), we can't expect that rtnl_lock will be released before kernel reboot. And after holding the rtnl_lock for more than 2s, we will print these logs, which is more helpful for us. > > + show_stack(rtnl_instance.task, NULL, KERN_DEBUG); > > Why KERN_DEBUG ? > > If you retrieve the output via dmesg, KERN_DEBUG would be fine. > But for syzkaller (which counts on printk() messages being printed to > consoles), KERN_INFO (or default) is expected. > KERN_INFO is expected, I will fix it in patch v2. > > + pr_info("------------ %s end -----------\n", __func__); > > +} > > + > > +static void rtnl_relase_btrace(void) > > +{ > > + rtnl_instance.end_time = sched_clock(); > > + > > You should del_timer_sync() here than > > > + if (rtnl_instance.end_time - rtnl_instance.start_time > 2000000000ULL) { > > + pr_info("rtnl_lock is held by [%d] from [%llu] to [%llu]\n", > > + rtnl_instance.pid, > > + rtnl_instance.start_time, > > + rtnl_instance.end_time); > > + } > > + > > + del_timer(&rtnl_chk_timer); > > here in order to make sure that end message is printed only after > rtnl_print_btrace() messages are printed. > Will have a separate patch for this. > > +} > > +#endif > > + > Best Regards Rocco _______________________________________________ linux-arm-kernel mailing list linux-arm-kernel@lists.infradead.org http://lists.infradead.org/mailman/listinfo/linux-arm-kernel
next prev parent reply other threads:[~2021-05-08 9:07 UTC|newest] Thread overview: 15+ messages / expand[flat|nested] mbox.gz Atom feed top 2021-04-29 7:02 [PATCH] rtnetlink: add rtnl_lock debug log Rocco Yue 2021-04-29 7:02 ` Rocco Yue 2021-04-29 7:02 ` Rocco Yue 2021-04-29 9:32 ` Andy Shevchenko 2021-04-29 9:32 ` Andy Shevchenko 2021-04-29 9:32 ` Andy Shevchenko 2021-05-08 8:53 ` Rocco.Yue 2021-05-08 8:53 ` Rocco.Yue 2021-04-29 12:07 ` kernel test robot 2021-04-29 12:07 ` kernel test robot 2021-04-30 11:48 ` Tetsuo Handa 2021-04-30 11:48 ` Tetsuo Handa 2021-04-30 11:48 ` Tetsuo Handa 2021-05-08 8:54 ` Rocco.Yue [this message] 2021-05-08 8:54 ` Rocco.Yue
Reply instructions: You may reply publicly to this message via plain-text email using any one of the following methods: * Save the following mbox file, import it into your mail client, and reply-to-all from there: mbox Avoid top-posting and favor interleaved quoting: https://en.wikipedia.org/wiki/Posting_style#Interleaved_style * Reply using the --to, --cc, and --in-reply-to switches of git-send-email(1): git send-email \ --in-reply-to=1620464074.29475.77.camel@mbjsdccf07 \ --to=rocco.yue@mediatek.com \ --cc=akpm@linux-foundation.org \ --cc=andrii@kernel.org \ --cc=andriy.shevchenko@linux.intel.com \ --cc=anshuman.khandual@arm.com \ --cc=cong.wang@bytedance.com \ --cc=davem@davemloft.net \ --cc=kuba@kernel.org \ --cc=laniel_francis@privacyrequired.com \ --cc=linux-arm-kernel@lists.infradead.org \ --cc=linux-kernel@vger.kernel.org \ --cc=linux-mediatek@lists.infradead.org \ --cc=masahiroy@kernel.org \ --cc=matthias.bgg@gmail.com \ --cc=ndesaulniers@google.com \ --cc=netdev@vger.kernel.org \ --cc=penguin-kernel@i-love.sakura.ne.jp \ --cc=peter.enderborg@sony.com \ --cc=peterz@infradead.org \ --cc=richard.weiyang@gmail.com \ --cc=roopa@cumulusnetworks.com \ --cc=sedat.dilek@gmail.com \ --cc=stephen@networkplumber.org \ --cc=tglx@linutronix.de \ --cc=vitor@massaru.org \ --cc=wsd_upsream@mediatek.com \ --cc=zhudi21@huawei.com \ /path/to/YOUR_REPLY https://kernel.org/pub/software/scm/git/docs/git-send-email.html * If your mail client supports setting the In-Reply-To header via mailto: links, try the mailto: linkBe sure your reply has a Subject: header at the top and a blank line before the message body.
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.