Re: [PATCH] rtnetlink: add rtnl_lock debug log

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