task txg_sync blocked for more than 120 seconds #2934
Comments
|
i also met this issue,but we found that if pool offline one disk which is 100% util,the issue disapperce. |
|
This indicates that zfs was waiting a long time for IO to complete. As @inevity observed this can happen if you have a drive which hasn't failed yet but is behaving badly. You can look for this with |
|
@behlendorf Thanks for this insight, I will monitor the disks today and see if anything odd shows up. |
|
Okay, so I've done This does seem a bit slower than I've seen before.. but this isn't exactly a fast server. I don't see any error in the Similarly, The drives are reasonable and should be able to read around 60-100Mbytes/s, so not sure if this is expected behaviour or not. I will try to get a higher throughput by doing a backup of some large files and see if I can reproduce and get higher utilisation. If there is anything else I can do that is within my reach and will help, please let me know. |
|
@ioquatix You're going to want to replace sdf. Notice that that average wait time for writes (w_await) for that device is a massive 545ms. From the |
|
@behlendorf Thanks for that, I didn't know that.
If you can confirm that you think this issue is related to |
|
If the drives share a common controller or bus then it's absolutely possible that the |
|
@behlendorf You have been most helpful. I do believe they are on the same bus. I will rip out that drive and perform a ritual sacrifice with it, to bless the new drive :) I'll report back. |
|
@behlendorf , since upgrade to 0.6.3,we suffered this issue on three machine. Belowe is sar stat ,10 min interval.till 04:20:01 PM,the machine hung and panic reboot. |
|
@behlendorf I'm pretty sure that I saw these error messages with a drive that was sort of behaving badly and after a few weeks (or 1-2 months) later it wound up showing thousands of defect/reallocated sectors and then went unusable (continually producing errors, taking ages to do things) so that coincides with what @inevity observed, I remember a discussion where the problem with failing drives was the timeout and how Linux handles it compared to the other BSD operating systems - but couldn't find it after some times of searching perhaps it'll wind up later, then I'll post a reference here |
|
So, I've replaced that drive with another drive completely different brand and known (reasonably) good. And, the await time is still a bit high. I've tried three different ports on two controllers. For some reason I haven't seen the await time get less than about 150ms. This is a completely different drive and I guess I'm just wondering if that's normal if the drive is the boot drive and has a bunch of requests stacked against it. |
|
By the way, I haven't tested ZFS yet, but I'll see if it makes any difference and report back. |
|
Hmm, okay. So, I've been running Mostly looks okay IMHO. A few minutes into the rsync backup: |
|
iotop: Sometimes speed drops down for a brief period of time, then goes back up. I'm not sure if this coincides with the |
|
|
I just had a similar problem. My kernel has grsecurity and rsync seemed to stall while I could hear a lot of disk IO. But then I tried |
|
Hello, i'm having the same issue - im running ZFS 0.6.5 on CentOS 7.1. After rebooting the system i'm trying to import the pool. Pool import works: pool: dpool01
state: ONLINE
status: Some supported features are not enabled on the pool. The pool can
still be used, but some features are unavailable.
action: Enable all features using 'zpool upgrade'. Once this is done,
the pool may no longer be accessible by software that does not support
the features. See zpool-features(5) for details.
scan: scrub repaired 0 in 5h16m with 0 errors on Fri Aug 14 17:45:52 2015
config:
NAME STATE READ WRITE CKSUM
dpool01 ONLINE 0 0 0
mirror-0 ONLINE 0 0 0
scsi-350014ee30012ec8c ONLINE 0 0 0
scsi-350014ee355683358 ONLINE 0 0 0
errors: No known data errors
Mounting the filesystem runs for 2 hours now ... still processing. Mounting the pool read only works without problems. [Mi Sep 16 13:58:28 2015] INFO: task txg_sync:4015 blocked for more than 120 seconds. [Mi Sep 16 13:58:28 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Mi Sep 16 13:58:28 2015] txg_sync D ffff880ec5c13680 0 4015 2 0x00000080 [Mi Sep 16 13:58:28 2015] ffff8800d9897b90 0000000000000046 ffff880e5349cfa0 ffff8800d9897fd8 [Mi Sep 16 13:58:28 2015] ffff8800d9897fd8 ffff8800d9897fd8 ffff880e5349cfa0 ffff880ec5c13f48 [Mi Sep 16 13:58:28 2015] ffff880c42bccd88 ffff880c42bccdc8 ffff880c42bccdb0 0000000000000001 [Mi Sep 16 13:58:28 2015] Call Trace: [Mi Sep 16 13:58:28 2015] [] io_schedule+0x9d/0x130 [Mi Sep 16 13:58:28 2015] [] cv_wait_common+0xae/0x150 [spl] [Mi Sep 16 13:58:28 2015] [] ? wake_up_bit+0x30/0x30 [Mi Sep 16 13:58:28 2015] [] __cv_wait_io+0x18/0x20 [spl] [Mi Sep 16 13:58:28 2015] [] zio_wait+0x123/0x210 [zfs] [Mi Sep 16 13:58:28 2015] [] dsl_pool_sync+0xbf/0x420 [zfs] [Mi Sep 16 13:58:28 2015] [] spa_sync+0x388/0xb70 [zfs] [Mi Sep 16 13:58:28 2015] [] ? autoremove_wake_function+0x2b/0x40 [Mi Sep 16 13:58:28 2015] [] txg_sync_thread+0x3cc/0x640 [zfs] [Mi Sep 16 13:58:28 2015] [] ? txg_fini+0x2a0/0x2a0 [zfs] [Mi Sep 16 13:58:28 2015] [] thread_generic_wrapper+0x71/0x80 [spl] [Mi Sep 16 13:58:28 2015] [] ? __thread_exit+0x20/0x20 [spl] [Mi Sep 16 13:58:28 2015] [] kthread+0xcf/0xe0 [Mi Sep 16 13:58:28 2015] [] ? kthread_create_on_node+0x140/0x140 [Mi Sep 16 13:58:28 2015] [] ret_from_fork+0x58/0x90 [Mi Sep 16 13:58:28 2015] [] ? kthread_create_on_node+0x140/0x140 [Mi Sep 16 13:58:28 2015] INFO: task mount.zfs:4464 blocked for more than 120 seconds. [Mi Sep 16 13:58:28 2015] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [Mi Sep 16 13:58:28 2015] mount.zfs D ffff880ec5c13680 0 4464 4463 0x00000080 [Mi Sep 16 13:58:28 2015] ffff880e3e8e3860 0000000000000086 ffff880e465816c0 ffff880e3e8e3fd8 [Mi Sep 16 13:58:28 2015] ffff880e3e8e3fd8 ffff880e3e8e3fd8 ffff880e465816c0 ffff880e4540db68 [Mi Sep 16 13:58:28 2015] ffff880e4540da20 ffff880e4540db70 ffff880e4540da48 0000000000000000 [Mi Sep 16 13:58:28 2015] Call Trace: [Mi Sep 16 13:58:28 2015] [] schedule+0x29/0x70 [Mi Sep 16 13:58:28 2015] [] cv_wait_common+0x125/0x150 [spl] [Mi Sep 16 13:58:28 2015] [] ? wake_up_bit+0x30/0x30 [Mi Sep 16 13:58:28 2015] [] __cv_wait+0x15/0x20 [spl] [Mi Sep 16 13:58:28 2015] [] txg_wait_open+0xc3/0x110 [zfs] [Mi Sep 16 13:58:28 2015] [] dmu_tx_wait+0x3a8/0x3c0 [zfs] [Mi Sep 16 13:58:28 2015] [] dmu_tx_assign+0x9a/0x510 [zfs] [Mi Sep 16 13:58:28 2015] [] zfs_rmnode+0x161/0x350 [zfs] [Mi Sep 16 13:58:28 2015] [] ? mutex_lock+0x12/0x2f [Mi Sep 16 13:58:28 2015] [] zfs_zinactive+0x168/0x180 [zfs] [Mi Sep 16 13:58:28 2015] [] zfs_inactive+0x67/0x240 [zfs] [Mi Sep 16 13:58:28 2015] [] ? truncate_pagecache+0x59/0x60 [Mi Sep 16 13:58:28 2015] [] zpl_evict_inode+0x43/0x60 [zfs] [Mi Sep 16 13:58:28 2015] [] evict+0xa7/0x170 [Mi Sep 16 13:58:28 2015] [] iput+0xf5/0x180 [Mi Sep 16 13:58:28 2015] [] zfs_unlinked_drain+0xb5/0xf0 [zfs] [Mi Sep 16 13:58:28 2015] [] ? finish_wait+0x56/0x70 [Mi Sep 16 13:58:28 2015] [] ? taskq_create+0x228/0x370 [spl] [Mi Sep 16 13:58:28 2015] [] ? wake_up_bit+0x30/0x30 [Mi Sep 16 13:58:28 2015] [] ? zfs_get_done+0x70/0x70 [zfs] [Mi Sep 16 13:58:28 2015] [] ? zil_open+0x42/0x60 [zfs] [Mi Sep 16 13:58:28 2015] [] zfs_sb_setup+0x138/0x170 [zfs] [Mi Sep 16 13:58:28 2015] [] zfs_domount+0x2d3/0x360 [zfs] [Mi Sep 16 13:58:28 2015] [] ? zpl_kill_sb+0x20/0x20 [zfs] [Mi Sep 16 13:58:28 2015] [] zpl_fill_super+0x2c/0x40 [zfs] [Mi Sep 16 13:58:28 2015] [] mount_nodev+0x4d/0xb0 [Mi Sep 16 13:58:28 2015] [] zpl_mount+0x52/0x80 [zfs] [Mi Sep 16 13:58:28 2015] [] mount_fs+0x39/0x1b0 [Mi Sep 16 13:58:28 2015] [] vfs_kern_mount+0x5f/0xf0 [Mi Sep 16 13:58:28 2015] [] do_mount+0x24e/0xa40 [Mi Sep 16 13:58:28 2015] [] ? __get_free_pages+0xe/0x50 [Mi Sep 16 13:58:28 2015] [] SyS_mount+0x96/0xf0 [Mi Sep 16 13:58:28 2015] [] system_call_fastpath+0x16/0x1b Iostat shows me some txg_sync process consuming >90% of IO: PID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND 4015 be/4 root 0.00 B 0.00 B 0.00 % 92.78 % [txg_sync] 4464 be/4 root 1391.75 M 0.00 B 0.00 % 0.22 % mount.zfs dpool01/d39c6e3cd45c7a712ffca0b94c16f86e /var/lib/lxc/d39c6e3cd45c7a712ffca0b94c16f86e -o rw,noatime,xattr,zfsutil Greets |
|
@discostur how full, empty is your pool ? |
|
my pool is quite empty: NAME USED AVAIL REFER MOUNTPOINT |
|
@discostur The |
|
I believe the original issue here has been addressed so I'm closing this issue. Please open a new issue if a similar problem is reproducible with zfs-0.6.5.1 or newer. @discostur @chrisrd the |
|
Just to let you know I've been seeing this issue as recently as 2-3 months ago. At that time I reduced the amount of memory available to ZFS significantly and I stopped seeing the issue. I can check again to see if it's still happening. |
|
@ioquatix if you can verify with 0.6.5.1 that would be helpful because it's my understanding that this has been resolved. I'd be good to know if I'm wrong about that. |
|
Hi, I also experience this problem: and get the same "stuck" behavior: |
|
still getting this on 0.6.5.3. please note that I'm not very tolerant and my kernel.hung_task_timeout_secs 120 seconds is changed to 15 seconds [Thu Dec 10 02:06:33 2015] INFO: task txg_sync:2226 blocked for more than 15 seconds. |
|
@mailinglists35 are they transient? |
|
yes, only during peak disk activity - for example this occured when at the same time robocopy was writing data and sdelete was wiping free space on a zvol exported via iscsi to a windows client |
|
Just a thought... Could depleted entropy pools be an issue here? Maybe in relation with kernel.randomize_va_space and/or LUKS; lack of entropy can cause long stalls sometimes. |
|
I experience this on pools without LUKS |
|
Is there some way we can test this hypothesis? Can the kernel log when it is running out of entropy? |
|
Okay so this might be odd, but what the hell. I usually experience this problem when running minecraft on said server. Memory Usage? CPU usage? Not really sure. It never seems to be out of memory or pegged. |
|
I just started experiencing the same problem mentioned in this issue yesterday. I'm running Linux Mint Cinnamon 17.3 64-bit. "uname -a" produces : "lsb_release -a" produces : I have several Windows and Linux VMware VMs ( VMware® Workstation 12 Pro 12.1.0 build-3272444 ) installed in a zpool on an external Western Digital USB 3.0 4TB My Book hard drive which holds a ZFS pool named "zfs-backup". In the hopes of fixing some inconsistencies in my 32-bit Windows 10 VM ( so that I could expand the virtual disk size ), I created a snapshot, reverted said snapshot and then deleted said snapshot. The process was very IO intensive on the zfs-backup pool and brought my system ( at least the UI/GUI ) to a halt. VMware was stuck at 60% "cleaning up deleted files" yesterday morning so I decided to get to virtual terminal so I could kill and restart the Cinnamon desktop manager and get back control of the GUI. Well, when I was in a virtual terminal, all of the sudden a load of error messages started being spewed from the kernel to virtual terminal 1. I caught sight of what looked to be backtraces, but the text was scrolling too fast. Anyway, my system then shut itself off. I don't know what happened or if there was a kernel panic ( my usual experience with kernel panics is a white-on-black screen filled with text describing the panic and a blinking caps lock key ). In any case, nothing from the crash was recorded to /var/log as far as I could tell. Anyhow, when I booted my system back up and tried to access my zfs-backup pool, almost every zfs or zpool command would hang/block. Here is my ZFS version from dmesg : Here is a sample of the type of kernel errors I was seeing : I waited several hours for the above command to unblock, but now it appears that my zfs-backup pool is up, running and mounted again, with no errors. Here is the output of "zpool status" : If anyone has any insight on what the cause of my problems was/is, or even better, a fix for this bug, then I'd be appreciative. Regards, jdb2 |
|
I get this occasionally with 0.6.5.7, making extensive use of LUKS. So far during the times I've noticed it, one particular disk was always at 100% utilization, so I have a feeling it's a bad disk more than anything else but in case it's entropy, I've installed and activated rng-tools. |
|
Haveged is also useful. Bad disk, yeah could be. |
|
@behlendorf Still experiencing this issue, no disks have failed in over a year, await time is low, txg_sync hanging. What should I do? |
|
I also experience this problem while removing directory with 3.5mln files. Ubuntu server 16.10, kernel: 4.8.0-34-generic, zfsutils-linux: 0.6.5.8-0ubuntu4.1 zpool in kvm VM on LVM volume on MD raid, compression lz4, deduplication Few minutes after rm -rf start I get "INFO: task txg_sync:1748 blocked for more than 120 seconds." and zpool becomes unusable. Do we have any workaround? Did anyone tried something like loop with small portions of files to remove? How can I help you in debugging this issue? |
|
I did not encounter this problem in over a year now, but I disabled (recreated my pool without) deduplication. Afterwards, it runs smoothly. To achieve something similar than deduplication, I use the COW capability to have incremental differences of backups, yet this is not perfect deduplication, but it saves me a factor of at least 10 in comparison to non-ZFS based backups. |
|
So, I had a boot drive (the one with the high await time). I've replaced it with an SSD. I'll report back if this alleviates the problem. |
|
I've come to the conclusion that there was something wrong with one of the CPU cores in this server. So, some of the issues I've reported here may be due to faulty hardware. |
|
We also encounter this issue during heavy load. |
|
I've disabled one of the CPU cores and since then haven't had a single problem. When both CPU cores were enabled, I had a number of correctable and uncorrectable ECC errors. Running It's certainly an odd situation. |
|
@ioquatix thanks for this insight regarding faulty CPU core. It might not be my own issue, but it speaks in general to underlying hardware issues / error. |
|
I definitely had an issue with one of the drives too - but it was corrected after running a badblocks destructive read/write check and recreating the array. I think the disk was non-TLER and was taking it's time to try to read the faulty sector. |
|
I don't think it's bad hardware. I was hitting this on 30 servers in a test environment running Ubuntu if I recall correctly. I don't remember the specific version. After a few weeks/months it went away--possibly due to a kernel upgrade or zfs package upgrade. |
|
Interesting - I could still reproduce the issue with those drives - WD Green 3TB - but can't reproduce the issue in exactly the same server with WD Red 4TB. I'll have to do another full backup and see if I can reproduce - I'm doing a zfs send/recv from the 6xRAID10 WD REDS -> 4xRAID10 WD GREENS and that usually triggers the issue. |
|
Getting this on ubuntu 16.04 just yesterday. However also had sata bus communications errors, bad controller. And non-TLER drives. So its really hard for me to know which one it is. I thought there was some fix or solution for ubuntu systems. But cannot remember where I saw it. [edit] but the guy was talking about snapshots, being taken with zfs-auto-snapshot (which I have also here). |
I've seen this issue a couple of times.
Not really sure what is causing it. Sometimes seems to occur during moderate continuous IO. Not sure if the first line is relevant, included it just in case.
The text was updated successfully, but these errors were encountered: