David, The two issue happened at same time when we were using. The backtrace for the two issues. Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.149259] CacheFiles: Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.150376] CacheFiles: Error: Overlong wait for old active object to go away Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.151405] CacheFiles: object: OBJa81bd72 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.152359] CacheFiles: objstate=LOOK_UP_OBJECT fl=48 wbusy=2 ev=40[0] Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.153330] CacheFiles: ops=0 inp=0 exc=0 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.154317] CacheFiles: parent=ffff8801fe8c3c00 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.155248] CacheFiles: cookie=ffff8840a6e07c60 [pr=ffff884ebb669ec8 nd=ffff88106fb5afa0 fl=4f] Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.156225] CacheFiles: key=[32] '31f210a8084b0f980a001af680240000ec9e68000a00040000000000fc2d2b00' Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.157180] CacheFiles: xobject: OBJa81bd71 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.158090] CacheFiles: xobjstate=DROP_OBJECT fl=70 wbusy=2 ev=0[0] Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.158998] CacheFiles: xops=0 inp=0 exc=0 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.159891] CacheFiles: xparent=ffff8801fe8c3c00 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.160753] CacheFiles: xcookie=ffff8840a6e07c60 [pr=ffff884ebb669ec8 nd=ffff88106fb5afa0 fl=4f] Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.161640] CacheFiles: xkey=[32] '31f210a8084b0f980a001af680240000ec9e68000a00040000000000fc2d2b00' Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.162600] BUG: unable to handle kernel NULL pointer dereference at 0000000000000002 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.163492] IP: [<0000000000000002>] 0x2 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.164363] PGD 2fe4ab067 PUD 301aa0067 PMD 0 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.165196] Oops: 0010 [#1] SMP Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.166028] Modules linked in: xt_nat nfsv3 xt_recent veth ipt_MASQUERADE nf_nat_masquerade_ipv4 xfrm_user xfrm_algo iptable_nat nf_nat_ipv4 br_netfilter bridge stp llc aufs ipmi_devintf cachefiles(OE) msr nvidia_drm(POE) ip6t_REJECT nf_reject_ipv6 nf_log_ipv6 nvidia_uvm(POE) xt_hl ip6t_rt nf_conntrack_ipv6 nf_defrag_ipv6 bonding ipmi_ssif ipt_REJECT nf_reject_ipv4 nf_log_ipv4 nf_log_common xt_LOG xt_multiport xt_limit xt_tcpudp xt_addrtype nf_conntrack_ipv4 mxm_wmi nf_defrag_ipv4 xt_conntrack ip6table_filter ip6_tables nf_conntrack_netbios_ns nf_conntrack_broadcast nf_nat_ftp nf_nat nf_conntrack_ftp nf_conntrack intel_rapl x86_pkg_temp_thermal intel_powerclamp iptable_filter coretemp ip_tables x_tables kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd ast ttm joydev drm_kms_helper input_leds drm i2c_algo_bit fb_sys_fops syscopyarea sb_edac sysfillrect sysimgblt edac_core mei_me nvidia_modeset(POE) mei shpchp lpc_ich ipmi_si 8250_fintek ipmi_msghandler wmi acpi_power_meter mac_hid nfsd auth_rpcgss knem(OE) nvidia(POE) nfs_acl lp parport nfs lockd grace sunrpc fscache(OE) rdma_ucm(OE) ib_ucm(OE) rdma_cm(OE) iw_cm(OE) configfs ib_ipoib(OE) ib_cm(OE) ib_uverbs(OE) ib_umad(OE) mlx5_ib(OE) mlx4_ib(OE) ib_sa(OE) ib_mad(OE) ib_core(OE) ib_addr(OE) ib_netlink(OE) mlx4_en(OE) mlx4_core(OE) nls_iso8859_1 ses enclosure mlx5_core(OE) ixgbe dca hid_generic mlx_compat(OE) vxlan ip6_udp_tunnel udp_tunnel ahci usbhid ptp megaraid_sas hid libahci mdio pps_core fjes Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.177451] CPU: 8 PID: 58210 Comm: kworker/u161:1 Tainted: P OE 4.4.0-45-generic #66~14.04.1-Ubuntu Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.178425] Hardware name: NVIDIA DGX-1/DGX-1, BIOS S2W_3A01.NVD02 11/03/2016 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.179412] Workqueue: fscache_object fscache_object_work_func [fscache] Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.180300] task: ffff8800381f6e00 ti: ffff882a9f248000 task.ti: ffff882a9f248000 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.181190] RIP: 0010:[<0000000000000002>] [<0000000000000002>] 0x2 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.182148] RSP: 0018:ffff882a9f24bdf8 EFLAGS: 00010202 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.183002] RAX: ffffffffc034d640 RBX: ffff881036ecf600 RCX: ffff8840903834d8 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.183866] RDX: 0000000000000002 RSI: 00000000ffffffff RDI: ffff881036ecf600 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.184800] RBP: ffff882a9f24be18 R08: 0000000000000000 R09: 0000000181000074 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.185736] R10: 0000000051482e01 R11: ffffea01f5452080 R12: 0000000000000000 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.186601] R13: ffff881036ecf690 R14: 0000000000001420 R15: ffff881036ecf690 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.187494] FS: 0000000000000000(0000) GS:ffff883f7f600000(0000) knlGS:0000000000000000 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.188371] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.189294] CR2: 0000000000000002 CR3: 00000002e27a1000 CR4: 00000000003406e0 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.190156] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.190969] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.191753] Stack: Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.192508] ffffffffc034848c ffff883f2f20b680 ffff883f7f01bc00 ffff880078adc200 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.193330] ffff882a9f24be60 ffffffff81095a70 000000007f01bc18 0000000000000000 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.194182] ffff883f7f01bc00 ffff883f7f01bc18 ffff883f2f20b6b0 ffff8800381f6e00 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.194967] Call Trace: Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.195739] [<ffffffffc034848c>] ? fscache_object_work_func+0x9c/0x1f0 [fscache] Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.196576] [<ffffffff81095a70>] process_one_work+0x150/0x3f0 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.197396] [<ffffffff810962e9>] worker_thread+0x219/0x470 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.198230] [<ffffffff810960d0>] ? rescuer_thread+0x310/0x310 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.199130] [<ffffffff8109b959>] kthread+0xc9/0xe0 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.199970] [<ffffffff8109b890>] ? kthread_park+0x60/0x60 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.200783] [<ffffffff817fa88f>] ret_from_fork+0x3f/0x70 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.201648] [<ffffffff8109b890>] ? kthread_park+0x60/0x60 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.202847] Code: Bad RIP value. Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.204285] RIP [<0000000000000002>] 0x2 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.205595] RSP <ffff882a9f24bdf8> Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.206351] CR2: 0000000000000002 Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.209685] ---[ end trace c5298f10cc175703 ]--- Sep 20 15:53:21 sc-sdgx-181 kernel: [3817108.218850] BUG: unable to handle kernel paging request at ffffffffffffffd8 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152175] CacheFiles: Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152207] CacheFiles: Error: Unexpected object collision Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152241] CacheFiles: object: OBJbd8f04 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152267] CacheFiles: objstate=LOOK_UP_OBJECT fl=8 wbusy=2 ev=0[0] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152303] CacheFiles: ops=0 inp=0 exc=0 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152327] CacheFiles: parent=ffff88226888b300 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152343] CacheFiles: cookie=ffff8828db4b4000 [pr=ffff8804157be9a0 nd=ffff8868e8e13398 fl=27] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152371] CacheFiles: key=[32] '62e88a3c08128b4e0a0084e611010000c7ee37000a00040000000000d2d72200' Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152431] CacheFiles: xobject: OBJbc7dab Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152447] CacheFiles: xobjstate=WAIT_FOR_CMD fl=38 wbusy=1 ev=50[6d] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152468] CacheFiles: xops=0 inp=0 exc=0 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152482] CacheFiles: xparent=ffff88226888b300 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152498] CacheFiles: xcookie=ffff885bbb5a6ec8 [pr=ffff8804157be9a0 nd= (null) fl=18] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152568] ------------[ cut here ]------------ Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.152585] kernel BUG at cachefiles/namei.c:197! Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.153782] invalid opcode: 0000 [#1] SMP Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.155211] Modules linked in: nfsv3 xt_recent veth ipt_MASQUERADE nf_nat_masquerade_ipv4 xfrm_user xfrm_algo iptable_nat nf_nat_ipv4 br_netfilter bridge stp llc aufs ipmi_devintf cachefiles(OE) msr nvidia_drm(POE) nvidia_uvm(POE) ip6t_REJECT nf_reject_ipv6 nf_log_ipv6 xt_hl ip6t_rt nf_conntrack_ipv6 nf_defrag_ipv6 bonding ipmi_ssif ipt_REJECT nf_reject_ipv4 nf_log_ipv4 nf_log_common xt_LOG xt_multiport xt_limit xt_tcpudp xt_addrtype nf_conntrack_ipv4 nf_defrag_ipv4 mxm_wmi xt_conntrack ip6table_filter ip6_tables intel_rapl nf_conntrack_netbios_ns x86_pkg_temp_thermal nf_conntrack_broadcast intel_powerclamp nf_nat_ftp nf_nat nf_conntrack_ftp nf_conntrack coretemp iptable_filter kvm_intel ip_tables x_tables kvm irqbypass crct10dif_pclmul crc32_pclmul aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd ast ttm joydev drm_kms_helper input_leds sb_edac drm i2c_algo_bit edac_core fb_sys_fops syscopyarea sysfillrect sysimgblt mei_me mei shpchp lpc_ich ipmi_si 8250_fintek ipmi_msghandler wmi nvidia_modeset(POE) acpi_power_meter mac_hid knem(OE) lp parport nvidia(POE) nfsd auth_rpcgss nfs_acl nfs lockd grace sunrpc fscache(OE) rdma_ucm(OE) ib_ucm(OE) rdma_cm(OE) iw_cm(OE) configfs ib_ipoib(OE) ib_cm(OE) ib_uverbs(OE) ib_umad(OE) mlx5_ib(OE) mlx4_ib(OE) ib_sa(OE) ib_mad(OE) ib_core(OE) ib_addr(OE) ib_netlink(OE) mlx4_en(OE) mlx4_core(OE) nls_iso8859_1 ses enclosure mlx5_core(OE) ixgbe dca mlx_compat(OE) hid_generic vxlan ip6_udp_tunnel udp_tunnel usbhid megaraid_sas ahci ptp hid libahci pps_core mdio fjes Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.172695] CPU: 26 PID: 76768 Comm: kworker/u162:0 Tainted: P OE 4.4.0-45-generic #66~14.04.1-Ubuntu Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.174319] Hardware name: NVIDIA DGX-1/DGX-1, BIOS S2W_3A01.NVD02 11/03/2016 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.176009] Workqueue: fscache_object fscache_object_work_func [fscache] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.177699] task: ffff8846e1c344c0 ti: ffff8867c165c000 task.ti: ffff8867c165c000 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.179380] RIP: 0010:[<ffffffffc10873e2>] [<ffffffffc10873e2>] cachefiles_walk_to_object+0x812/0x880 [cachefiles] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.181100] RSP: 0000:ffff8867c165fce8 EFLAGS: 00010202 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.182799] RAX: ffff88668b416401 RBX: ffff883c2c126e80 RCX: 00000000026b4205 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.184481] RDX: 00000000026b4204 RSI: ffff887f7ed8dc78 RDI: ffff883f7f007340 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.186150] RBP: ffff8867c165fd90 R08: 000000000001a020 R09: ffffffffc1089a3a Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.187839] R10: ffff887f7ed9a020 R11: ffffea019a2d0500 R12: ffff88339aaa2880 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.189603] R13: ffff8853a8204128 R14: ffff883c2c126e80 R15: ffff886fb3e3dec0 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.191216] FS: 0000000000000000(0000) GS:ffff887f7ed80000(0000) knlGS:0000000000000000 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.193013] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.194683] CR2: 0000000007400d00 CR3: 0000000002e0c000 CR4: 00000000003406e0 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.196369] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.198038] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.199667] Stack: Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.201337] ffffffff810b1a9f ffff8867c165fd58 ffff8846e1c344c0 ffff883ea20d20c0 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.203308] ffff887f61abc800 ffff887f04b12b20 ffff887f04b12a00 ffff883c2c126f90 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.205503] ffff887f41104c00 ffff887f6488b7a0 ffff887f7ed96d70 ffff8846e1c34520 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.207297] Call Trace: Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.209060] [<ffffffff810b1a9f>] ? update_curr+0xdf/0x170 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.210922] [<ffffffff810afbf4>] ? set_next_entity+0xa4/0x710 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.212624] [<ffffffffc10859ed>] cachefiles_lookup_object+0x4d/0xf0 [cachefiles] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.214532] [<ffffffffc02c8f4d>] fscache_look_up_object+0xbd/0x1d0 [fscache] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.216589] [<ffffffffc02c957d>] fscache_object_work_func+0x9d/0x200 [fscache] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.218941] [<ffffffff81095a70>] process_one_work+0x150/0x3f0 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.220574] [<ffffffff810961ea>] worker_thread+0x11a/0x470 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.222165] [<ffffffff817f6659>] ? __schedule+0x359/0x980 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.223708] [<ffffffff810960d0>] ? rescuer_thread+0x310/0x310 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.225328] [<ffffffff8109b959>] kthread+0xc9/0xe0 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.227019] [<ffffffff8109b890>] ? kthread_park+0x60/0x60 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.228739] [<ffffffff817fa88f>] ret_from_fork+0x3f/0x70 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.230487] [<ffffffff8109b890>] ? kthread_park+0x60/0x60 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.232017] Code: 0b 48 c7 c7 71 a5 08 c1 31 c0 4c 89 f3 e8 a6 99 0f c0 48 c7 c7 a0 b1 08 c1 31 c0 e8 98 99 0f c0 4c 89 e6 48 89 df e8 f5 25 00 00 <0f> 0b 0f 0b 48 c7 c7 71 a5 08 c1 31 c0 e8 7b 99 0f c0 48 c7 c7 Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.235180] RIP [<ffffffffc10873e2>] cachefiles_walk_to_object+0x812/0x880 [cachefiles] Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.236753] RSP <ffff8867c165fce8> Oct 9 06:34:24 sc-sdgx-122 kernel: [1759788.243018] ---[ end trace b0a35d8a38b2ffee ]--- On Thu, Jul 5, 2018 at 7:12 AM, David Howells <dhowells@xxxxxxxxxx> wrote: > KiranKumar Modukuri <kiran.modukuri@xxxxxxxxx> wrote: > >> CacheFiles: Error: Overlong wait for old active object to go away. > > Do you have the rest of the information it logs in this case? It should have > logged a summary of the two objects: > > pr_err("Error: Overlong wait for old active object to go away\n"); > cachefiles_printk_object(object, xobject); <------ > >> --- a/fs/cachefiles/namei.c >> +++ b/fs/cachefiles/namei.c >> @@ -194,7 +194,7 @@ wait_for_old_object: >> pr_err("\n"); >> pr_err("Error: Unexpected object collision\n"); >> cachefiles_printk_object(object, xobject); >> - BUG(); >> + WARN(true, "Unexpected object collision\n"); > > You didn't mention in your patch description that you'd hit this, so why are > you changing it? If you did, do you have the object summaries printed by > cachefiles_printk_object()? > > That said, it seems reasonable to either return an error at this point or wait > for the ACTIVE flag to be cleared on xobject. Maybe only permit one passage > of "wait_for_old_object:", but since objects shouldn't get reactivated that > probably isn't necessary. > > I think this bit: > > Remove the BUG() for the case where the old object is still being > dropped and convert to WARN() > > needs to be in its own patch since it's not obviously anything to do with the > subject at hand. > >> } >> atomic_inc(&xobject->usage); >> write_unlock(&cache->active_lock); >> @@ -247,6 +247,7 @@ wait_for_old_object: >> >> ASSERT(!test_bit(CACHEFILES_OBJECT_ACTIVE, &xobject->flags)); >> >> + clear_bit(CACHEFILES_OBJECT_ACTIVE, &object->flags); >> cache->cache.ops->put_object(&xobject->fscache); >> goto try_again; > > This bit looks right. It needs trace_cachefiles_mark_inactive() by it for > upstream consumption. > > David -- Kiran -- Linux-cachefs mailing list Linux-cachefs@xxxxxxxxxx https://www.redhat.com/mailman/listinfo/linux-cachefs