On Thu, Nov 19, 2020 at 7:08 PM Dmitry Vyukov wrote: > > > > On Thu, Nov 19, 2020 at 2:45 PM Tetsuo Handa > > > > wrote: > > > > > > > > > > On 2020/11/19 22:06, Dmitry Vyukov wrote: > > > > > >>>> > > > > > >>>> I am trying to reproduce this locally first. syzbot caims it can > > > > > >>>> reproduce it with a number of very simpler reproducers (like spawn > > > > > >>>> process, unshare, create socket): > > > > > >>>> https://syzkaller.appspot.com/bug?id=8a18efe79140782a88dcd098808d6ab20ed740cc > > > > > >>>> > > > > > >>>> I see a very slow drift, but it's very slow, so get only to: > > > > > >>>> direct dependencies: 22072 [max: 32768] > > > > > >>>> > > > > > >>>> But that's running a very uniform workload. > > > > > >>>> > > > > > >>>> However when I tried to cat /proc/lockdep to see if there is anything > > > > > >>>> fishy already, > > > > > >>>> I got this (on c2e7554e1b85935d962127efa3c2a76483b0b3b6). > > > > > >>>> > > > > > >>>> Some missing locks? > > > > > > > > > > Not a TOMOYO's bug. Maybe a lockdep's bug. > > > > > > > > > > > > > > > > > But I don't know if it's enough to explain the overflow or not... > > > > > > > > > > > > > > > > Since you can't hit the limit locally, I guess we need to ask syzbot to > > > > > run massive testcases. > > > > > > > > I am trying to test the code that will do this. Otherwise we will get > > > > days-long round-trips for stupid bugs. These files are also quite > > > > huge, I afraid that may not fit into storage. > > > > > > > > So far I get to at most: > > > > > > > > lock-classes: 2901 [max: 8192] > > > > direct dependencies: 25574 [max: 32768] > > > > dependency chains: 40605 [max: 65536] > > > > dependency chain hlocks used: 176814 [max: 327680] > > > > stack-trace entries: 258590 [max: 524288] > > > > > > > > with these worst offenders: > > > > > > > > # egrep "BD: [0-9]" /proc/lockdep > > > > 00000000df5b6792 FD: 2 BD: 1235 -.-.: &obj_hash[i].lock > > > > 000000005dfeb73c FD: 1 BD: 1236 ..-.: pool_lock > > > > 00000000b86254b1 FD: 14 BD: 1111 -.-.: &rq->lock > > > > 00000000866efb75 FD: 1 BD: 1112 ....: &cfs_b->lock > > > > 000000006970cf1a FD: 2 BD: 1126 ----: tk_core.seq.seqcount > > > > 00000000f49d95b0 FD: 3 BD: 1180 -.-.: &base->lock > > > > 00000000ba3f8454 FD: 5 BD: 1115 -.-.: hrtimer_bases.lock > > > > 00000000fb340f16 FD: 16 BD: 1030 -.-.: &p->pi_lock > > > > 00000000c9f6f58c FD: 1 BD: 1114 -.-.: &per_cpu_ptr(group->pcpu, cpu)->seq > > > > 0000000049d3998c FD: 1 BD: 1112 -.-.: &cfs_rq->removed.lock > > > > 00000000fdf7f396 FD: 7 BD: 1112 -...: &rt_b->rt_runtime_lock > > > > 0000000021aedb8d FD: 1 BD: 1113 -...: &rt_rq->rt_runtime_lock > > > > 000000004e34c8d4 FD: 1 BD: 1112 ....: &cp->lock > > > > 00000000b2ac5d96 FD: 1 BD: 1127 -.-.: pvclock_gtod_data > > > > 00000000c5df4dc3 FD: 1 BD: 1031 ..-.: &tsk->delays->lock > > > > 00000000fe623698 FD: 1 BD: 1112 -...: > > > > per_cpu_ptr(&cgroup_rstat_cpu_lock, cpu) > > > > > > > > > > > > But the kernel continues to crash on different unrelated bugs... > > > > > > > > > Here is one successful sample. How do we debug it? What should we be > > > looking for? > > > > > > p.s. it's indeed huge, full log was 11MB, this probably won't be > > > chewed by syzbot. > > > Peter, are these [hex numbers] needed? Could we strip them during > > > post-processing? At first sight they look like derivatives of the > > > name. > > > > The worst back-edge offenders are: > > > > 00000000b445a595 FD: 2 BD: 1595 -.-.: &obj_hash[i].lock > > 0000000055ae0468 FD: 1 BD: 1596 ..-.: pool_lock > > 00000000b1336dc4 FD: 2 BD: 1002 ..-.: &zone->lock > > 000000009a0cabce FD: 1 BD: 1042 ...-: &____s->seqcount > > 000000001f2849b5 FD: 1 BD: 1192 ..-.: depot_lock > > 00000000d044255b FD: 1 BD: 1038 -.-.: &n->list_lock > > 000000005868699e FD: 17 BD: 1447 -.-.: &rq->lock > > 00000000bb52ab59 FD: 1 BD: 1448 ....: &cfs_b->lock > > 000000004f442fff FD: 2 BD: 1469 ----: tk_core.seq.seqcount > > 00000000c908cc32 FD: 3 BD: 1512 -.-.: &base->lock > > 00000000478677cc FD: 5 BD: 1435 -.-.: hrtimer_bases.lock > > 00000000b5b65cb1 FD: 19 BD: 1255 -.-.: &p->pi_lock > > 000000007f313bd5 FD: 1 BD: 1451 -.-.: &per_cpu_ptr(group->pcpu, cpu)->seq > > 00000000bac5d8ed FD: 1 BD: 1004 ...-: &____s->seqcount#2 > > 000000000f57e411 FD: 1 BD: 1448 -.-.: &cfs_rq->removed.lock > > 0000000013c1ab65 FD: 7 BD: 1449 -.-.: &rt_b->rt_runtime_lock > > 000000003bdf78f4 FD: 1 BD: 1450 -.-.: &rt_rq->rt_runtime_lock > > 00000000975d5b80 FD: 1 BD: 1448 ....: &cp->lock > > 000000002586e81b FD: 1 BD: 1471 -.-.: pvclock_gtod_data > > 00000000d03aed24 FD: 1 BD: 1275 ..-.: &tsk->delays->lock > > 000000001119414f FD: 1 BD: 1448 -...: > > per_cpu_ptr(&cgroup_rstat_cpu_lock, cpu) > > 000000006f3d793b FD: 6 BD: 1449 -.-.: &ctx->lock > > 00000000f3f0190c FD: 9 BD: 1448 -...: &rq->lock/1 > > 000000007410cf1a FD: 1 BD: 1448 -...: &rd->rto_lock > > > > There are 19 with ~1500 incoming edges. So that's 20K. > > > > In my local testing I was at around 20-something K and these worst > > offenders were at ~1000 back edges. > > Now they got to 1500, so that is what got us over the 32K limit, right? > > > > Does this analysis make sense? > > > > Any ideas what to do with these? > > And here is a full dump for: > BUG: MAX_LOCKDEP_CHAINS too low! Attached a wrong one, here is the one with "BUG: MAX_LOCKDEP_CHAINS too low!". There are also some outliers with high FD count. But these mostly look fine too, just locks with high fan out (genl_mutex/deferred_process_work): $ egrep "FD: [0-9]" log42 00000000745aa345 FD: 1032 BD: 13 +.+.: cgroup_mutex 00000000cdf4d414 FD: 1193 BD: 8 ++++: pernet_ops_rwsem 00000000582c60d4 FD: 1707 BD: 1 +.+.: (wq_completion)events 000000003f5e465a FD: 1012 BD: 46 +.+.: rtnl_mutex 000000005c1c41b7 FD: 1041 BD: 1 ++++: cb_lock 000000001dea9384 FD: 1038 BD: 3 +.+.: genl_mutex 00000000d158b76e FD: 1483 BD: 2 +.+.: (delayed_fput_work).work 00000000caec859a FD: 1036 BD: 1 +.+.: (wq_completion)events_power_efficient 00000000e36b9bc8 FD: 1033 BD: 1 +.+.: blkcg_pol_register_mutex 00000000927de1d8 FD: 1013 BD: 2 +.+.: (linkwatch_work).work 00000000161fed05 FD: 1013 BD: 1 +.+.: dlci_ioctl_mutex 000000003b6f60a4 FD: 1194 BD: 1 +.+.: masq_mutex 0000000050f06ef0 FD: 1015 BD: 1 +.+.: (wq_completion)ipv6_addrconf 0000000022d8bdd2 FD: 1013 BD: 2 +.+.: (addr_chk_work).work 00000000208719ed FD: 1014 BD: 1 +.+.: br_ioctl_mutex 0000000034a64a9d FD: 1013 BD: 1 +.+.: vlan_ioctl_mutex 000000004bbb2b36 FD: 1013 BD: 2 +.+.: reg_work 00000000f3d10da2 FD: 1075 BD: 2 +.+.: (work_completion)(&fw_work->work) 00000000bf633318 FD: 1089 BD: 2 +.+.: &p->lock 00000000a04e4ca6 FD: 1342 BD: 4 +.+.: &sb->s_type->i_mutex_key#11 0000000074e4d032 FD: 1065 BD: 2 .+.+: sb_writers#7 000000005b21b2d8 FD: 1056 BD: 6 +.+.: &of->mutex 000000004e03ff55 FD: 1189 BD: 1 +.+.: &f->f_pos_lock 000000003c8d0466 FD: 1013 BD: 2 +.+.: (crda_timeout).work 00000000d7d5a678 FD: 1013 BD: 2 +.+.: (work_completion)(&(&ifa->dad_work)->work) 0000000085c47bd2 FD: 1013 BD: 2 +.+.: (reg_check_chans).work 0000000008a61c9f FD: 1065 BD: 2 .+.+: sb_writers#10 000000003728e6ec FD: 1065 BD: 1 .+.+: sb_writers#11 000000007fe449ca FD: 1035 BD: 1 ++++: &type->s_umount_key#43 0000000078ce5279 FD: 1013 BD: 2 +.+.: deferred_process_work 00000000c673625f FD: 1029 BD: 1 .+.+: kn->active#80 000000003734f752 FD: 1028 BD: 8 +.+.: nsim_bus_dev_list_lock 0000000085797ea4 FD: 1023 BD: 20 +.+.: devlink_mutex 0000000019a4328d FD: 1020 BD: 2 +.+.: (work_completion)(&(&nsim_dev->trap_data->trap_report_dw)->work) 00000000615ae4c1 FD: 1018 BD: 22 +.+.: &nsim_dev->port_list_lock 00000000bf207b94 FD: 1039 BD: 2 +.+.: nlk_cb_mutex-GENERIC 00000000d0a722ec FD: 1015 BD: 1 +.+.: (wq_completion)cfg80211 00000000e2d69b1e FD: 1013 BD: 10 +.+.: (work_completion)(&rdev->event_work) 0000000094cc69ac FD: 1040 BD: 3 +.+.: &type->i_mutex_dir_key#6/1 00000000897451d9 FD: 1035 BD: 2 +.+.: &type->i_mutex_dir_key#7/1 000000008bade0a8 FD: 1014 BD: 1 +.+.: ppp_mutex 000000004f82d94d FD: 1196 BD: 1 +.+.: (wq_completion)netns 000000002d98bcf4 FD: 1195 BD: 2 +.+.: net_cleanup_work :00000000cade4b38 FD: 1343 BD: 1 .+.+: sb_writers#13 00000000530be43e FD: 1013 BD: 2 +.+.: (work_completion)(&(&rdev->dfs_update_channels_wk)->work) 0000000027cc2a05 FD: 1032 BD: 2 +.+.: (work_completion)(&map->work)