[LU-5278] ZFS - many OST watchdogs with IOR

• Type: Bug
• Resolution: Fixed
• Priority: Critical
• Fix Version/s: Lustre 2.8.0
• Affects Version/s: Lustre 2.6.0
• Labels: MB llnl prz zfs
• Environment: Hyperion/LLNL
• Severity: 3
• Assignee: Alex Zhuravlev
• Reporter: Cliff White (Inactive)

Description

Running IOR with 100 clients. Performance is terrible. OSTs are wedging and dropping watchdogs.
Example:

2014-07-01 08:22:47 LNet: Service thread pid 8308 was inactive for 200.00s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
2014-07-01 08:22:47 Pid: 8308, comm: ll_ost_io00_014
2014-07-01 08:22:47
2014-07-01 08:22:47 Call Trace:
2014-07-01 08:22:47  [<ffffffffa05b34ba>] ? dmu_zfetch+0x51a/0xd70 [zfs]
2014-07-01 08:22:47  [<ffffffff810a6d01>] ? ktime_get_ts+0xb1/0xf0
2014-07-01 08:22:47  [<ffffffff815287f3>] io_schedule+0x73/0xc0
2014-07-01 08:22:47  [<ffffffffa04f841c>] cv_wait_common+0x8c/0x100 [spl]
2014-07-01 08:22:47  [<ffffffff8109af00>] ? autoremove_wake_function+0x0/0x40
2014-07-01 08:22:47  [<ffffffffa04f84a8>] __cv_wait_io+0x18/0x20 [spl]
2014-07-01 08:22:47  [<ffffffffa062f0ab>] zio_wait+0xfb/0x1b0 [zfs]
2014-07-01 08:22:47  [<ffffffffa05a503d>] dmu_buf_hold_array_by_dnode+0x19d/0x4c0 [zfs]
2014-07-01 08:22:47  [<ffffffffa05a5e68>] dmu_buf_hold_array_by_bonus+0x68/0x90 [zfs]
2014-07-01 08:22:47  [<ffffffffa0e3f1a3>] osd_bufs_get+0x493/0xb00 [osd_zfs]
2014-07-01 08:22:47  [<ffffffffa03be488>] ? libcfs_log_return+0x28/0x40 [libcfs]
2014-07-01 08:22:47  [<ffffffffa0f2e00b>] ofd_preprw_read+0x15b/0x890 [ofd]
2014-07-01 08:22:47  [<ffffffffa0f30709>] ofd_preprw+0x749/0x1650 [ofd]
2014-07-01 08:22:47  [<ffffffffa09d71b1>] obd_preprw.clone.3+0x121/0x390 [ptlrpc]
2014-07-01 08:22:47  [<ffffffffa09deb03>] tgt_brw_read+0x2d3/0x1150 [ptlrpc]
2014-07-01 08:22:47  [<ffffffffa03be488>] ? libcfs_log_return+0x28/0x40 [libcfs]
2014-07-01 08:22:47  [<ffffffffa097ab36>] ? lustre_pack_reply_v2+0x216/0x280 [ptlrpc]
2014-07-01 08:22:47  [<ffffffffa097ac4e>] ? lustre_pack_reply_flags+0xae/0x1f0 [ptlrpc]
2014-07-01 08:22:47  [<ffffffffa09dca7c>] tgt_request_handle+0x23c/0xac0 [ptlrpc]
2014-07-01 08:22:47  [<ffffffffa098c29a>] ptlrpc_main+0xd1a/0x1980 [ptlrpc]
2014-07-01 08:22:47  [<ffffffffa098b580>] ? ptlrpc_main+0x0/0x1980 [ptlrpc]
2014-07-01 08:22:47  [<ffffffff8109ab56>] kthread+0x96/0xa0
2014-07-01 08:22:47  [<ffffffff8100c20a>] child_rip+0xa/0x20
2014-07-01 08:22:47  [<ffffffff8109aac0>] ? kthread+0x0/0xa0
2014-07-01 08:22:47  [<ffffffff8100c200>] ? child_rip+0x0/0x20

Lustre dump attached.

Second example:

2014-07-01 09:38:41 Pid: 9299, comm: ll_ost_io00_070
2014-07-01 09:38:41
2014-07-01 09:38:41 Call Trace:
2014-07-01 09:38:41  [<ffffffffa05b02f7>] ? dmu_zfetch+0x357/0xd70 [zfs]
2014-07-01 09:38:41  [<ffffffffa05957f2>] ? arc_read+0x572/0x8d0 [zfs]
2014-07-01 09:38:41  [<ffffffff810a6d01>] ? ktime_get_ts+0xb1/0xf0
2014-07-01 09:38:41  [<ffffffff815287f3>] io_schedule+0x73/0xc0
2014-07-01 09:38:41  [<ffffffffa04f841c>] cv_wait_common+0x8c/0x100 [spl]
2014-07-01 09:38:41  [<ffffffff8109af00>] ? autoremove_wake_function+0x0/0x40
2014-07-01 09:38:41  [<ffffffffa04f84a8>] __cv_wait_io+0x18/0x20 [spl]
2014-07-01 09:38:41  [<ffffffffa062c0ab>] zio_wait+0xfb/0x1b0 [zfs]
2014-07-01 09:38:41  [<ffffffffa05a203d>] dmu_buf_hold_array_by_dnode+0x19d/0x4c0 [zfs]
2014-07-01 09:38:41  [<ffffffffa05a2e68>] dmu_buf_hold_array_by_bonus+0x68/0x90 [zfs]
2014-07-01 09:38:41  [<ffffffffa0e441a3>] osd_bufs_get+0x493/0xb00 [osd_zfs]
2014-07-01 09:38:41  [<ffffffffa03be488>] ? libcfs_log_return+0x28/0x40 [libcfs]
2014-07-01 09:38:41  [<ffffffffa0f3700b>] ofd_preprw_read+0x15b/0x890 [ofd]
2014-07-01 09:38:41  [<ffffffffa0f39709>] ofd_preprw+0x749/0x1650 [ofd]
2014-07-01 09:38:41  [<ffffffffa09d41b1>] obd_preprw.clone.3+0x121/0x390 [ptlrpc]
2014-07-01 09:38:41  [<ffffffffa09dbb03>] tgt_brw_read+0x2d3/0x1150 [ptlrpc]
2014-07-01 09:38:41  [<ffffffffa03be488>] ? libcfs_log_return+0x28/0x40 [libcfs]
2014-07-01 09:38:41  [<ffffffffa0977b36>] ? lustre_pack_reply_v2+0x216/0x280 [ptlrpc]
2014-07-01 09:38:41  [<ffffffffa0977c4e>] ? lustre_pack_reply_flags+0xae/0x1f0 [ptlrpc]
2014-07-01 09:38:41  [<ffffffffa09d9a7c>] tgt_request_handle+0x23c/0xac0 [ptlrpc]
2014-07-01 09:38:41  [<ffffffffa098929a>] ptlrpc_main+0xd1a/0x1980 [ptlrpc]
2014-07-01 09:38:41  [<ffffffffa0988580>] ? ptlrpc_main+0x0/0x1980 [ptlrpc]
2014-07-01 09:38:41  [<ffffffff8109ab56>] kthread+0x96/0xa0
2014-07-01 09:38:41  [<ffffffff8100c20a>] child_rip+0xa/0x20
2014-07-01 09:38:41  [<ffffffff8109aac0>] ? kthread+0x0/0xa0
2014-07-01 09:38:41  [<ffffffff8100c200>] ? child_rip+0x0/0x20
2014-07-01 09:38:41

Issue Links

• is duplicated by: LU-3109 ZFS - very slow reads, OST watchdogs
• is duplicated by: LU-5775 obdfilter-survey test 1c: lctl hung on OSS
• is related to: LU-6254 Fix OFD/OSD prefetch for osd-ldiskfs and osd-zfs
• is related to: LU-4820 extra memcpy in read path
• is related to: LU-6228 How to balance network connections across socknal_sd tasks?

Comments

[Peter Jones]

Landed for 2.8

[Gerrit Updater]

Oleg Drokin ([e-mail]) merged in patch http://review.whamcloud.com/13612/
Subject: LU-5278 echo: request pages in batches
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 89021de564c27f38a4146357e58dd80ddf68e246

[Alex Zhuravlev]

the following isn't exactly the same, but looks very similar:

13:06:17:INFO: task txg_sync:16276 blocked for more than 120 seconds.
13:06:17: Tainted: P --------------- 2.6.32-504.12.2.el6_lustre.g036b949.x86_64 #1
13:06:17:"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
13:06:17:txg_sync D 0000000000000001 0 16276 2 0x00000080
13:06:17: ffff88006de4b890 0000000000000046 ffff88006de4b820 ffffffff81041e98
13:06:17: 00000000ffffffff 000007051e05132a 0000000000000000 ffff88007918e980
13:06:17: 00000000002301ae ffffffffaad2f4da ffff88006fc5bab8 ffff88006de4bfd8
13:06:17:Call Trace:
13:06:17: [<ffffffff81041e98>] ? pvclock_clocksource_read+0x58/0xd0
13:06:17: [<ffffffff810aaa21>] ? ktime_get_ts+0xb1/0xf0
13:06:17: [<ffffffff8152aad3>] io_schedule+0x73/0xc0
13:06:17: [<ffffffffa0145596>] cv_wait_common+0xa6/0x120 [spl]
13:06:17: [<ffffffff8109eb00>] ? autoremove_wake_function+0x0/0x40
13:06:17: [<ffffffffa0145628>] __cv_wait_io+0x18/0x20 [spl]
13:08:18: [<ffffffffa028f81b>] zio_wait+0xfb/0x1c0 [zfs]
13:08:18: [<ffffffffa029134b>] zio_free+0xab/0xe0 [zfs]
13:08:18: [<ffffffffa02279a1>] dsl_free+0x11/0x20 [zfs]
13:08:18: [<ffffffffa021b102>] dsl_dataset_block_kill+0x352/0x380 [zfs]
13:08:18: [<ffffffffa0214bee>] free_blocks+0x6e/0xb0 [zfs]
13:08:18: [<ffffffffa0215838>] dnode_sync+0x4c8/0xac0 [zfs]
13:08:18: [<ffffffffa01fb3fb>] ? dbuf_sync_list+0x7b/0x80 [zfs]
13:08:18: [<ffffffffa01f034a>] ? arc_write+0xea/0x100 [zfs]
13:08:18: [<ffffffffa0204e49>] dmu_objset_sync_dnodes+0x89/0xb0 [zfs]
13:08:18: [<ffffffffa020503a>] dmu_objset_sync+0x1ca/0x2d0 [zfs]
13:08:18: [<ffffffffa02040c0>] ? dmu_objset_write_ready+0x0/0x50 [zfs]
13:08:18: [<ffffffffa0205140>] ? dmu_objset_write_done+0x0/0x70 [zfs]
13:08:18: [<ffffffffa0222b8b>] dsl_pool_sync+0x2ab/0x3f0 [zfs]
13:08:18: [<ffffffffa023b8bf>] spa_sync+0x40f/0xa70 [zfs]
13:08:18: [<ffffffffa0245771>] ? spa_txg_history_set+0xc1/0xf0 [zfs]
13:08:18: [<ffffffffa0248c7d>] txg_sync_thread+0x30d/0x520 [zfs]
13:08:18: [<ffffffff8105c2f9>] ? set_user_nice+0xc9/0x130
13:08:18: [<ffffffffa0248970>] ? txg_sync_thread+0x0/0x520 [zfs]

https://testing.hpdd.intel.com/test_logs/c128d706-e305-11e4-a348-5254006e85c2/show_text

[Cliff White (Inactive)]

/proc/spl from the MDS

[Cliff White (Inactive)]

Lustre-log dumped by watchdog, all files under /proc/spl on OST

[Cliff White (Inactive)]

Watchdogs continue with prefetch disabled.

LNet: Service thread pid 64826 was inactive for 200.00s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
Pid: 64826, comm: ll_ost03_025

Call Trace:
[<ffffffffa054f790>] ? vdev_mirror_child_done+0x0/0x30 [zfs]
[<ffffffff8152acee>] ? mutex_lock+0x1e/0x50
[<ffffffff8152acee>] ? mutex_lock+0x1e/0x50
[<ffffffff81529e83>] io_schedule+0x73/0xc0
[<ffffffffa044b596>] cv_wait_common+0xa6/0x120 [spl]
[<ffffffff8109afa0>] ? autoremove_wake_function+0x0/0x40
[<ffffffffa044b628>] __cv_wait_io+0x18/0x20 [spl]
[<ffffffffa058c81b>] zio_wait+0xfb/0x1c0 [zfs]
[<ffffffffa04f673a>] dbuf_read+0x47a/0x7f0 [zfs]
[<ffffffffa04fed98>] dmu_buf_hold+0x108/0x1d0 [zfs]
[<ffffffffa0555ab2>] zap_get_leaf_byblk+0x52/0x300 [zfs]
[<ffffffffa0554584>] ? zap_idx_to_blk+0xe4/0x150 [zfs]
[<ffffffffa0555dca>] zap_deref_leaf+0x6a/0x80 [zfs]
[<ffffffffa0556430>] fzap_lookup+0x60/0x120 [zfs]
[<ffffffffa05598f8>] ? zap_name_alloc+0x88/0xf0 [zfs]
[<ffffffffa055ba21>] zap_lookup_norm+0xe1/0x190 [zfs]
[<ffffffffa055bb63>] zap_lookup+0x33/0x40 [zfs]
[<ffffffffa108afa5>] osd_fid_lookup+0xb5/0x2f0 [osd_zfs]
[<ffffffffa1084a1c>] osd_object_init+0x19c/0x6c0 [osd_zfs]
[<ffffffffa03bb798>] ? libcfs_log_return+0x28/0x40 [libcfs]
[<ffffffffa0fac9d9>] ? ofd_object_init+0x99/0x180 [ofd]
[<ffffffffa07c6318>] lu_object_alloc+0xd8/0x320 [obdclass]
[<ffffffffa07c7821>] lu_object_find_try+0x151/0x260 [obdclass]
[<ffffffffa07c79e1>] lu_object_find_at+0xb1/0xe0 [obdclass]
[<ffffffffa03bf161>] ? libcfs_debug_msg+0x41/0x50 [libcfs]
[<ffffffffa07c7a26>] lu_object_find+0x16/0x20 [obdclass]
[<ffffffffa0fc3215>] ofd_object_find+0x35/0xf0 [ofd]
[<ffffffffa0fc5b0b>] ofd_precreate_objects+0x1fb/0x19e0 [ofd]
[<ffffffffa03bf161>] ? libcfs_debug_msg+0x41/0x50 [libcfs]
[<ffffffffa0fd2928>] ? ofd_grant_create+0x2b8/0x450 [ofd]
[<ffffffffa0fb6ca6>] ofd_create_hdl+0x566/0x25c0 [ofd]
[<ffffffffa09e78c0>] ? lustre_pack_reply_v2+0x220/0x280 [ptlrpc]
[<ffffffffa0a4946e>] tgt_request_handle+0x8be/0x1000 [ptlrpc]
[<ffffffffa09f8e61>] ptlrpc_main+0xe41/0x1960 [ptlrpc]
[<ffffffffa09f8020>] ? ptlrpc_main+0x0/0x1960 [ptlrpc]
[<ffffffff8109abf6>] kthread+0x96/0xa0
[<ffffffff8100c20a>] child_rip+0xa/0x20
[<ffffffff8109ab60>] ? kthread+0x0/0xa0
[<ffffffff8100c200>] ? child_rip+0x0/0x20

LustreError: dumping log to /tmp/lustre-log.1429199475.64826

[Cliff White (Inactive)]

I am a bit confused by all the network tuning comments. Are there patches available that have not landed in 2.7.52?

[Rick Wagner (Inactive)]

Andreas & Gabriele, I have moved my network tuning questions over to LU-6228.

[Gabriele Paciucci (Inactive)]

If you are using Ethernet, you should also tune the systctl.conf. Please refer to your Ethernet vendor. This is a good starting point from Mellanox but you can apply to other vendors.
http://www.mellanox.com/related-docs/prod_software/Performance_Tuning_Guide_for_Mellanox_Network_Adapters.pdf

[Rick Wagner (Inactive)]

Gabriele, thanks. There are negative numbers in /proc/sys/lnet/peers, and even bumping up the credits on the server gave 10% or so improvement. I'll have to shift to another set of clients to test both sides, since I'm using a production system nodes as clients and can't reload the kernel modules. This would help explain the remaining bottleneck.