Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1258835 > unrolled thread
| Started by | Jeff Layton <jlayton@poochiereds.net> |
|---|---|
| First post | 2015-10-29 15:40 +0100 |
| Last post | 2015-10-31 12:40 +0100 |
| Articles | 4 — 2 participants |
Back to article view | Back to linux.kernel
timer code oops when calling mod_delayed_work Jeff Layton <jlayton@poochiereds.net> - 2015-10-29 15:40 +0100
Re: timer code oops when calling mod_delayed_work Jeff Layton <jlayton@poochiereds.net> - 2015-10-29 19:00 +0100
Re: timer code oops when calling mod_delayed_work Tejun Heo <tj@kernel.org> - 2015-10-31 03:10 +0100
Re: timer code oops when calling mod_delayed_work Jeff Layton <jlayton@poochiereds.net> - 2015-10-31 12:40 +0100
| From | Jeff Layton <jlayton@poochiereds.net> |
|---|---|
| Date | 2015-10-29 15:40 +0100 |
| Subject | timer code oops when calling mod_delayed_work |
| Message-ID | <qoWwW-1lC-23@gated-at.bofh.it> |
Our QA guys hit the following warning and oops today on a relatively recent upstream kernel. They were running a fairly busy NFSv3 I/O test against this server: [ 71.074180] NFSD: starting 90-second grace period (net ffffffff81cf3b40) [ 221.146802] Ebtables v2.0 unregistered [ 318.909835] ------------[ cut here ]------------ [ 318.909846] WARNING: CPU: 22 PID: 3402 at kernel/workqueue.c:1444 __queue_delayed_work+0xe7/0x190() [ 318.909848] Modules linked in: bridge stp llc intel_rapl iosf_mbi x86_pkg_temp_thermal coretemp kvm_intel kvm ipmi_ssif crct10dif_pclmul crc32_pclmul iTCO_wdt iTCO_vendor_support joydev mei_me mei sb_edac shpchp ipmi_si lpc_ich i2c_i801 edac_core tpm_tis wmi ipmi_msghandler tpm acpi_power_meter acpi_pad nfsd auth_rpcgss nfs_acl lockd grace sunrpc xfs libcrc32c mlx4_en vxlan ip6_udp_tunnel udp_tunnel ast drm_kms_helper ttm crc32c_intel igb drm mlx4_core ptp nvme pps_core dca i2c_algo_bit fjes [last unloaded: iptable_security] [ 318.909889] CPU: 22 PID: 3402 Comm: nfsd Not tainted 4.3.0-0.rc7.git0.1.fc24.x86_64 #1 [ 318.909891] Hardware name: Quanta D51B/D51BP (1G LOM), BIOS S2BP3A05 01/29/2015 [ 318.909892] 0000000000000000 00000000319846b5 ffff880322d0f440 ffffffff813a48cf [ 318.909895] 0000000000000000 ffff880322d0f478 ffffffff8109f122 0000000000000400 [ 318.909898] ffff88085f48fc00 ffffffffa03623e0 ffff88085f48fc00 000000000001d4c0 [ 318.909901] Call Trace: [ 318.909906] [<ffffffff813a48cf>] dump_stack+0x44/0x55 [ 318.909909] [<ffffffff8109f122>] warn_slowpath_common+0x82/0xc0 [ 318.909913] [<ffffffff8109f26a>] warn_slowpath_null+0x1a/0x20 [ 318.909915] [<ffffffff810b67a7>] __queue_delayed_work+0xe7/0x190 [ 318.909917] [<ffffffff810b70de>] mod_delayed_work_on+0x5e/0xa0 [ 318.909931] [<ffffffffa0333394>] prune_cache_entries+0x94/0xb0 [nfsd] [ 318.909936] [<ffffffffa03333be>] nfsd_reply_cache_scan+0xe/0x10 [nfsd] [ 318.909941] [<ffffffff811b78e2>] shrink_slab.part.42+0x1e2/0x380 [ 318.909944] [<ffffffff811bbfc6>] shrink_zone+0x2b6/0x2c0 [ 318.909946] [<ffffffff811bc145>] do_try_to_free_pages+0x175/0x400 [ 318.909949] [<ffffffff811bc4da>] try_to_free_pages+0x10a/0x150 [ 318.909954] [<ffffffff811ae5b1>] __alloc_pages_nodemask+0x581/0x990 [ 318.909957] [<ffffffff811b19f5>] ? account_page_dirtied+0xd5/0x160 [ 318.909960] [<ffffffff811f7b41>] alloc_pages_current+0x91/0x100 [ 318.909963] [<ffffffff811a45bb>] __page_cache_alloc+0xab/0xe0 [ 318.909965] [<ffffffff811a4c94>] pagecache_get_page+0x84/0x1e0 [ 318.909967] [<ffffffff811a4e16>] grab_cache_page_write_begin+0x26/0x40 [ 318.909990] [<ffffffffa0221cd4>] xfs_vm_write_begin+0x34/0xe0 [xfs] [ 318.910005] [<ffffffffa0221a39>] ? xfs_vm_write_end+0x29/0x80 [xfs] [ 318.910007] [<ffffffff811a418e>] generic_perform_write+0xce/0x1c0 [ 318.910023] [<ffffffffa022efb7>] xfs_file_buffered_aio_write+0x127/0x250 [xfs] [ 318.910028] [<ffffffffa032be60>] ? nfserrno+0x60/0x60 [nfsd] [ 318.910031] [<ffffffff812035e9>] ? __kmalloc+0x1b9/0x260 [ 318.910034] [<ffffffff81223617>] ? rw_copy_check_uvector+0x57/0x110 [ 318.910047] [<ffffffffa022f1d5>] xfs_file_write_iter+0xf5/0x110 [xfs] [ 318.910050] [<ffffffff81221e3c>] do_iter_readv_writev+0x6c/0xa0 [ 318.910053] [<ffffffff812229bf>] do_readv_writev+0x18f/0x230 [ 318.910065] [<ffffffffa022f0e0>] ? xfs_file_buffered_aio_write+0x250/0x250 [xfs] [ 318.910068] [<ffffffff813284bb>] ? security_file_open+0x8b/0x90 [ 318.910070] [<ffffffff8121ffa4>] ? do_dentry_open+0x264/0x2f0 [ 318.910084] [<ffffffffa022ced0>] ? xfs_extent_busy_ag_cmp+0x20/0x20 [xfs] [ 318.910086] [<ffffffff81222ae9>] vfs_writev+0x39/0x50 [ 318.910092] [<ffffffffa032df4d>] nfsd_vfs_write+0xbd/0x380 [nfsd] [ 318.910097] [<ffffffffa0330568>] nfsd_write+0xd8/0xf0 [nfsd] [ 318.910103] [<ffffffffa03367fc>] nfsd3_proc_write+0xbc/0x150 [nfsd] [ 318.910107] [<ffffffffa0328e68>] nfsd_dispatch+0xb8/0x200 [nfsd] [ 318.910128] [<ffffffffa02d39dc>] svc_process_common+0x40c/0x650 [sunrpc] [ 318.910137] [<ffffffffa02d4b14>] svc_process+0xf4/0x180 [sunrpc] [ 318.910142] [<ffffffffa03288bf>] nfsd+0xef/0x160 [nfsd] [ 318.910146] [<ffffffffa03287d0>] ? nfsd_destroy+0x60/0x60 [nfsd] [ 318.910149] [<ffffffff810bd6a8>] kthread+0xd8/0xf0 [ 318.910152] [<ffffffff810bd5d0>] ? kthread_worker_fn+0x160/0x160 [ 318.910155] [<ffffffff8177f19f>] ret_from_fork+0x3f/0x70 [ 318.910158] [<ffffffff810bd5d0>] ? kthread_worker_fn+0x160/0x160 [ 318.910160] ---[ end trace db375019f3368852 ]--- [ 318.910169] ------------[ cut here ]------------ [ 318.910201] kernel BUG at kernel/time/timer.c:977! [ 318.910226] invalid opcode: 0000 [#1] SMP [ 318.910249] Modules linked in: bridge stp llc intel_rapl iosf_mbi x86_pkg_temp_thermal coretemp kvm_intel kvm ipmi_ssif crct10dif_pclmul crc32_pclmul iTCO_wdt iTCO_vendor_support joydev mei_me mei sb_edac shpchp ipmi_si lpc_ich i2c_i801 edac_core tpm_tis wmi ipmi_msghandler tpm acpi_power_meter acpi_pad nfsd auth_rpcgss nfs_acl lockd grace sunrpc xfs libcrc32c mlx4_en vxlan ip6_udp_tunnel udp_tunnel ast drm_kms_helper ttm crc32c_intel igb drm mlx4_core ptp nvme pps_core dca i2c_algo_bit fjes [last unloaded: iptable_security] [ 318.910588] CPU: 22 PID: 3402 Comm: nfsd Tainted: G W 4.3.0-0.rc7.git0.1.fc24.x86_64 #1 [ 318.910629] Hardware name: Quanta D51B/D51BP (1G LOM), BIOS S2BP3A05 01/29/2015 [ 318.910664] task: ffff880322c49e00 ti: ffff880322d0c000 task.ti: ffff880322d0c000 [ 318.910698] RIP: 0010:[<ffffffff811076a6>] [<ffffffff811076a6>] add_timer_on+0xc6/0x110 [ 318.910736] RSP: 0018:ffff880322d0f458 EFLAGS: 00010082 [ 318.910761] RAX: 0000000000000000 RBX: 0000000000000016 RCX: 0000000100021e85 [ 318.910793] RDX: ffffffffa03623c0 RSI: 0000000000000016 RDI: ffffffffa03623e0 [ 318.910826] RBP: ffff880322d0f488 R08: 000000000000000a R09: 00000000000005f2 [ 318.910856] R10: 000000000000027c R11: 00000000000005f2 R12: ffff88085f48fc00 [ 318.910888] R13: ffff88085fd8e080 R14: ffff88085f48fc00 R15: 000000000001d4c0 [ 318.910922] FS: 0000000000000000(0000) GS:ffff88085fd80000(0000) knlGS:0000000000000000 [ 318.910956] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 318.910981] CR2: 00007f9d6ea41000 CR3: 0000000001c0b000 CR4: 00000000001406e0 [ 318.911012] Stack: [ 318.911025] ffff88085f48fc00 0000000000000016 ffff88085f48fc00 ffffffffa03623e0 [ 318.911069] ffff88085f48fc00 000000000001d4c0 ffff880322d0f4c0 ffffffff810b6749 [ 318.911111] 000000000001d4c0 ffffffffa03623c0 0000000000000001 ffffffffa03623c0 [ 318.911153] Call Trace: [ 318.911170] [<ffffffff810b6749>] __queue_delayed_work+0x89/0x190 [ 318.911201] [<ffffffff810b70de>] mod_delayed_work_on+0x5e/0xa0 [ 318.911236] [<ffffffffa0333394>] prune_cache_entries+0x94/0xb0 [nfsd] [ 318.911267] [<ffffffffa03333be>] nfsd_reply_cache_scan+0xe/0x10 [nfsd] [ 318.911299] [<ffffffff811b78e2>] shrink_slab.part.42+0x1e2/0x380 [ 318.911330] [<ffffffff811bbfc6>] shrink_zone+0x2b6/0x2c0 [ 318.911358] [<ffffffff811bc145>] do_try_to_free_pages+0x175/0x400 [ 318.911391] [<ffffffff811bc4da>] try_to_free_pages+0x10a/0x150 [ 318.911422] [<ffffffff811ae5b1>] __alloc_pages_nodemask+0x581/0x990 [ 318.911454] [<ffffffff811b19f5>] ? account_page_dirtied+0xd5/0x160 [ 318.911483] [<ffffffff811f7b41>] alloc_pages_current+0x91/0x100 [ 318.911513] [<ffffffff811a45bb>] __page_cache_alloc+0xab/0xe0 [ 318.911543] [<ffffffff811a4c94>] pagecache_get_page+0x84/0x1e0 [ 318.911573] [<ffffffff811a4e16>] grab_cache_page_write_begin+0x26/0x40 [ 318.911620] [<ffffffffa0221cd4>] xfs_vm_write_begin+0x34/0xe0 [xfs] [ 318.911661] [<ffffffffa0221a39>] ? xfs_vm_write_end+0x29/0x80 [xfs] [ 318.912748] [<ffffffff811a418e>] generic_perform_write+0xce/0x1c0 [ 318.913810] [<ffffffffa022efb7>] xfs_file_buffered_aio_write+0x127/0x250 [xfs] [ 318.914858] [<ffffffffa032be60>] ? nfserrno+0x60/0x60 [nfsd] [ 318.915715] [<ffffffff812035e9>] ? __kmalloc+0x1b9/0x260 [ 318.916360] [<ffffffff81223617>] ? rw_copy_check_uvector+0x57/0x110 [ 318.917014] [<ffffffffa022f1d5>] xfs_file_write_iter+0xf5/0x110 [xfs] [ 318.917650] [<ffffffff81221e3c>] do_iter_readv_writev+0x6c/0xa0 [ 318.918312] [<ffffffff812229bf>] do_readv_writev+0x18f/0x230 [ 318.918954] [<ffffffffa022f0e0>] ? xfs_file_buffered_aio_write+0x250/0x250 [xfs] [ 318.919575] [<ffffffff813284bb>] ? security_file_open+0x8b/0x90 [ 318.920178] [<ffffffff8121ffa4>] ? do_dentry_open+0x264/0x2f0 [ 318.920771] [<ffffffffa022ced0>] ? xfs_extent_busy_ag_cmp+0x20/0x20 [xfs] [ 318.921354] [<ffffffff81222ae9>] vfs_writev+0x39/0x50 [ 318.921961] [<ffffffffa032df4d>] nfsd_vfs_write+0xbd/0x380 [nfsd] [ 318.922509] [<ffffffffa0330568>] nfsd_write+0xd8/0xf0 [nfsd] [ 318.923045] [<ffffffffa03367fc>] nfsd3_proc_write+0xbc/0x150 [nfsd] [ 318.923574] [<ffffffffa0328e68>] nfsd_dispatch+0xb8/0x200 [nfsd] [ 318.924111] [<ffffffffa02d39dc>] svc_process_common+0x40c/0x650 [sunrpc] [ 318.924633] [<ffffffffa02d4b14>] svc_process+0xf4/0x180 [sunrpc] [ 318.925144] [<ffffffffa03288bf>] nfsd+0xef/0x160 [nfsd] [ 318.925654] [<ffffffffa03287d0>] ? nfsd_destroy+0x60/0x60 [nfsd] [ 318.926163] [<ffffffff810bd6a8>] kthread+0xd8/0xf0 [ 318.926668] [<ffffffff810bd5d0>] ? kthread_worker_fn+0x160/0x160 [ 318.927189] [<ffffffff8177f19f>] ret_from_fork+0x3f/0x70 [ 318.927685] [<ffffffff810bd5d0>] ? kthread_worker_fn+0x160/0x160 [ 318.928210] Code: 4d 85 c0 75 e4 48 89 de 4c 89 ef e8 55 f9 ff ff 48 8b 34 24 4c 89 ef e8 19 72 67 00 48 83 c4 08 5b 41 5c 41 5d 41 5e 41 5f 5d c3 <0f> 0b 48 83 7f 38 00 48 8b 45 08 0f 85 5f ff ff ff 48 89 47 38 [ 318.929315] RIP [<ffffffff811076a6>] add_timer_on+0xc6/0x110 [ 318.930019] RSP <ffff880322d0f458> Basically the shrinker kicked in. After we shrank a bunch of cache entries, we tried to mod_delayed_work on the cache cleaner job so that it wouldn't run too soon, and that's where the code oopsed. Is our usage of mod_delayed_work in prune_cache_entries() wrong in some way? Or is there some breakage in the workqueue or timer code? -- Jeff Layton <jlayton@poochiereds.net> -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
[toc] | [next] | [standalone]
| From | Jeff Layton <jlayton@poochiereds.net> |
|---|---|
| Date | 2015-10-29 19:00 +0100 |
| Message-ID | <qoZEt-3ix-1@gated-at.bofh.it> |
| In reply to | #1258835 |
On Thu, 29 Oct 2015 10:31:13 -0400
Jeff Layton <jlayton@poochiereds.net> wrote:
> Our QA guys hit the following warning and oops today on a relatively
> recent upstream kernel. They were running a fairly busy NFSv3 I/O test
> against this server:
>
> [ 71.074180] NFSD: starting 90-second grace period (net ffffffff81cf3b40)
> [ 221.146802] Ebtables v2.0 unregistered
> [ 318.909835] ------------[ cut here ]------------
> [ 318.909846] WARNING: CPU: 22 PID: 3402 at kernel/workqueue.c:1444 __queue_delayed_work+0xe7/0x190()
> [ 318.909848] Modules linked in: bridge stp llc intel_rapl iosf_mbi x86_pkg_temp_thermal coretemp kvm_intel kvm ipmi_ssif crct10dif_pclmul crc32_pclmul iTCO_wdt iTCO_vendor_support joydev mei_me mei sb_edac shpchp ipmi_si lpc_ich i2c_i801 edac_core tpm_tis wmi ipmi_msghandler tpm acpi_power_meter acpi_pad nfsd auth_rpcgss nfs_acl lockd grace sunrpc xfs libcrc32c mlx4_en vxlan ip6_udp_tunnel udp_tunnel ast drm_kms_helper ttm crc32c_intel igb drm mlx4_core ptp nvme pps_core dca i2c_algo_bit fjes [last unloaded: iptable_security]
> [ 318.909889] CPU: 22 PID: 3402 Comm: nfsd Not tainted 4.3.0-0.rc7.git0.1.fc24.x86_64 #1
> [ 318.909891] Hardware name: Quanta D51B/D51BP (1G LOM), BIOS S2BP3A05 01/29/2015
> [ 318.909892] 0000000000000000 00000000319846b5 ffff880322d0f440 ffffffff813a48cf
> [ 318.909895] 0000000000000000 ffff880322d0f478 ffffffff8109f122 0000000000000400
> [ 318.909898] ffff88085f48fc00 ffffffffa03623e0 ffff88085f48fc00 000000000001d4c0
> [ 318.909901] Call Trace:
> [ 318.909906] [<ffffffff813a48cf>] dump_stack+0x44/0x55
> [ 318.909909] [<ffffffff8109f122>] warn_slowpath_common+0x82/0xc0
> [ 318.909913] [<ffffffff8109f26a>] warn_slowpath_null+0x1a/0x20
> [ 318.909915] [<ffffffff810b67a7>] __queue_delayed_work+0xe7/0x190
> [ 318.909917] [<ffffffff810b70de>] mod_delayed_work_on+0x5e/0xa0
> [ 318.909931] [<ffffffffa0333394>] prune_cache_entries+0x94/0xb0 [nfsd]
> [ 318.909936] [<ffffffffa03333be>] nfsd_reply_cache_scan+0xe/0x10 [nfsd]
> [ 318.909941] [<ffffffff811b78e2>] shrink_slab.part.42+0x1e2/0x380
> [ 318.909944] [<ffffffff811bbfc6>] shrink_zone+0x2b6/0x2c0
> [ 318.909946] [<ffffffff811bc145>] do_try_to_free_pages+0x175/0x400
> [ 318.909949] [<ffffffff811bc4da>] try_to_free_pages+0x10a/0x150
> [ 318.909954] [<ffffffff811ae5b1>] __alloc_pages_nodemask+0x581/0x990
> [ 318.909957] [<ffffffff811b19f5>] ? account_page_dirtied+0xd5/0x160
> [ 318.909960] [<ffffffff811f7b41>] alloc_pages_current+0x91/0x100
> [ 318.909963] [<ffffffff811a45bb>] __page_cache_alloc+0xab/0xe0
> [ 318.909965] [<ffffffff811a4c94>] pagecache_get_page+0x84/0x1e0
> [ 318.909967] [<ffffffff811a4e16>] grab_cache_page_write_begin+0x26/0x40
> [ 318.909990] [<ffffffffa0221cd4>] xfs_vm_write_begin+0x34/0xe0 [xfs]
> [ 318.910005] [<ffffffffa0221a39>] ? xfs_vm_write_end+0x29/0x80 [xfs]
> [ 318.910007] [<ffffffff811a418e>] generic_perform_write+0xce/0x1c0
> [ 318.910023] [<ffffffffa022efb7>] xfs_file_buffered_aio_write+0x127/0x250 [xfs]
> [ 318.910028] [<ffffffffa032be60>] ? nfserrno+0x60/0x60 [nfsd]
> [ 318.910031] [<ffffffff812035e9>] ? __kmalloc+0x1b9/0x260
> [ 318.910034] [<ffffffff81223617>] ? rw_copy_check_uvector+0x57/0x110
> [ 318.910047] [<ffffffffa022f1d5>] xfs_file_write_iter+0xf5/0x110 [xfs]
> [ 318.910050] [<ffffffff81221e3c>] do_iter_readv_writev+0x6c/0xa0
> [ 318.910053] [<ffffffff812229bf>] do_readv_writev+0x18f/0x230
> [ 318.910065] [<ffffffffa022f0e0>] ? xfs_file_buffered_aio_write+0x250/0x250 [xfs]
> [ 318.910068] [<ffffffff813284bb>] ? security_file_open+0x8b/0x90
> [ 318.910070] [<ffffffff8121ffa4>] ? do_dentry_open+0x264/0x2f0
> [ 318.910084] [<ffffffffa022ced0>] ? xfs_extent_busy_ag_cmp+0x20/0x20 [xfs]
> [ 318.910086] [<ffffffff81222ae9>] vfs_writev+0x39/0x50
> [ 318.910092] [<ffffffffa032df4d>] nfsd_vfs_write+0xbd/0x380 [nfsd]
> [ 318.910097] [<ffffffffa0330568>] nfsd_write+0xd8/0xf0 [nfsd]
> [ 318.910103] [<ffffffffa03367fc>] nfsd3_proc_write+0xbc/0x150 [nfsd]
> [ 318.910107] [<ffffffffa0328e68>] nfsd_dispatch+0xb8/0x200 [nfsd]
> [ 318.910128] [<ffffffffa02d39dc>] svc_process_common+0x40c/0x650 [sunrpc]
> [ 318.910137] [<ffffffffa02d4b14>] svc_process+0xf4/0x180 [sunrpc]
> [ 318.910142] [<ffffffffa03288bf>] nfsd+0xef/0x160 [nfsd]
> [ 318.910146] [<ffffffffa03287d0>] ? nfsd_destroy+0x60/0x60 [nfsd]
> [ 318.910149] [<ffffffff810bd6a8>] kthread+0xd8/0xf0
> [ 318.910152] [<ffffffff810bd5d0>] ? kthread_worker_fn+0x160/0x160
> [ 318.910155] [<ffffffff8177f19f>] ret_from_fork+0x3f/0x70
> [ 318.910158] [<ffffffff810bd5d0>] ? kthread_worker_fn+0x160/0x160
> [ 318.910160] ---[ end trace db375019f3368852 ]---
> [ 318.910169] ------------[ cut here ]------------
> [ 318.910201] kernel BUG at kernel/time/timer.c:977!
> [ 318.910226] invalid opcode: 0000 [#1] SMP
> [ 318.910249] Modules linked in: bridge stp llc intel_rapl iosf_mbi x86_pkg_temp_thermal coretemp kvm_intel kvm ipmi_ssif crct10dif_pclmul crc32_pclmul iTCO_wdt iTCO_vendor_support joydev mei_me mei sb_edac shpchp ipmi_si lpc_ich i2c_i801 edac_core tpm_tis wmi ipmi_msghandler tpm acpi_power_meter acpi_pad nfsd auth_rpcgss nfs_acl lockd grace sunrpc xfs libcrc32c mlx4_en vxlan ip6_udp_tunnel udp_tunnel ast drm_kms_helper ttm crc32c_intel igb drm mlx4_core ptp nvme pps_core dca i2c_algo_bit fjes [last unloaded: iptable_security]
> [ 318.910588] CPU: 22 PID: 3402 Comm: nfsd Tainted: G W 4.3.0-0.rc7.git0.1.fc24.x86_64 #1
> [ 318.910629] Hardware name: Quanta D51B/D51BP (1G LOM), BIOS S2BP3A05 01/29/2015
> [ 318.910664] task: ffff880322c49e00 ti: ffff880322d0c000 task.ti: ffff880322d0c000
> [ 318.910698] RIP: 0010:[<ffffffff811076a6>] [<ffffffff811076a6>] add_timer_on+0xc6/0x110
> [ 318.910736] RSP: 0018:ffff880322d0f458 EFLAGS: 00010082
> [ 318.910761] RAX: 0000000000000000 RBX: 0000000000000016 RCX: 0000000100021e85
> [ 318.910793] RDX: ffffffffa03623c0 RSI: 0000000000000016 RDI: ffffffffa03623e0
> [ 318.910826] RBP: ffff880322d0f488 R08: 000000000000000a R09: 00000000000005f2
> [ 318.910856] R10: 000000000000027c R11: 00000000000005f2 R12: ffff88085f48fc00
> [ 318.910888] R13: ffff88085fd8e080 R14: ffff88085f48fc00 R15: 000000000001d4c0
> [ 318.910922] FS: 0000000000000000(0000) GS:ffff88085fd80000(0000) knlGS:0000000000000000
> [ 318.910956] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 318.910981] CR2: 00007f9d6ea41000 CR3: 0000000001c0b000 CR4: 00000000001406e0
> [ 318.911012] Stack:
> [ 318.911025] ffff88085f48fc00 0000000000000016 ffff88085f48fc00 ffffffffa03623e0
> [ 318.911069] ffff88085f48fc00 000000000001d4c0 ffff880322d0f4c0 ffffffff810b6749
> [ 318.911111] 000000000001d4c0 ffffffffa03623c0 0000000000000001 ffffffffa03623c0
> [ 318.911153] Call Trace:
> [ 318.911170] [<ffffffff810b6749>] __queue_delayed_work+0x89/0x190
> [ 318.911201] [<ffffffff810b70de>] mod_delayed_work_on+0x5e/0xa0
> [ 318.911236] [<ffffffffa0333394>] prune_cache_entries+0x94/0xb0 [nfsd]
> [ 318.911267] [<ffffffffa03333be>] nfsd_reply_cache_scan+0xe/0x10 [nfsd]
> [ 318.911299] [<ffffffff811b78e2>] shrink_slab.part.42+0x1e2/0x380
> [ 318.911330] [<ffffffff811bbfc6>] shrink_zone+0x2b6/0x2c0
> [ 318.911358] [<ffffffff811bc145>] do_try_to_free_pages+0x175/0x400
> [ 318.911391] [<ffffffff811bc4da>] try_to_free_pages+0x10a/0x150
> [ 318.911422] [<ffffffff811ae5b1>] __alloc_pages_nodemask+0x581/0x990
> [ 318.911454] [<ffffffff811b19f5>] ? account_page_dirtied+0xd5/0x160
> [ 318.911483] [<ffffffff811f7b41>] alloc_pages_current+0x91/0x100
> [ 318.911513] [<ffffffff811a45bb>] __page_cache_alloc+0xab/0xe0
> [ 318.911543] [<ffffffff811a4c94>] pagecache_get_page+0x84/0x1e0
> [ 318.911573] [<ffffffff811a4e16>] grab_cache_page_write_begin+0x26/0x40
> [ 318.911620] [<ffffffffa0221cd4>] xfs_vm_write_begin+0x34/0xe0 [xfs]
> [ 318.911661] [<ffffffffa0221a39>] ? xfs_vm_write_end+0x29/0x80 [xfs]
> [ 318.912748] [<ffffffff811a418e>] generic_perform_write+0xce/0x1c0
> [ 318.913810] [<ffffffffa022efb7>] xfs_file_buffered_aio_write+0x127/0x250 [xfs]
> [ 318.914858] [<ffffffffa032be60>] ? nfserrno+0x60/0x60 [nfsd]
> [ 318.915715] [<ffffffff812035e9>] ? __kmalloc+0x1b9/0x260
> [ 318.916360] [<ffffffff81223617>] ? rw_copy_check_uvector+0x57/0x110
> [ 318.917014] [<ffffffffa022f1d5>] xfs_file_write_iter+0xf5/0x110 [xfs]
> [ 318.917650] [<ffffffff81221e3c>] do_iter_readv_writev+0x6c/0xa0
> [ 318.918312] [<ffffffff812229bf>] do_readv_writev+0x18f/0x230
> [ 318.918954] [<ffffffffa022f0e0>] ? xfs_file_buffered_aio_write+0x250/0x250 [xfs]
> [ 318.919575] [<ffffffff813284bb>] ? security_file_open+0x8b/0x90
> [ 318.920178] [<ffffffff8121ffa4>] ? do_dentry_open+0x264/0x2f0
> [ 318.920771] [<ffffffffa022ced0>] ? xfs_extent_busy_ag_cmp+0x20/0x20 [xfs]
> [ 318.921354] [<ffffffff81222ae9>] vfs_writev+0x39/0x50
> [ 318.921961] [<ffffffffa032df4d>] nfsd_vfs_write+0xbd/0x380 [nfsd]
> [ 318.922509] [<ffffffffa0330568>] nfsd_write+0xd8/0xf0 [nfsd]
> [ 318.923045] [<ffffffffa03367fc>] nfsd3_proc_write+0xbc/0x150 [nfsd]
> [ 318.923574] [<ffffffffa0328e68>] nfsd_dispatch+0xb8/0x200 [nfsd]
> [ 318.924111] [<ffffffffa02d39dc>] svc_process_common+0x40c/0x650 [sunrpc]
> [ 318.924633] [<ffffffffa02d4b14>] svc_process+0xf4/0x180 [sunrpc]
> [ 318.925144] [<ffffffffa03288bf>] nfsd+0xef/0x160 [nfsd]
> [ 318.925654] [<ffffffffa03287d0>] ? nfsd_destroy+0x60/0x60 [nfsd]
> [ 318.926163] [<ffffffff810bd6a8>] kthread+0xd8/0xf0
> [ 318.926668] [<ffffffff810bd5d0>] ? kthread_worker_fn+0x160/0x160
> [ 318.927189] [<ffffffff8177f19f>] ret_from_fork+0x3f/0x70
> [ 318.927685] [<ffffffff810bd5d0>] ? kthread_worker_fn+0x160/0x160
> [ 318.928210] Code: 4d 85 c0 75 e4 48 89 de 4c 89 ef e8 55 f9 ff ff 48 8b 34 24 4c 89 ef e8 19 72 67 00 48 83 c4 08 5b 41 5c 41 5d 41 5e 41 5f 5d c3 <0f> 0b 48 83 7f 38 00 48 8b 45 08 0f 85 5f ff ff ff 48 89 47 38
> [ 318.929315] RIP [<ffffffff811076a6>] add_timer_on+0xc6/0x110
> [ 318.930019] RSP <ffff880322d0f458>
>
> Basically the shrinker kicked in. After we shrank a bunch of cache
> entries, we tried to mod_delayed_work on the cache cleaner job so that
> it wouldn't run too soon, and that's where the code oopsed.
>
> Is our usage of mod_delayed_work in prune_cache_entries() wrong in some
> way? Or is there some breakage in the workqueue or timer code?
>
Ok, a bit more analysis...
We did get a vmcore from this. Here is the "cache_cleaner" delayed work:
crash> p cache_cleaner
cache_cleaner = $12 = {
work = {
data = {
counter = 0xfffffffe1
},
entry = {
next = 0xffffffffa03623c8 <cache_cleaner+8>,
prev = 0xffffffffa03623c8 <cache_cleaner+8>
},
func = 0xffffffffa03333c0 <cache_cleaner_func>
},
timer = {
entry = {
next = 0x0,
pprev = 0xffff88085fd0eaf8
},
expires = 0x100021e99,
function = 0xffffffff810b66a0 <delayed_work_timer_fn>,
data = 0xffffffffa03623c0,
flags = 0x200014,
slack = 0xffffffff,
start_pid = 0x0,
start_site = 0x0,
start_comm = "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
},
wq = 0xffff88085f48fc00,
cpu = 0x14
}
So the PENDING bit is set (lowest bit in data.counter), and timer->entry.pprev
pprev pointer is not NULL (so timer_pending is true). I also see that
there are several nfsd threads running the shrinker at the same time.
There is one potential problem that I see, but I'd appreciate someone
sanity checking me on this. Here is mod_delayed_work_on:
------------------[snip]------------------------
bool mod_delayed_work_on(int cpu, struct workqueue_struct *wq,
struct delayed_work *dwork, unsigned long delay)
{
unsigned long flags;
int ret;
do {
ret = try_to_grab_pending(&dwork->work, true, &flags);
} while (unlikely(ret == -EAGAIN));
if (likely(ret >= 0)) {
__queue_delayed_work(cpu, wq, dwork, delay);
local_irq_restore(flags);
}
/* -ENOENT from try_to_grab_pending() becomes %true */
return ret;
}
------------------[snip]------------------------
...and here is the beginning of try_to_grab_pending:
------------------[snip]------------------------
/* try to steal the timer if it exists */
if (is_dwork) {
struct delayed_work *dwork = to_delayed_work(work);
/*
* dwork->timer is irqsafe. If del_timer() fails, it's
* guaranteed that the timer is not queued anywhere and not
* running on the local CPU.
*/
if (likely(del_timer(&dwork->timer)))
return 1;
}
/* try to claim PENDING the normal way */
if (!test_and_set_bit(WORK_STRUCT_PENDING_BIT, work_data_bits(work)))
return 0;
------------------[snip]------------------------
...so if del_timer returns true, we'll return 1 from
try_to_grab_pending without actually setting the
WORK_STRUCT_PENDING_BIT, and then will end up calling
__queue_delayed_work.
That seems wrong to me -- shouldn't we be ensuring that that bit is set
when returning 1 from try_to_grab_pending to guard against concurrent
queue_delayed_work_on calls?
--
Jeff Layton <jlayton@poochiereds.net>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | Tejun Heo <tj@kernel.org> |
|---|---|
| Date | 2015-10-31 03:10 +0100 |
| Message-ID | <qptMd-5iJ-1@gated-at.bofh.it> |
| In reply to | #1258938 |
(cc'ing Lai)
Hello, Jeff.
On Thu, Oct 29, 2015 at 01:58:36PM -0400, Jeff Layton wrote:
> crash> p cache_cleaner
> cache_cleaner = $12 = {
> work = {
> data = {
> counter = 0xfffffffe1
If I'm not mistaken, PENDING, flush color 14, OFFQ and POOL_NONE.
> },
> entry = {
> next = 0xffffffffa03623c8 <cache_cleaner+8>,
> prev = 0xffffffffa03623c8 <cache_cleaner+8>
Empty entry.
> },
> func = 0xffffffffa03333c0 <cache_cleaner_func>
> },
> timer = {
> entry = {
> next = 0x0,
> pprev = 0xffff88085fd0eaf8
> },
> expires = 0x100021e99,
> function = 0xffffffff810b66a0 <delayed_work_timer_fn>,
> data = 0xffffffffa03623c0,
> flags = 0x200014,
> slack = 0xffffffff,
> start_pid = 0x0,
> start_site = 0x0,
> start_comm = "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
> },
> wq = 0xffff88085f48fc00,
> cpu = 0x14
> }
>
> So the PENDING bit is set (lowest bit in data.counter), and timer->entry.pprev
> pprev pointer is not NULL (so timer_pending is true). I also see that
> there are several nfsd threads running the shrinker at the same time.
>
> There is one potential problem that I see, but I'd appreciate someone
> sanity checking me on this. Here is mod_delayed_work_on:
...
> ...and here is the beginning of try_to_grab_pending:
>
> ------------------[snip]------------------------
> /* try to steal the timer if it exists */
> if (is_dwork) {
> struct delayed_work *dwork = to_delayed_work(work);
>
> /*
> * dwork->timer is irqsafe. If del_timer() fails, it's
> * guaranteed that the timer is not queued anywhere and not
> * running on the local CPU.
> */
> if (likely(del_timer(&dwork->timer)))
> return 1;
> }
>
> /* try to claim PENDING the normal way */
> if (!test_and_set_bit(WORK_STRUCT_PENDING_BIT, work_data_bits(work)))
> return 0;
> ------------------[snip]------------------------
>
>
> ...so if del_timer returns true, we'll return 1 from
> try_to_grab_pending without actually setting the
> WORK_STRUCT_PENDING_BIT, and then will end up calling
> __queue_delayed_work.
>
> That seems wrong to me -- shouldn't we be ensuring that that bit is set
> when returning 1 from try_to_grab_pending to guard against concurrent
> queue_delayed_work_on calls?
But if try_to_grab_pending() succeeded at stealing dwork->timer, it's
known that the PENDING bit must already be set. IOW, the bit is
stolen together with the timer.
Heh, this one is tricky. Yeah, try_to_grab_pending() missing PENDING
would explain the failure but I can't see how it'd leak at the moment.
Thanks.
--
tejun
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [next] | [standalone]
| From | Jeff Layton <jlayton@poochiereds.net> |
|---|---|
| Date | 2015-10-31 12:40 +0100 |
| Message-ID | <qpCFP-2fo-11@gated-at.bofh.it> |
| In reply to | #1259897 |
On Sat, 31 Oct 2015 11:00:12 +0900
Tejun Heo <tj@kernel.org> wrote:
> (cc'ing Lai)
>
> Hello, Jeff.
>
> On Thu, Oct 29, 2015 at 01:58:36PM -0400, Jeff Layton wrote:
> > crash> p cache_cleaner
> > cache_cleaner = $12 = {
> > work = {
> > data = {
> > counter = 0xfffffffe1
>
> If I'm not mistaken, PENDING, flush color 14, OFFQ and POOL_NONE.
>
> > },
> > entry = {
> > next = 0xffffffffa03623c8 <cache_cleaner+8>,
> > prev = 0xffffffffa03623c8 <cache_cleaner+8>
>
> Empty entry.
>
> > },
> > func = 0xffffffffa03333c0 <cache_cleaner_func>
> > },
> > timer = {
> > entry = {
> > next = 0x0,
> > pprev = 0xffff88085fd0eaf8
> > },
> > expires = 0x100021e99,
> > function = 0xffffffff810b66a0 <delayed_work_timer_fn>,
> > data = 0xffffffffa03623c0,
> > flags = 0x200014,
> > slack = 0xffffffff,
> > start_pid = 0x0,
> > start_site = 0x0,
> > start_comm = "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
> > },
> > wq = 0xffff88085f48fc00,
> > cpu = 0x14
> > }
> >
> > So the PENDING bit is set (lowest bit in data.counter), and timer->entry.pprev
> > pprev pointer is not NULL (so timer_pending is true). I also see that
> > there are several nfsd threads running the shrinker at the same time.
> >
> > There is one potential problem that I see, but I'd appreciate someone
> > sanity checking me on this. Here is mod_delayed_work_on:
> ...
> > ...and here is the beginning of try_to_grab_pending:
> >
> > ------------------[snip]------------------------
> > /* try to steal the timer if it exists */
> > if (is_dwork) {
> > struct delayed_work *dwork = to_delayed_work(work);
> >
> > /*
> > * dwork->timer is irqsafe. If del_timer() fails, it's
> > * guaranteed that the timer is not queued anywhere and not
> > * running on the local CPU.
> > */
> > if (likely(del_timer(&dwork->timer)))
> > return 1;
> > }
> >
> > /* try to claim PENDING the normal way */
> > if (!test_and_set_bit(WORK_STRUCT_PENDING_BIT, work_data_bits(work)))
> > return 0;
> > ------------------[snip]------------------------
> >
> >
> > ...so if del_timer returns true, we'll return 1 from
> > try_to_grab_pending without actually setting the
> > WORK_STRUCT_PENDING_BIT, and then will end up calling
> > __queue_delayed_work.
> >
> > That seems wrong to me -- shouldn't we be ensuring that that bit is set
> > when returning 1 from try_to_grab_pending to guard against concurrent
> > queue_delayed_work_on calls?
>
> But if try_to_grab_pending() succeeded at stealing dwork->timer, it's
> known that the PENDING bit must already be set. IOW, the bit is
> stolen together with the timer.
>
> Heh, this one is tricky. Yeah, try_to_grab_pending() missing PENDING
> would explain the failure but I can't see how it'd leak at the moment.
>
Thanks Tejun. Yeah, I realized that after sending the response above.
If you successfully delete the timer the timer then the PENDING bit
should already be set. Might be worth throwing in something like this,
just before the return 1:
WARN_ON(!test_bit(WORK_STRUCT_PENDING_BIT, work_data_bits(work)))
...but I doubt it would fire. I think it's likely that the bug is
elsewhere.
The other thing is that we've had this code in place for a couple of
years now, and this is the first time I've seen an oops like this. I
suspect that this may be a recent regression, but I don't know that for
sure.
I have asked Chris and Michael to see if they can bisect it down, but
it may be a bit before they can get that done. Any insight you might
have in the meantime would helpful.
--
Jeff Layton <jlayton@poochiereds.net>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web