lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <CAHp75Vc=GMv5dJ1dJYr=B3W6c+nuPCfXa4wxLJOYPTuqrMskFg@mail.gmail.com>
Date:   Thu, 29 Apr 2021 12:32:17 +0300
From:   Andy Shevchenko <andy.shevchenko@...il.com>
To:     Rocco Yue <rocco.yue@...iatek.com>
Cc:     "David S . Miller" <davem@...emloft.net>,
        Jakub Kicinski <kuba@...nel.org>,
        Matthias Brugger <matthias.bgg@...il.com>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Masahiro Yamada <masahiroy@...nel.org>,
        Nick Desaulniers <ndesaulniers@...gle.com>,
        Andy Shevchenko <andriy.shevchenko@...ux.intel.com>,
        "Peter Zijlstra (Intel)" <peterz@...radead.org>,
        Tetsuo Handa <penguin-kernel@...ove.sakura.ne.jp>,
        Peter Enderborg <peter.enderborg@...y.com>,
        Thomas Gleixner <tglx@...utronix.de>,
        Anshuman Khandual <anshuman.khandual@....com>,
        Vitor Massaru Iha <vitor@...saru.org>,
        Sedat Dilek <sedat.dilek@...il.com>,
        Wei Yang <richard.weiyang@...il.com>,
        Cong Wang <cong.wang@...edance.com>,
        Di Zhu <zhudi21@...wei.com>,
        Stephen Hemminger <stephen@...workplumber.org>,
        Francis Laniel <laniel_francis@...vacyrequired.com>,
        Roopa Prabhu <roopa@...ulusnetworks.com>,
        Andrii Nakryiko <andrii@...nel.org>,
        Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
        netdev <netdev@...r.kernel.org>,
        linux-arm Mailing List <linux-arm-kernel@...ts.infradead.org>,
        "moderated list:ARM/Mediatek SoC support" 
        <linux-mediatek@...ts.infradead.org>, wsd_upsream@...iatek.com
Subject: Re: [PATCH] rtnetlink: add rtnl_lock debug log

On Thu, Apr 29, 2021 at 10:21 AM Rocco Yue <rocco.yue@...iatek.com> wrote:
>
> We often encounter system hangs caused by certain processes
> holding rtnl_lock for a long time. Even if there is a lock
> detection mechanism in Linux, it is a bit troublesome and
> affects the system performance. We hope to add a lightweight
> debugging mechanism for detecting rtnl_lock.
>
> Up to now, we have discovered and solved some potential bugs
> through such debug information of this lightweight rtnl_lock,
> which is helpful for us.
>
> When you say Y for RTNL_LOCK_DEBUG, then the kernel will detect
> if any function hold rtnl_lock too long and some key information
> will be printed to help identify the issue point.
>
> i.e: from the following logs, we can clear know that the pid=5546

clearly

> RfxSender_4 process hold rtnl_lock for a long time, causing the

holds

> system hang. And we can also speculate that the delay operation

to hang

> may be performed in devinet_ioctl(), resulting in rtnl_lock was
> not released in time.
>
> <6>[  141.151364] ----------- rtnl_print_btrace start -----------

Can you, please, shrink this to the point?

> <6>[  141.152079] RfxSender_4[5546][R] hold rtnl_lock more than 2 sec,
> start time: 139129481562
> <4>[  141.153114]  rtnl_lock+0x88/0xfc
> <4>[  141.153523]  devinet_ioctl+0x190/0x1268
> <4>[  141.154007]  inet_ioctl+0x108/0x1f4
> <4>[  141.154449]  sock_do_ioctl+0x88/0x200
> <4>[  141.154911]  sock_ioctl+0x4b0/0x884
> <4>[  141.155367]  do_vfs_ioctl+0x6b0/0xcc4
> <4>[  141.155830]  __arm64_sys_ioctl+0xc0/0xec
> <4>[  141.156326]  el0_svc_common+0x130/0x2c0
> <4>[  141.156810]  el0_svc_handler+0xd0/0xe0
> <4>[  141.157283]  el0_svc+0x8/0xc
> <4>[  141.157646] Call trace:
> <4>[  141.157956]  dump_backtrace+0x0/0x240
> <4>[  141.158418]  show_stack+0x18/0x24
> <4>[  141.158836]  rtnl_print_btrace+0x138/0x1cc
> <4>[  141.159362]  call_timer_fn+0x120/0x47c
> <4>[  141.159834]  expire_timers+0x28c/0x420
> <4>[  141.160306]  __run_timers+0x3d0/0x494
> <4>[  141.160768]  run_timer_softirq+0x24/0x48
> <4>[  141.161262]  __do_softirq+0x26c/0x968
> <4>[  141.161725]  irq_exit+0x1f8/0x2b4
> <4>[  141.162145]  __handle_domain_irq+0xdc/0x15c
> <4>[  141.162672]  gic_handle_irq+0xe4/0x188
> <4>[  141.163144]  el1_irq+0x104/0x200
> <4>[  141.163559]  __const_udelay+0x118/0x1b0
> <4>[  141.164044]  devinet_ioctl+0x1a0/0x1268
> <4>[  141.164527]  inet_ioctl+0x108/0x1f4
> <4>[  141.164968]  sock_do_ioctl+0x88/0x200
> <4>[  141.165428]  sock_ioctl+0x4b0/0x884
> <4>[  141.165868]  do_vfs_ioctl+0x6b0/0xcc4
> <4>[  141.166330]  __arm64_sys_ioctl+0xc0/0xec
> <4>[  141.166825]  el0_svc_common+0x130/0x2c0
> <4>[  141.167308]  el0_svc_handler+0xd0/0xe0
> <4>[  141.167786]  el0_svc+0x8/0xc
> <6>[  141.168153] ------------ rtnl_print_btrace end -----------
>
> <6>[  147.321389] rtnl_lock is held by [5546] from
> [139129481562] to [147321378812]


...

> +static struct rtnl_debug_btrace_t rtnl_instance = {
> +       .task           = NULL,
> +       .pid            = 0,
> +       .start_time     = 0,
> +       .end_time       = 0,
> +       .nr_entries     = 0,

static assumes all 0:s, what's the point?

> +};

...

> +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);

> +       show_stack(rtnl_instance.task, NULL, KERN_DEBUG);

Unaligned debug level.

> +       pr_info("------------ %s end -----------\n", __func__);

Looking into tons of these, perhaps you need to define pr_fmt(). I
haven't checked if it's already defined, though.

> +}

...

> +       if (rtnl_instance.end_time - rtnl_instance.start_time > 2000000000ULL) {

Perhaps you should use one of the defined constants from time64.h ?

> +               pr_info("rtnl_lock is held by [%d] from [%llu] to [%llu]\n",
> +                       rtnl_instance.pid,
> +                       rtnl_instance.start_time,
> +                       rtnl_instance.end_time);
> +       }

-- 
With Best Regards,
Andy Shevchenko

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ