* Deadlock between btrfs-transacti and userland on 5.2.1
[not found] <DB8PR03MB56287A9E527898E5727BB41599C80@DB8PR03MB5628.eurprd03.prod.outlook.com>
@ 2019-07-18 12:23 ` Drazen Kacar
2019-07-19 12:12 ` Drazen Kacar
2019-09-11 14:59 ` Filipe Manana
0 siblings, 2 replies; 3+ messages in thread
From: Drazen Kacar @ 2019-07-18 12:23 UTC (permalink / raw)
To: linux-btrfs
[-- Attachment #1: Type: text/plain, Size: 5319 bytes --]
Hello,
I think I've encountered a deadlock between btrfs-transacti and postgres
process(es). This is system information (btrfs fi usage obtained after
poweroff and boot):
# cat /etc/redhat-release
CentOS Linux release 7.6.1810 (Core)
# uname -a
Linux prod-dbsnap-01 5.2.1-1.el7.elrepo.x86_64 #1 SMP Sun Jul 14 08:15:04 EDT 2019 x86_64 x86_64 x86_64 GNU/Linux
# btrfs --version
btrfs-progs v5.2
# btrfs filesystem usage /data/pg_data
Overall:
Device size: 2.00TiB
Device allocated: 345.03GiB
Device unallocated: 1.66TiB
Device missing: 0.00B
Used: 338.07GiB
Free (estimated): 1.67TiB (min: 854.27GiB)
Data ratio: 1.00
Metadata ratio: 2.00
Global reserve: 512.00MiB (used: 0.00B)
Data,RAID0: Size:332.00GiB, Used:329.22GiB
/dev/sdb 83.00GiB
/dev/sdc 83.00GiB
/dev/sdd 83.00GiB
/dev/sde 83.00GiB
Metadata,RAID10: Size:6.50GiB, Used:4.42GiB
/dev/sdb 3.25GiB
/dev/sdc 3.25GiB
/dev/sdd 3.25GiB
/dev/sde 3.25GiB
System,RAID10: Size:16.00MiB, Used:48.00KiB
/dev/sdb 8.00MiB
/dev/sdc 8.00MiB
/dev/sdd 8.00MiB
/dev/sde 8.00MiB
Unallocated:
/dev/sdb 425.74GiB
/dev/sdc 425.74GiB
/dev/sdd 425.74GiB
/dev/sde 425.74GiB
There were three btrfs subvolumes and on each one there was a Postgres
database slave doing recovery (single threaded writing). But there was a
lot of writing. And prior to starting Postgres slaves I was restoring base
backup from the backup server, which was being done by a number of
parallel rsync processes (12 at most, I think).
The file system is mounted with:
# grep btrfs /proc/mounts
/dev/sdd /data/pg_data btrfs rw,noatime,compress-force=zstd:3,space_cache,subvolid=5,subvol=/ 0 0
After several hours I got this in /var/log/messages:
# grep 'INFO: task .*blocked for more than' messages
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task btrfs-transacti:1361 blocked for more than 122 seconds.
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:62682 blocked for more than 122 seconds.
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:80145 blocked for more than 122 seconds.
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:87299 blocked for more than 122 seconds.
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:93108 blocked for more than 122 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task btrfs-transacti:1361 blocked for more than 245 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:62682 blocked for more than 245 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:80145 blocked for more than 245 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:87299 blocked for more than 245 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:93108 blocked for more than 245 seconds.
Full log is in the attachment. It seems to me that there is a deadlock
between btrfs-transacti and any process which is trying to write
something (not sure about reading). While this was going on the cpu
usage (according to top) was non-existant. There are 4 cpus (it's a virtual
machine in VmWare) and 3 were 100% idle. The 4th was 100% in
waiting. (I didn't find out which process was on that cpu, unfortunately.)
I powered off the machine (yesterday), booted this morning and things
are working without errors. I stopped postgres clusters, though.
I have a few questions:
1. After something like this happens and the machine is rebooted is there
a procedure which would lower the probablity of encountering the deadlock
again (maybe btrfs scrub or btrfs defragment or something like that)? This
happened after a heavy write activity, so maybe fragmentation had
something to do with it.
2. Should I run btrfsck (or something else) to verify on-disk integrity after a
problem like this? Or it's just an in-memory problem, so I can assume that
nothing bad happened to the data on disks.
3. I'd like to write a watchdog program to catch deadlocks and reboot
(probably power-cycle) the VM, but I'm not sure what would the appropriate
check be. Does it have to write something to the disk or reading would be
sufficient? And how to bypass the OS buffer cache (fsync() or O_DIRECT
should do it for writing, but I'm not sure about reading)?
What would the appropriate timeout be? (If the operation doesn't
complete in xx seconds a reboot should be triggered, but I don't know how
many seconds to wait when there's a heavy load and things are just slow,
but there's no deadlock.)
Should I put watchdog process in real-time class (or however the equivalent
is called on Linux)? Since this is a mainline kernel, I'm not sure if I could assume
that real-time support won't have bugs of its own.
And last, but not least, is there additional data that could help with debugging
issues like this? (If possible, something that could be programmed into
watchdog service.)
[-- Attachment #2: messages_deadlock.txt --]
[-- Type: text/plain, Size: 24455 bytes --]
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task btrfs-transacti:1361 blocked for more than 122 seconds.
Jul 17 16:47:09 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:47:09 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs-transacti D 0 1361 2 0x80004000
Jul 17 16:47:09 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:47:09 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? blk_flush_plug_list+0xd1/0x100
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? bit_wait+0x50/0x50
Jul 17 16:47:09 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:47:09 prod-dbsnap-01 kernel: io_schedule+0x16/0x40
Jul 17 16:47:09 prod-dbsnap-01 kernel: bit_wait_io+0x11/0x50
Jul 17 16:47:09 prod-dbsnap-01 kernel: __wait_on_bit+0x6b/0xa0
Jul 17 16:47:09 prod-dbsnap-01 kernel: out_of_line_wait_on_bit+0x91/0xb0
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? init_wait_var_entry+0x50/0x50
Jul 17 16:47:09 prod-dbsnap-01 kernel: lock_extent_buffer_for_io+0x12f/0x320 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btree_write_cache_pages+0x207/0x420 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btree_writepages+0x5d/0x70 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: do_writepages+0x1f/0x70
Jul 17 16:47:09 prod-dbsnap-01 kernel: __filemap_fdatawrite_range+0xc6/0x100
Jul 17 16:47:09 prod-dbsnap-01 kernel: filemap_fdatawrite_range+0x13/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_write_marked_extents+0x107/0x150 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_write_and_wait_transaction.isra.26+0x4d/0xa0 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_commit_transaction+0x7b4/0xab0 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: transaction_kthread+0x157/0x190 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:62682 blocked for more than 122 seconds.
Jul 17 16:47:09 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:47:09 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:47:09 prod-dbsnap-01 kernel: postgres D 0 62682 20074 0x00004000
Jul 17 16:47:09 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:47:09 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:47:09 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:47:09 prod-dbsnap-01 kernel: schedule_preempt_disabled+0xe/0x10
Jul 17 16:47:09 prod-dbsnap-01 kernel: __mutex_lock.isra.11+0x233/0x4e0
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 17 16:47:09 prod-dbsnap-01 kernel: __mutex_lock_slowpath+0x13/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: mutex_lock+0x31/0x40
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_log_inode_parent+0x70c/0xdd0 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? prepare_to_wait_event+0x82/0x170
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? wait_current_trans+0x33/0x100 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? _cond_resched+0x19/0x30
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? join_transaction+0x2b/0x460 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_log_dentry_safe+0x59/0x80 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_sync_file+0x35b/0x410 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 17 16:47:09 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 17 16:47:09 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 17 16:47:09 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 17 16:47:09 prod-dbsnap-01 kernel: RIP: 0033:0x7fdbacc98310
Jul 17 16:47:09 prod-dbsnap-01 kernel: Code: 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 83 3d 8d 6c 2d 00 00 75 10 b8 4b 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 31 c3 48 83 ec 08 e8 2e 6a 01 00 48 89 04 24
Jul 17 16:47:09 prod-dbsnap-01 kernel: RSP: 002b:00007fff8e7c2908 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 17 16:47:09 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000018cbc RCX: 00007fdbacc98310
Jul 17 16:47:09 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 0000000000018cbc RDI: 0000000000000004
Jul 17 16:47:09 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 17 16:47:09 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 17 16:47:09 prod-dbsnap-01 kernel: R13: 0000000001228189 R14: 00007fdb9caf9280 R15: 0000000000000100
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:80145 blocked for more than 122 seconds.
Jul 17 16:47:09 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:47:09 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:47:09 prod-dbsnap-01 kernel: postgres D 0 80145 80126 0x00004000
Jul 17 16:47:09 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:47:09 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:47:09 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:47:09 prod-dbsnap-01 kernel: schedule_preempt_disabled+0xe/0x10
Jul 17 16:47:09 prod-dbsnap-01 kernel: __mutex_lock.isra.11+0x233/0x4e0
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 17 16:47:09 prod-dbsnap-01 kernel: __mutex_lock_slowpath+0x13/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: mutex_lock+0x31/0x40
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_log_inode_parent+0x163/0xdd0 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? prepare_to_wait_event+0x82/0x170
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? wait_current_trans+0x33/0x100 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? _cond_resched+0x19/0x30
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? join_transaction+0x2b/0x460 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_log_dentry_safe+0x59/0x80 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_sync_file+0x35b/0x410 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 17 16:47:09 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 17 16:47:09 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 17 16:47:09 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 17 16:47:09 prod-dbsnap-01 kernel: RIP: 0033:0x7f1de34bdd00
Jul 17 16:47:09 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 17 16:47:09 prod-dbsnap-01 kernel: RSP: 002b:00007fff3d26d058 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 17 16:47:09 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f1de34bdd00
Jul 17 16:47:09 prod-dbsnap-01 kernel: RDX: 0000000000000120 RSI: 00007f1dc4a9e580 RDI: 0000000000000003
Jul 17 16:47:09 prod-dbsnap-01 kernel: RBP: 00007f1de38c97f0 R08: 00007f1dc4a9e690 R09: 00007f1dc4a9e588
Jul 17 16:47:09 prod-dbsnap-01 kernel: R10: 00007f1de1303c8c R11: 0000000000000246 R12: 00000086e3333668
Jul 17 16:47:09 prod-dbsnap-01 kernel: R13: 0000000000000001 R14: 00007fff3d26d560 R15: 0000000000000010
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:87299 blocked for more than 122 seconds.
Jul 17 16:47:09 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:47:09 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:47:09 prod-dbsnap-01 kernel: postgres D 0 87299 80126 0x00004000
Jul 17 16:47:09 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:47:09 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:47:09 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:47:09 prod-dbsnap-01 kernel: schedule_preempt_disabled+0xe/0x10
Jul 17 16:47:09 prod-dbsnap-01 kernel: __mutex_lock.isra.11+0x233/0x4e0
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 17 16:47:09 prod-dbsnap-01 kernel: __mutex_lock_slowpath+0x13/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: mutex_lock+0x31/0x40
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_log_inode_parent+0x70c/0xdd0 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? prepare_to_wait_event+0x82/0x170
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? wait_current_trans+0x33/0x100 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? _cond_resched+0x19/0x30
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? join_transaction+0x2b/0x460 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_log_dentry_safe+0x59/0x80 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_sync_file+0x35b/0x410 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 17 16:47:09 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 17 16:47:09 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 17 16:47:09 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 17 16:47:09 prod-dbsnap-01 kernel: RIP: 0033:0x7f1de1031310
Jul 17 16:47:09 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 17 16:47:09 prod-dbsnap-01 kernel: RSP: 002b:00007fff3d26d208 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 17 16:47:09 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 00000000000086e3 RCX: 00007f1de1031310
Jul 17 16:47:09 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 00000000000086e3 RDI: 0000000000000004
Jul 17 16:47:09 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 17 16:47:09 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 17 16:47:09 prod-dbsnap-01 kernel: R13: 0000000001650289 R14: 00007f1dd0e92280 R15: 00000000000000e0
Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:93108 blocked for more than 122 seconds.
Jul 17 16:47:09 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:47:09 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:47:09 prod-dbsnap-01 kernel: postgres D 0 93108 93106 0x00004000
Jul 17 16:47:09 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:47:09 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:47:09 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:47:09 prod-dbsnap-01 kernel: schedule_preempt_disabled+0xe/0x10
Jul 17 16:47:09 prod-dbsnap-01 kernel: __mutex_lock.isra.11+0x233/0x4e0
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? btrfs_must_commit_transaction+0x60/0x70 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: __mutex_lock_slowpath+0x13/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: mutex_lock+0x31/0x40
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_log_inode_parent+0x70c/0xdd0 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? wait_current_trans+0x33/0x100 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? _cond_resched+0x19/0x30
Jul 17 16:47:09 prod-dbsnap-01 kernel: ? join_transaction+0x2b/0x460 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_log_dentry_safe+0x59/0x80 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: btrfs_sync_file+0x35b/0x410 [btrfs]
Jul 17 16:47:09 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 17 16:47:09 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 17 16:47:09 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 17 16:47:09 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 17 16:47:09 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 17 16:47:09 prod-dbsnap-01 kernel: RIP: 0033:0x7f489051dd00
Jul 17 16:47:09 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 17 16:47:09 prod-dbsnap-01 kernel: RSP: 002b:00007fff39abd838 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 17 16:47:09 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f489051dd00
Jul 17 16:47:09 prod-dbsnap-01 kernel: RDX: 0000000000000180 RSI: 0000000000000002 RDI: 0000000000000003
Jul 17 16:47:09 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 3839303030303030 R09: 00007f488dfe920d
Jul 17 16:47:09 prod-dbsnap-01 kernel: R10: 00007f488e363c8c R11: 0000000000000246 R12: 00007fff39abe200
Jul 17 16:47:09 prod-dbsnap-01 kernel: R13: 0000000000000000 R14: 0000000000000014 R15: 00007fff39abe200
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task btrfs-transacti:1361 blocked for more than 245 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:49:12 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs-transacti D 0 1361 2 0x80004000
Jul 17 16:49:12 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:49:12 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? blk_flush_plug_list+0xd1/0x100
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? bit_wait+0x50/0x50
Jul 17 16:49:12 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:49:12 prod-dbsnap-01 kernel: io_schedule+0x16/0x40
Jul 17 16:49:12 prod-dbsnap-01 kernel: bit_wait_io+0x11/0x50
Jul 17 16:49:12 prod-dbsnap-01 kernel: __wait_on_bit+0x6b/0xa0
Jul 17 16:49:12 prod-dbsnap-01 kernel: out_of_line_wait_on_bit+0x91/0xb0
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? init_wait_var_entry+0x50/0x50
Jul 17 16:49:12 prod-dbsnap-01 kernel: lock_extent_buffer_for_io+0x12f/0x320 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btree_write_cache_pages+0x207/0x420 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btree_writepages+0x5d/0x70 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: do_writepages+0x1f/0x70
Jul 17 16:49:12 prod-dbsnap-01 kernel: __filemap_fdatawrite_range+0xc6/0x100
Jul 17 16:49:12 prod-dbsnap-01 kernel: filemap_fdatawrite_range+0x13/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_write_marked_extents+0x107/0x150 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_write_and_wait_transaction.isra.26+0x4d/0xa0 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_commit_transaction+0x7b4/0xab0 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: transaction_kthread+0x157/0x190 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:62682 blocked for more than 245 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:49:12 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:49:12 prod-dbsnap-01 kernel: postgres D 0 62682 20074 0x00004000
Jul 17 16:49:12 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:49:12 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:49:12 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:49:12 prod-dbsnap-01 kernel: schedule_preempt_disabled+0xe/0x10
Jul 17 16:49:12 prod-dbsnap-01 kernel: __mutex_lock.isra.11+0x233/0x4e0
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 17 16:49:12 prod-dbsnap-01 kernel: __mutex_lock_slowpath+0x13/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: mutex_lock+0x31/0x40
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_log_inode_parent+0x70c/0xdd0 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? prepare_to_wait_event+0x82/0x170
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? wait_current_trans+0x33/0x100 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? _cond_resched+0x19/0x30
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? join_transaction+0x2b/0x460 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_log_dentry_safe+0x59/0x80 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_sync_file+0x35b/0x410 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 17 16:49:12 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 17 16:49:12 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 17 16:49:12 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 17 16:49:12 prod-dbsnap-01 kernel: RIP: 0033:0x7fdbacc98310
Jul 17 16:49:12 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 17 16:49:12 prod-dbsnap-01 kernel: RSP: 002b:00007fff8e7c2908 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 17 16:49:12 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000018cbc RCX: 00007fdbacc98310
Jul 17 16:49:12 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 0000000000018cbc RDI: 0000000000000004
Jul 17 16:49:12 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 17 16:49:12 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 17 16:49:12 prod-dbsnap-01 kernel: R13: 0000000001228189 R14: 00007fdb9caf9280 R15: 0000000000000100
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:80145 blocked for more than 245 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:49:12 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:49:12 prod-dbsnap-01 kernel: postgres D 0 80145 80126 0x00004000
Jul 17 16:49:12 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:49:12 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:49:12 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:49:12 prod-dbsnap-01 kernel: schedule_preempt_disabled+0xe/0x10
Jul 17 16:49:12 prod-dbsnap-01 kernel: __mutex_lock.isra.11+0x233/0x4e0
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 17 16:49:12 prod-dbsnap-01 kernel: __mutex_lock_slowpath+0x13/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: mutex_lock+0x31/0x40
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_log_inode_parent+0x163/0xdd0 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? prepare_to_wait_event+0x82/0x170
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? wait_current_trans+0x33/0x100 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? _cond_resched+0x19/0x30
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? join_transaction+0x2b/0x460 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_log_dentry_safe+0x59/0x80 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_sync_file+0x35b/0x410 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 17 16:49:12 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 17 16:49:12 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 17 16:49:12 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 17 16:49:12 prod-dbsnap-01 kernel: RIP: 0033:0x7f1de34bdd00
Jul 17 16:49:12 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 17 16:49:12 prod-dbsnap-01 kernel: RSP: 002b:00007fff3d26d058 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 17 16:49:12 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f1de34bdd00
Jul 17 16:49:12 prod-dbsnap-01 kernel: RDX: 0000000000000120 RSI: 00007f1dc4a9e580 RDI: 0000000000000003
Jul 17 16:49:12 prod-dbsnap-01 kernel: RBP: 00007f1de38c97f0 R08: 00007f1dc4a9e690 R09: 00007f1dc4a9e588
Jul 17 16:49:12 prod-dbsnap-01 kernel: R10: 00007f1de1303c8c R11: 0000000000000246 R12: 00000086e3333668
Jul 17 16:49:12 prod-dbsnap-01 kernel: R13: 0000000000000001 R14: 00007fff3d26d560 R15: 0000000000000010
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:87299 blocked for more than 245 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:49:12 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:49:12 prod-dbsnap-01 kernel: postgres D 0 87299 80126 0x00004000
Jul 17 16:49:12 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:49:12 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:49:12 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:49:12 prod-dbsnap-01 kernel: schedule_preempt_disabled+0xe/0x10
Jul 17 16:49:12 prod-dbsnap-01 kernel: __mutex_lock.isra.11+0x233/0x4e0
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 17 16:49:12 prod-dbsnap-01 kernel: __mutex_lock_slowpath+0x13/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: mutex_lock+0x31/0x40
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_log_inode_parent+0x70c/0xdd0 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? prepare_to_wait_event+0x82/0x170
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? wait_current_trans+0x33/0x100 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? _cond_resched+0x19/0x30
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? join_transaction+0x2b/0x460 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_log_dentry_safe+0x59/0x80 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_sync_file+0x35b/0x410 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 17 16:49:12 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 17 16:49:12 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 17 16:49:12 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 17 16:49:12 prod-dbsnap-01 kernel: RIP: 0033:0x7f1de1031310
Jul 17 16:49:12 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 17 16:49:12 prod-dbsnap-01 kernel: RSP: 002b:00007fff3d26d208 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 17 16:49:12 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 00000000000086e3 RCX: 00007f1de1031310
Jul 17 16:49:12 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 00000000000086e3 RDI: 0000000000000004
Jul 17 16:49:12 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 17 16:49:12 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 17 16:49:12 prod-dbsnap-01 kernel: R13: 0000000001650289 R14: 00007f1dd0e92280 R15: 00000000000000e0
Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:93108 blocked for more than 245 seconds.
Jul 17 16:49:12 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 17 16:49:12 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 17 16:49:12 prod-dbsnap-01 kernel: postgres D 0 93108 93106 0x00004000
Jul 17 16:49:12 prod-dbsnap-01 kernel: Call Trace:
Jul 17 16:49:12 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 17 16:49:12 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 17 16:49:12 prod-dbsnap-01 kernel: schedule_preempt_disabled+0xe/0x10
Jul 17 16:49:12 prod-dbsnap-01 kernel: __mutex_lock.isra.11+0x233/0x4e0
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? btrfs_must_commit_transaction+0x60/0x70 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: __mutex_lock_slowpath+0x13/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: mutex_lock+0x31/0x40
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_log_inode_parent+0x70c/0xdd0 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? wait_current_trans+0x33/0x100 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? _cond_resched+0x19/0x30
Jul 17 16:49:12 prod-dbsnap-01 kernel: ? join_transaction+0x2b/0x460 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_log_dentry_safe+0x59/0x80 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: btrfs_sync_file+0x35b/0x410 [btrfs]
Jul 17 16:49:12 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 17 16:49:12 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 17 16:49:12 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 17 16:49:12 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 17 16:49:12 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 17 16:49:12 prod-dbsnap-01 kernel: RIP: 0033:0x7f489051dd00
Jul 17 16:49:12 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 17 16:49:12 prod-dbsnap-01 kernel: RSP: 002b:00007fff39abd838 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 17 16:49:12 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f489051dd00
Jul 17 16:49:12 prod-dbsnap-01 kernel: RDX: 0000000000000180 RSI: 0000000000000002 RDI: 0000000000000003
Jul 17 16:49:12 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 3839303030303030 R09: 00007f488dfe920d
Jul 17 16:49:12 prod-dbsnap-01 kernel: R10: 00007f488e363c8c R11: 0000000000000246 R12: 00007fff39abe200
Jul 17 16:49:12 prod-dbsnap-01 kernel: R13: 0000000000000000 R14: 0000000000000014 R15: 00007fff39abe200
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: Deadlock between btrfs-transacti and userland on 5.2.1
2019-07-18 12:23 ` Deadlock between btrfs-transacti and userland on 5.2.1 Drazen Kacar
@ 2019-07-19 12:12 ` Drazen Kacar
2019-09-11 14:59 ` Filipe Manana
1 sibling, 0 replies; 3+ messages in thread
From: Drazen Kacar @ 2019-07-19 12:12 UTC (permalink / raw)
To: linux-btrfs
[-- Attachment #1: Type: text/plain, Size: 215 bytes --]
I've got more hung tasks. Log is attached. Several empty lines
in the file mean that there was a reboot in between.
btrfs scrub -Bdr says there are no errors on disks.
btrfs device stats also shows no errors.
[-- Attachment #2: messages_more_hungs.txt --]
[-- Type: text/plain, Size: 60687 bytes --]
Jul 19 11:47:36 prod-dbsnap-01 systemd: Started PostgreSQL snapshot service for ardcimicrofinance_6432.
Jul 19 11:47:36 prod-dbsnap-01 systemd: Reloading.
Jul 19 11:47:36 prod-dbsnap-01 systemd: Binding to IPv6 address not available since kernel does not support IPv6.
Jul 19 11:47:36 prod-dbsnap-01 systemd: Binding to IPv6 address not available since kernel does not support IPv6.
Jul 19 11:50:01 prod-dbsnap-01 systemd: Created slice User Slice of root.
Jul 19 11:50:01 prod-dbsnap-01 systemd: Started Session 241 of user root.
Jul 19 11:50:01 prod-dbsnap-01 systemd: Removed slice User Slice of root.
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task postgres:20710 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: postgres D 0 20710 20672 0x00004000
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 11:52:01 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 11:52:01 prod-dbsnap-01 kernel: RIP: 0033:0x7fc16f67bd00
Jul 19 11:52:01 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 11:52:01 prod-dbsnap-01 kernel: RSP: 002b:00007ffee0d14198 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 19 11:52:01 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 00000000000000f9 RCX: 00007fc16f67bd00
Jul 19 11:52:01 prod-dbsnap-01 kernel: RDX: 0000000000000120 RSI: 00007fc150c5c580 RDI: 00000000000000f9
Jul 19 11:52:01 prod-dbsnap-01 kernel: RBP: 00007fc16fa877f0 R08: 00007fc150c5c690 R09: 00007fc150c5c588
Jul 19 11:52:01 prod-dbsnap-01 kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000019abc10bce0
Jul 19 11:52:01 prod-dbsnap-01 kernel: R13: 0000000000000001 R14: 000000000206dba0 R15: 0000000000000f9d
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task postgres:28814 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: postgres D 0 28814 28787 0x00004000
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 11:52:01 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 11:52:01 prod-dbsnap-01 kernel: RIP: 0033:0x7f1e421e4d00
Jul 19 11:52:01 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 11:52:01 prod-dbsnap-01 kernel: RSP: 002b:00007ffc18ebe718 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 19 11:52:01 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 00000000000003e0 RCX: 00007f1e421e4d00
Jul 19 11:52:01 prod-dbsnap-01 kernel: RDX: 0000000000000120 RSI: 00007f1e237c5580 RDI: 00000000000003e0
Jul 19 11:52:01 prod-dbsnap-01 kernel: RBP: 00007f1e425f07f0 R08: 00007f1e237c5690 R09: 00007f1e237c5588
Jul 19 11:52:01 prod-dbsnap-01 kernel: R10: 0000000000000000 R11: 0000000000000246 R12: 0000006053e93948
Jul 19 11:52:01 prod-dbsnap-01 kernel: R13: 0000000000000001 R14: 0000000000e21f20 R15: 0000000000003042
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task postgres:31379 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: postgres D 0 31379 28787 0x00004004
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: io_schedule+0x16/0x40
Jul 19 11:52:01 prod-dbsnap-01 kernel: wait_on_page_bit+0x1c0/0x270
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? file_fdatawait_range+0x30/0x30
Jul 19 11:52:01 prod-dbsnap-01 kernel: wait_on_page_writeback+0x48/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: extent_write_cache_pages+0x214/0x4c0 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: extent_writepages+0x4f/0x90 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? tcp_push+0xde/0x110
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_writepages+0xe/0x10 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_writepages+0x1f/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: __filemap_fdatawrite_range+0xc6/0x100
Jul 19 11:52:01 prod-dbsnap-01 kernel: filemap_fdatawrite_range+0x13/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_fdatawrite_range+0x20/0x50 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: start_ordered_ops+0x4c/0x90 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __sys_sendto+0x107/0x1a0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_sync_file+0xce/0x410 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 11:52:01 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 11:52:01 prod-dbsnap-01 kernel: RIP: 0033:0x7f1e3fd58310
Jul 19 11:52:01 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 11:52:01 prod-dbsnap-01 kernel: RSP: 002b:00007ffc18ebf888 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 19 11:52:01 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000006053 RCX: 00007f1e3fd58310
Jul 19 11:52:01 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 0000000000006053 RDI: 0000000000000004
Jul 19 11:52:01 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 19 11:52:01 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 19 11:52:01 prod-dbsnap-01 kernel: R13: 0000000000e208e9 R14: 00007f1e2fbb9280 R15: 0000000000001e00
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task postgres:31526 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: postgres D 0 31526 20672 0x00004000
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 11:52:01 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 11:52:01 prod-dbsnap-01 kernel: RIP: 0033:0x7fc16d1ef310
Jul 19 11:52:01 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 11:52:01 prod-dbsnap-01 kernel: RSP: 002b:00007ffee0d15308 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 19 11:52:01 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000019abc RCX: 00007fc16d1ef310
Jul 19 11:52:01 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 0000000000019abc RDI: 0000000000000004
Jul 19 11:52:01 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 19 11:52:01 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 19 11:52:01 prod-dbsnap-01 kernel: R13: 000000000208a5d9 R14: 00007fc15d050280 R15: 0000000000012000
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task postgres:36718 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: postgres D 0 36718 36697 0x00004000
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 11:52:01 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 11:52:01 prod-dbsnap-01 kernel: RIP: 0033:0x7f577cf4cd00
Jul 19 11:52:01 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 11:52:01 prod-dbsnap-01 kernel: RSP: 002b:00007ffdc0a03fb8 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 19 11:52:01 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f577cf4cd00
Jul 19 11:52:01 prod-dbsnap-01 kernel: RDX: 0000000000000120 RSI: 00007f575e52d580 RDI: 0000000000000003
Jul 19 11:52:01 prod-dbsnap-01 kernel: RBP: 00007f577d3587f0 R08: 00007f575e52d690 R09: 00007f575e52d588
Jul 19 11:52:01 prod-dbsnap-01 kernel: R10: 00000000000032c8 R11: 0000000000000246 R12: 000000930ca33770
Jul 19 11:52:01 prod-dbsnap-01 kernel: R13: 0000000000000001 R14: 0000009308e80f30 R15: 0000000000000001
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task postgres:41263 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: postgres D 0 41263 36697 0x00004004
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 11:52:01 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 11:52:01 prod-dbsnap-01 kernel: RIP: 0033:0x7f577aac0310
Jul 19 11:52:01 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 11:52:01 prod-dbsnap-01 kernel: RSP: 002b:00007ffdc0a03bc8 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 19 11:52:01 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 000000000000930c RCX: 00007f577aac0310
Jul 19 11:52:01 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 000000000000930c RDI: 0000000000000004
Jul 19 11:52:01 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 19 11:52:01 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 19 11:52:01 prod-dbsnap-01 kernel: R13: 00000000015392c9 R14: 00007f576a921280 R15: 00000000000000e0
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task kworker/u256:5:118303 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: kworker/u256:5 D 0 118303 2 0x80004000
Jul 19 11:52:01 prod-dbsnap-01 kernel: Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 11:52:01 prod-dbsnap-01 kernel: start_transaction+0x316/0x4a0 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_join_transaction+0x1d/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_finish_ordered_io+0x45a/0x7c0 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: finish_ordered_fn+0x15/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: normal_work_helper+0xc5/0x320 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? pwq_activate_delayed_work+0x42/0xb0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_endio_write_helper+0x12/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: process_one_work+0x179/0x3a0
Jul 19 11:52:01 prod-dbsnap-01 kernel: worker_thread+0x4f/0x3e0
Jul 19 11:52:01 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? max_active_store+0x80/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task kworker/u256:4:6869 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: kworker/u256:4 D 0 6869 2 0x80004000
Jul 19 11:52:01 prod-dbsnap-01 kernel: Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 11:52:01 prod-dbsnap-01 kernel: start_transaction+0x316/0x4a0 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_join_transaction+0x1d/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_finish_ordered_io+0x45a/0x7c0 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? x86_gsbase_write_task+0x20/0x30
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: finish_ordered_fn+0x15/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: normal_work_helper+0xc5/0x320 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? pwq_activate_delayed_work+0x42/0xb0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_endio_write_helper+0x12/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: process_one_work+0x179/0x3a0
Jul 19 11:52:01 prod-dbsnap-01 kernel: worker_thread+0x4f/0x3e0
Jul 19 11:52:01 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? max_active_store+0x80/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task kworker/u256:14:8117 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: kworker/u256:14 D 0 8117 2 0x80004000
Jul 19 11:52:01 prod-dbsnap-01 kernel: Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 11:52:01 prod-dbsnap-01 kernel: start_transaction+0x316/0x4a0 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_join_transaction+0x1d/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_finish_ordered_io+0x45a/0x7c0 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? x86_gsbase_write_task+0x20/0x30
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 11:52:01 prod-dbsnap-01 kernel: finish_ordered_fn+0x15/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: normal_work_helper+0xc5/0x320 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? pwq_activate_delayed_work+0x42/0xb0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_endio_write_helper+0x12/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: process_one_work+0x179/0x3a0
Jul 19 11:52:01 prod-dbsnap-01 kernel: worker_thread+0x4f/0x3e0
Jul 19 11:52:01 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? max_active_store+0x80/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 11:52:01 prod-dbsnap-01 kernel: INFO: task kworker/u256:6:10389 blocked for more than 122 seconds.
Jul 19 11:52:01 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 11:52:01 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 11:52:01 prod-dbsnap-01 kernel: kworker/u256:6 D 0 10389 2 0x80004000
Jul 19 11:52:01 prod-dbsnap-01 kernel: Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: Call Trace:
Jul 19 11:52:01 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 11:52:01 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 11:52:01 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 11:52:01 prod-dbsnap-01 kernel: start_transaction+0x316/0x4a0 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_join_transaction+0x1d/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_finish_ordered_io+0x45a/0x7c0 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? syscall_return_via_sysret+0xf/0x7f
Jul 19 11:52:01 prod-dbsnap-01 kernel: finish_ordered_fn+0x15/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: normal_work_helper+0xc5/0x320 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? pwq_activate_delayed_work+0x42/0xb0
Jul 19 11:52:01 prod-dbsnap-01 kernel: btrfs_endio_write_helper+0x12/0x20 [btrfs]
Jul 19 11:52:01 prod-dbsnap-01 kernel: process_one_work+0x179/0x3a0
Jul 19 11:52:01 prod-dbsnap-01 kernel: worker_thread+0x4f/0x3e0
Jul 19 11:52:01 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? max_active_store+0x80/0x80
Jul 19 11:52:01 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 11:52:01 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 12:20:13 prod-dbsnap-01 kernel: INFO: task postgres:1840 blocked for more than 122 seconds.
Jul 19 12:20:13 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:20:13 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:20:13 prod-dbsnap-01 kernel: postgres D 0 1840 1796 0x00000000
Jul 19 12:20:13 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:20:13 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 12:20:13 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:20:13 prod-dbsnap-01 kernel: rwsem_down_write_failed+0x1f3/0x380
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? new_sync_read+0x11a/0x1c0
Jul 19 12:20:13 prod-dbsnap-01 kernel: down_write+0x3e/0x40
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_file_llseek+0x4c/0x2b0 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? vfs_read+0x8e/0x140
Jul 19 12:20:13 prod-dbsnap-01 kernel: ksys_lseek+0x8a/0xb0
Jul 19 12:20:13 prod-dbsnap-01 kernel: __x64_sys_lseek+0x1a/0x20
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:20:13 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:20:13 prod-dbsnap-01 kernel: RIP: 0033:0x7f49e7ff0d60
Jul 19 12:20:13 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:20:13 prod-dbsnap-01 kernel: RSP: 002b:00007ffd950c1358 EFLAGS: 00000246 ORIG_RAX: 0000000000000008
Jul 19 12:20:13 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000390000 RCX: 00007f49e7ff0d60
Jul 19 12:20:13 prod-dbsnap-01 kernel: RDX: 0000000000000000 RSI: 0000000000390000 RDI: 0000000000000003
Jul 19 12:20:13 prod-dbsnap-01 kernel: RBP: 0000019ac1390000 R08: 0000000002c29758 R09: 0000000002c2050c
Jul 19 12:20:13 prod-dbsnap-01 kernel: R10: 0000000002c2b730 R11: 0000000000000246 R12: 0000000000000003
Jul 19 12:20:13 prod-dbsnap-01 kernel: R13: 0000000000390000 R14: 0000000002c2050c R15: 0000000000000026
Jul 19 12:20:13 prod-dbsnap-01 kernel: INFO: task postgres:2037 blocked for more than 122 seconds.
Jul 19 12:20:13 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:20:13 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:20:13 prod-dbsnap-01 kernel: postgres D 0 2037 1801 0x00004000
Jul 19 12:20:13 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:20:13 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:20:13 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 12:20:13 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:20:13 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:20:13 prod-dbsnap-01 kernel: RIP: 0033:0x7f866ab96d00
Jul 19 12:20:13 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:20:13 prod-dbsnap-01 kernel: RSP: 002b:00007ffdc52426c8 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 19 12:20:13 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000000341 RCX: 00007f866ab96d00
Jul 19 12:20:13 prod-dbsnap-01 kernel: RDX: 0000000000000120 RSI: 00007f864c177580 RDI: 0000000000000341
Jul 19 12:20:13 prod-dbsnap-01 kernel: RBP: 00007f866afa27f0 R08: 00007f864c177690 R09: 00007f864c177588
Jul 19 12:20:13 prod-dbsnap-01 kernel: R10: 959bd756f2ca9fd3 R11: 0000000000000246 R12: 00000093121d6de0
Jul 19 12:20:13 prod-dbsnap-01 kernel: R13: 0000000000000001 R14: 0000000000000058 R15: 0000000000001eae
Jul 19 12:20:13 prod-dbsnap-01 kernel: INFO: task postgres:2061 blocked for more than 122 seconds.
Jul 19 12:20:13 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:20:13 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:20:13 prod-dbsnap-01 kernel: postgres D 0 2061 1808 0x00004000
Jul 19 12:20:13 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:20:13 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:20:13 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 12:20:13 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:20:13 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:20:13 prod-dbsnap-01 kernel: RIP: 0033:0x7fb113087d00
Jul 19 12:20:13 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:20:13 prod-dbsnap-01 kernel: RSP: 002b:00007fffba1597c8 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 19 12:20:13 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 00000000000003e0 RCX: 00007fb113087d00
Jul 19 12:20:13 prod-dbsnap-01 kernel: RDX: 0000000000000120 RSI: 00007fb0f4668580 RDI: 00000000000003e0
Jul 19 12:20:13 prod-dbsnap-01 kernel: RBP: 00007fb1134937f0 R08: 00007fb0f4668690 R09: 00007fb0f4668588
Jul 19 12:20:13 prod-dbsnap-01 kernel: R10: 959bd756f2ca9fd3 R11: 0000000000000246 R12: 0000006055e08180
Jul 19 12:20:13 prod-dbsnap-01 kernel: R13: 0000000000000001 R14: 000000000000126f R15: 000000000000158d
Jul 19 12:20:13 prod-dbsnap-01 kernel: INFO: task postgres:2135 blocked for more than 122 seconds.
Jul 19 12:20:13 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:20:13 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:20:13 prod-dbsnap-01 kernel: postgres D 0 2135 1801 0x00004004
Jul 19 12:20:13 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:20:13 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:20:13 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:20:13 prod-dbsnap-01 kernel: io_schedule+0x16/0x40
Jul 19 12:20:13 prod-dbsnap-01 kernel: wait_on_page_bit+0x1c0/0x270
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? file_fdatawait_range+0x30/0x30
Jul 19 12:20:13 prod-dbsnap-01 kernel: wait_on_page_writeback+0x48/0xa0
Jul 19 12:20:13 prod-dbsnap-01 kernel: extent_write_cache_pages+0x214/0x4c0 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: extent_writepages+0x4f/0x90 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? tcp_push+0xde/0x110
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_writepages+0xe/0x10 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_writepages+0x1f/0x70
Jul 19 12:20:13 prod-dbsnap-01 kernel: __filemap_fdatawrite_range+0xc6/0x100
Jul 19 12:20:13 prod-dbsnap-01 kernel: filemap_fdatawrite_range+0x13/0x20
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_fdatawrite_range+0x20/0x50 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: start_ordered_ops+0x4c/0x90 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? __sys_sendto+0x107/0x1a0
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_sync_file+0xce/0x410 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 12:20:13 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:20:13 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:20:13 prod-dbsnap-01 kernel: RIP: 0033:0x7f866870a310
Jul 19 12:20:13 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:20:13 prod-dbsnap-01 kernel: RSP: 002b:00007ffdc5243748 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 19 12:20:13 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000009312 RCX: 00007f866870a310
Jul 19 12:20:13 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 0000000000009312 RDI: 0000000000000004
Jul 19 12:20:13 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 19 12:20:13 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 19 12:20:13 prod-dbsnap-01 kernel: R13: 0000000002c2a009 R14: 00007f865856b280 R15: 0000000000002430
Jul 19 12:20:13 prod-dbsnap-01 kernel: INFO: task postgres:2165 blocked for more than 122 seconds.
Jul 19 12:20:13 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:20:13 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:20:13 prod-dbsnap-01 kernel: postgres D 0 2165 1796 0x00004000
Jul 19 12:20:13 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:20:13 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:20:13 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 12:20:13 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 12:20:13 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 19 12:20:13 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:20:13 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:20:13 prod-dbsnap-01 kernel: RIP: 0033:0x7f49e5b64310
Jul 19 12:20:13 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:20:13 prod-dbsnap-01 kernel: RSP: 002b:00007ffd950c4088 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 19 12:20:13 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000019ac1 RCX: 00007f49e5b64310
Jul 19 12:20:13 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 0000000000019ac1 RDI: 0000000000000004
Jul 19 12:20:13 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 19 12:20:13 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 19 12:20:13 prod-dbsnap-01 kernel: R13: 0000000002c370c9 R14: 00007f49d59c5280 R15: 000000000000abb0
Jul 19 12:24:18 prod-dbsnap-01 kernel: INFO: task postgres:1961 blocked for more than 122 seconds.
Jul 19 12:24:18 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:24:18 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:24:18 prod-dbsnap-01 kernel: postgres D 0 1961 1807 0x00004000
Jul 19 12:24:18 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:24:18 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:24:18 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 12:24:18 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:24:18 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:24:18 prod-dbsnap-01 kernel: RIP: 0033:0x7f99ee448d00
Jul 19 12:24:18 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:24:18 prod-dbsnap-01 kernel: RSP: 002b:00007ffdb772d008 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 19 12:24:18 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000000389 RCX: 00007f99ee448d00
Jul 19 12:24:18 prod-dbsnap-01 kernel: RDX: 00007f99df2a8070 RSI: 000000000a00000e RDI: 000000000000038f
Jul 19 12:24:18 prod-dbsnap-01 kernel: RBP: 000000000a00000e R08: 000000000007cc24 R09: 00007ffdb77810b0
Jul 19 12:24:18 prod-dbsnap-01 kernel: R10: 000000000000010c R11: 0000000000000246 R12: 0000000000000009
Jul 19 12:24:18 prod-dbsnap-01 kernel: R13: 00000000010ee588 R14: 00000000010a7190 R15: 00000000010a7190
Jul 19 12:24:18 prod-dbsnap-01 kernel: INFO: task postgres:2032 blocked for more than 122 seconds.
Jul 19 12:24:18 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:24:18 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:24:18 prod-dbsnap-01 kernel: postgres D 0 2032 1796 0x00004000
Jul 19 12:24:18 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:24:18 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:24:18 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 12:24:18 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:24:18 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:24:18 prod-dbsnap-01 kernel: RIP: 0033:0x7f49e7ff0d00
Jul 19 12:24:18 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:24:18 prod-dbsnap-01 kernel: RSP: 002b:00007ffd950c3008 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 19 12:24:18 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 00000000000003e0 RCX: 00007f49e7ff0d00
Jul 19 12:24:18 prod-dbsnap-01 kernel: RDX: 0000000000000120 RSI: 00007f49c95d1580 RDI: 00000000000003e0
Jul 19 12:24:18 prod-dbsnap-01 kernel: RBP: 00007f49e83fc7f0 R08: 00007f49c95d1690 R09: 00007f49c95d1588
Jul 19 12:24:18 prod-dbsnap-01 kernel: R10: 959bd756f2ca9fd3 R11: 0000000000000246 R12: 0000019ac2a59b20
Jul 19 12:24:18 prod-dbsnap-01 kernel: R13: 0000000000000001 R14: 00000000000002de R15: 0000000000000307
Jul 19 12:24:18 prod-dbsnap-01 kernel: INFO: task postgres:2061 blocked for more than 122 seconds.
Jul 19 12:24:18 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:24:18 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:24:18 prod-dbsnap-01 kernel: postgres D 0 2061 1808 0x00004000
Jul 19 12:24:18 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:24:18 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:24:18 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 12:24:18 prod-dbsnap-01 kernel: lock_and_cleanup_extent_if_need+0x1b7/0x230 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_buffered_write.isra.25+0x22e/0x710 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_file_write_iter+0x20d/0x580 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: new_sync_write+0x120/0x1a0
Jul 19 12:24:18 prod-dbsnap-01 kernel: __vfs_write+0x29/0x40
Jul 19 12:24:18 prod-dbsnap-01 kernel: vfs_write+0xb2/0x1b0
Jul 19 12:24:18 prod-dbsnap-01 kernel: ksys_write+0x61/0xd0
Jul 19 12:24:18 prod-dbsnap-01 kernel: __x64_sys_write+0x1a/0x20
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:24:18 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:24:18 prod-dbsnap-01 kernel: RIP: 0033:0x7fb113087680
Jul 19 12:24:18 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:24:18 prod-dbsnap-01 kernel: RSP: 002b:00007fffba159788 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Jul 19 12:24:18 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 00007fb1133e4ad0 RCX: 00007fb113087680
Jul 19 12:24:18 prod-dbsnap-01 kernel: RDX: 0000000000002000 RSI: 00000000014bb758 RDI: 00000000000003a7
Jul 19 12:24:18 prod-dbsnap-01 kernel: RBP: 0000000000002000 R08: 0000000000000009 R09: 0000000000000000
Jul 19 12:24:18 prod-dbsnap-01 kernel: R10: 959bd756f2ca9fd3 R11: 0000000000000246 R12: 0000000000002000
Jul 19 12:24:18 prod-dbsnap-01 kernel: R13: 00000000014bb758 R14: 000000000a000010 R15: 00007fb1134937f0
Jul 19 12:24:18 prod-dbsnap-01 kernel: INFO: task postgres:2444 blocked for more than 122 seconds.
Jul 19 12:24:18 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:24:18 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:24:18 prod-dbsnap-01 kernel: postgres D 0 2444 1796 0x00004004
Jul 19 12:24:18 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:24:18 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:24:18 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:24:18 prod-dbsnap-01 kernel: io_schedule+0x16/0x40
Jul 19 12:24:18 prod-dbsnap-01 kernel: wait_on_page_bit+0x1c0/0x270
Jul 19 12:24:18 prod-dbsnap-01 kernel: ? file_fdatawait_range+0x30/0x30
Jul 19 12:24:18 prod-dbsnap-01 kernel: wait_on_page_writeback+0x48/0xa0
Jul 19 12:24:18 prod-dbsnap-01 kernel: extent_write_cache_pages+0x214/0x4c0 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: extent_writepages+0x4f/0x90 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: ? tcp_push+0xde/0x110
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_writepages+0xe/0x10 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_writepages+0x1f/0x70
Jul 19 12:24:18 prod-dbsnap-01 kernel: __filemap_fdatawrite_range+0xc6/0x100
Jul 19 12:24:18 prod-dbsnap-01 kernel: filemap_fdatawrite_range+0x13/0x20
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_fdatawrite_range+0x20/0x50 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: start_ordered_ops+0x4c/0x90 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: ? __sys_sendto+0x107/0x1a0
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_sync_file+0xce/0x410 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 12:24:18 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:24:18 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:24:18 prod-dbsnap-01 kernel: RIP: 0033:0x7f49e5b64310
Jul 19 12:24:18 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:24:18 prod-dbsnap-01 kernel: RSP: 002b:00007ffd950c4088 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 19 12:24:18 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000019ac2 RCX: 00007f49e5b64310
Jul 19 12:24:18 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 0000000000019ac2 RDI: 0000000000000004
Jul 19 12:24:18 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 19 12:24:18 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 19 12:24:18 prod-dbsnap-01 kernel: R13: 0000000002c208f9 R14: 00007f49d59c5280 R15: 0000000000003d20
Jul 19 12:24:18 prod-dbsnap-01 kernel: INFO: task postgres:2445 blocked for more than 122 seconds.
Jul 19 12:24:18 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 12:24:18 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 12:24:18 prod-dbsnap-01 kernel: postgres D 0 2445 1801 0x00004000
Jul 19 12:24:18 prod-dbsnap-01 kernel: Call Trace:
Jul 19 12:24:18 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 12:24:18 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_start_ordered_extent+0x104/0x140 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_wait_ordered_range+0xca/0x110 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: btrfs_sync_file+0x1f8/0x410 [btrfs]
Jul 19 12:24:18 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 12:24:18 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 19 12:24:18 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 12:24:18 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 12:24:18 prod-dbsnap-01 kernel: RIP: 0033:0x7f866870a310
Jul 19 12:24:18 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 12:24:18 prod-dbsnap-01 kernel: RSP: 002b:00007ffdc5243748 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 19 12:24:18 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000009312 RCX: 00007f866870a310
Jul 19 12:24:18 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 0000000000009312 RDI: 0000000000000004
Jul 19 12:24:18 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 19 12:24:18 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 19 12:24:18 prod-dbsnap-01 kernel: R13: 0000000002c30571 R14: 00007f865856b280 R15: 0000000000000038
Jul 19 13:02:23 prod-dbsnap-01 kernel: INFO: task btrfs-cleaner:1400 blocked for more than 122 seconds.
Jul 19 13:02:23 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:02:23 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:02:23 prod-dbsnap-01 kernel: btrfs-cleaner D 0 1400 2 0x80004000
Jul 19 13:02:23 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:02:23 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:02:23 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:02:23 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:02:23 prod-dbsnap-01 kernel: start_transaction+0x377/0x4a0 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: btrfs_start_transaction+0x1e/0x20 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: btrfs_drop_snapshot+0x500/0x960 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: btrfs_clean_one_deleted_snapshot+0xcb/0x120 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: cleaner_kthread+0xeb/0x140 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 13:02:23 prod-dbsnap-01 kernel: ? btree_invalidatepage+0xd0/0xd0 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 13:02:23 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 13:02:23 prod-dbsnap-01 kernel: INFO: task postgres:3423 blocked for more than 122 seconds.
Jul 19 13:02:23 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:02:23 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:02:23 prod-dbsnap-01 kernel: postgres D 0 3423 3269 0x00004004
Jul 19 13:02:23 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:02:23 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:02:23 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:02:23 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:02:23 prod-dbsnap-01 kernel: start_transaction+0x377/0x4a0 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: btrfs_start_transaction+0x1e/0x20 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: btrfs_sync_file+0x335/0x410 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 13:02:23 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 13:02:23 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 19 13:02:23 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 13:02:23 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 13:02:23 prod-dbsnap-01 kernel: RIP: 0033:0x7fb03c2f2310
Jul 19 13:02:23 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 13:02:23 prod-dbsnap-01 kernel: RSP: 002b:00007ffdbacb2988 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 19 13:02:23 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 000000000000931e RCX: 00007fb03c2f2310
Jul 19 13:02:23 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 000000000000931e RDI: 0000000000000004
Jul 19 13:02:23 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 19 13:02:23 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 19 13:02:23 prod-dbsnap-01 kernel: R13: 0000000000ee19f1 R14: 00007fb02c153280 R15: 0000000000000f08
Jul 19 13:02:23 prod-dbsnap-01 kernel: INFO: task postgres:4039 blocked for more than 122 seconds.
Jul 19 13:02:23 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:02:23 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:02:23 prod-dbsnap-01 kernel: postgres D 0 4039 4036 0x00004000
Jul 19 13:02:23 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:02:23 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:02:23 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:02:23 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:02:23 prod-dbsnap-01 kernel: start_transaction+0x377/0x4a0 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: btrfs_start_transaction+0x1e/0x20 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: btrfs_sync_file+0x335/0x410 [btrfs]
Jul 19 13:02:23 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 13:02:23 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 13:02:23 prod-dbsnap-01 kernel: __x64_sys_fsync+0x14/0x20
Jul 19 13:02:23 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 13:02:23 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 13:02:23 prod-dbsnap-01 kernel: RIP: 0033:0x7f31f038bd00
Jul 19 13:02:23 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 13:02:23 prod-dbsnap-01 kernel: RSP: 002b:00007ffff1c80508 EFLAGS: 00000246 ORIG_RAX: 000000000000004a
Jul 19 13:02:23 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f31f038bd00
Jul 19 13:02:23 prod-dbsnap-01 kernel: RDX: 0000000000000180 RSI: 0000000000000002 RDI: 0000000000000003
Jul 19 13:02:23 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 4231303030303030 R09: 00007f31ede5720d
Jul 19 13:02:23 prod-dbsnap-01 kernel: R10: 00007f31ee1d1c8c R11: 0000000000000246 R12: 00007ffff1c80ed0
Jul 19 13:02:23 prod-dbsnap-01 kernel: R13: 0000000000000000 R14: 0000000000000014 R15: 00007ffff1c80ed0
Jul 19 13:04:26 prod-dbsnap-01 kernel: INFO: task btrfs-cleaner:1400 blocked for more than 245 seconds.
Jul 19 13:04:26 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:04:26 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs-cleaner D 0 1400 2 0x80004000
Jul 19 13:04:26 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:04:26 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:04:26 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:04:26 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:04:26 prod-dbsnap-01 kernel: start_transaction+0x377/0x4a0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_start_transaction+0x1e/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_drop_snapshot+0x500/0x960 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_clean_one_deleted_snapshot+0xcb/0x120 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: cleaner_kthread+0xeb/0x140 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? btree_invalidatepage+0xd0/0xd0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 13:04:26 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 13:04:26 prod-dbsnap-01 kernel: INFO: task kworker/u256:3:2678 blocked for more than 122 seconds.
Jul 19 13:04:26 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:04:26 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:04:26 prod-dbsnap-01 kernel: kworker/u256:3 D 0 2678 2 0x80004000
Jul 19 13:04:26 prod-dbsnap-01 kernel: Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:04:26 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:04:26 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:04:26 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:04:26 prod-dbsnap-01 kernel: start_transaction+0x316/0x4a0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_join_transaction+0x1d/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_finish_ordered_io+0x45a/0x7c0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? x86_gsbase_write_task+0x20/0x30
Jul 19 13:04:26 prod-dbsnap-01 kernel: finish_ordered_fn+0x15/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: normal_work_helper+0xc5/0x320 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? pwq_activate_delayed_work+0x42/0xb0
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_endio_write_helper+0x12/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: process_one_work+0x179/0x3a0
Jul 19 13:04:26 prod-dbsnap-01 kernel: worker_thread+0x4f/0x3e0
Jul 19 13:04:26 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? max_active_store+0x80/0x80
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 13:04:26 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 13:04:26 prod-dbsnap-01 kernel: INFO: task kworker/u256:8:2683 blocked for more than 122 seconds.
Jul 19 13:04:26 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:04:26 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:04:26 prod-dbsnap-01 kernel: kworker/u256:8 D 0 2683 2 0x80004000
Jul 19 13:04:26 prod-dbsnap-01 kernel: Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:04:26 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:04:26 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:04:26 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:04:26 prod-dbsnap-01 kernel: start_transaction+0x316/0x4a0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_join_transaction+0x1d/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_finish_ordered_io+0x45a/0x7c0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: finish_ordered_fn+0x15/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: normal_work_helper+0xc5/0x320 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? pwq_activate_delayed_work+0x42/0xb0
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_endio_write_helper+0x12/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: process_one_work+0x179/0x3a0
Jul 19 13:04:26 prod-dbsnap-01 kernel: worker_thread+0x4f/0x3e0
Jul 19 13:04:26 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? max_active_store+0x80/0x80
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 13:04:26 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 13:04:26 prod-dbsnap-01 kernel: INFO: task kworker/u256:9:2684 blocked for more than 122 seconds.
Jul 19 13:04:26 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:04:26 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:04:26 prod-dbsnap-01 kernel: kworker/u256:9 D 0 2684 2 0x80004000
Jul 19 13:04:26 prod-dbsnap-01 kernel: Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:04:26 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:04:26 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:04:26 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:04:26 prod-dbsnap-01 kernel: start_transaction+0x316/0x4a0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_join_transaction+0x1d/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_finish_ordered_io+0x45a/0x7c0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? __switch_to_asm+0x40/0x70
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? x86_gsbase_write_task+0x20/0x30
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? __switch_to_asm+0x34/0x70
Jul 19 13:04:26 prod-dbsnap-01 kernel: finish_ordered_fn+0x15/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: normal_work_helper+0xc5/0x320 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? pwq_activate_delayed_work+0x42/0xb0
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_endio_write_helper+0x12/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: process_one_work+0x179/0x3a0
Jul 19 13:04:26 prod-dbsnap-01 kernel: worker_thread+0x4f/0x3e0
Jul 19 13:04:26 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? max_active_store+0x80/0x80
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 13:04:26 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 13:04:26 prod-dbsnap-01 kernel: INFO: task kworker/u256:13:3321 blocked for more than 122 seconds.
Jul 19 13:04:26 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:04:26 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:04:26 prod-dbsnap-01 kernel: kworker/u256:13 D 0 3321 2 0x80004000
Jul 19 13:04:26 prod-dbsnap-01 kernel: Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:04:26 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:04:26 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:04:26 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:04:26 prod-dbsnap-01 kernel: start_transaction+0x316/0x4a0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_join_transaction+0x1d/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_finish_ordered_io+0x45a/0x7c0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: finish_ordered_fn+0x15/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: normal_work_helper+0xc5/0x320 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? pwq_activate_delayed_work+0x42/0xb0
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_endio_write_helper+0x12/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: process_one_work+0x179/0x3a0
Jul 19 13:04:26 prod-dbsnap-01 kernel: worker_thread+0x4f/0x3e0
Jul 19 13:04:26 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? max_active_store+0x80/0x80
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 13:04:26 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
Jul 19 13:04:26 prod-dbsnap-01 kernel: INFO: task postgres:3423 blocked for more than 245 seconds.
Jul 19 13:04:26 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:04:26 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:04:26 prod-dbsnap-01 kernel: postgres D 0 3423 3269 0x00004004
Jul 19 13:04:26 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:04:26 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:04:26 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:04:26 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:04:26 prod-dbsnap-01 kernel: start_transaction+0x377/0x4a0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_start_transaction+0x1e/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_sync_file+0x335/0x410 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: vfs_fsync_range+0x3f/0x80
Jul 19 13:04:26 prod-dbsnap-01 kernel: do_fsync+0x3d/0x70
Jul 19 13:04:26 prod-dbsnap-01 kernel: __x64_sys_fdatasync+0x17/0x20
Jul 19 13:04:26 prod-dbsnap-01 kernel: do_syscall_64+0x60/0x1c0
Jul 19 13:04:26 prod-dbsnap-01 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 19 13:04:26 prod-dbsnap-01 kernel: RIP: 0033:0x7fb03c2f2310
Jul 19 13:04:26 prod-dbsnap-01 kernel: Code: Bad RIP value.
Jul 19 13:04:26 prod-dbsnap-01 kernel: RSP: 002b:00007ffdbacb2988 EFLAGS: 00000246 ORIG_RAX: 000000000000004b
Jul 19 13:04:26 prod-dbsnap-01 kernel: RAX: ffffffffffffffda RBX: 000000000000931e RCX: 00007fb03c2f2310
Jul 19 13:04:26 prod-dbsnap-01 kernel: RDX: 0000000000000027 RSI: 000000000000931e RDI: 0000000000000004
Jul 19 13:04:26 prod-dbsnap-01 kernel: RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
Jul 19 13:04:26 prod-dbsnap-01 kernel: R10: 0000000000004000 R11: 0000000000000246 R12: 0000000000000004
Jul 19 13:04:26 prod-dbsnap-01 kernel: R13: 0000000000ee19f1 R14: 00007fb02c153280 R15: 0000000000000f08
Jul 19 13:04:26 prod-dbsnap-01 kernel: INFO: task kworker/u256:1:3787 blocked for more than 122 seconds.
Jul 19 13:04:26 prod-dbsnap-01 kernel: Not tainted 5.2.1-1.el7.elrepo.x86_64 #1
Jul 19 13:04:26 prod-dbsnap-01 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 19 13:04:26 prod-dbsnap-01 kernel: kworker/u256:1 D 0 3787 2 0x80004000
Jul 19 13:04:26 prod-dbsnap-01 kernel: Workqueue: btrfs-endio-write btrfs_endio_write_helper [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: Call Trace:
Jul 19 13:04:26 prod-dbsnap-01 kernel: __schedule+0x2a9/0x650
Jul 19 13:04:26 prod-dbsnap-01 kernel: schedule+0x38/0xa0
Jul 19 13:04:26 prod-dbsnap-01 kernel: wait_current_trans+0xc5/0x100 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? remove_wait_queue+0x60/0x60
Jul 19 13:04:26 prod-dbsnap-01 kernel: start_transaction+0x316/0x4a0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_join_transaction+0x1d/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_finish_ordered_io+0x45a/0x7c0 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: finish_ordered_fn+0x15/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: normal_work_helper+0xc5/0x320 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? pwq_activate_delayed_work+0x42/0xb0
Jul 19 13:04:26 prod-dbsnap-01 kernel: btrfs_endio_write_helper+0x12/0x20 [btrfs]
Jul 19 13:04:26 prod-dbsnap-01 kernel: process_one_work+0x179/0x3a0
Jul 19 13:04:26 prod-dbsnap-01 kernel: worker_thread+0x4f/0x3e0
Jul 19 13:04:26 prod-dbsnap-01 kernel: kthread+0x105/0x140
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? max_active_store+0x80/0x80
Jul 19 13:04:26 prod-dbsnap-01 kernel: ? kthread_bind+0x20/0x20
Jul 19 13:04:26 prod-dbsnap-01 kernel: ret_from_fork+0x35/0x40
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: Deadlock between btrfs-transacti and userland on 5.2.1
2019-07-18 12:23 ` Deadlock between btrfs-transacti and userland on 5.2.1 Drazen Kacar
2019-07-19 12:12 ` Drazen Kacar
@ 2019-09-11 14:59 ` Filipe Manana
1 sibling, 0 replies; 3+ messages in thread
From: Filipe Manana @ 2019-09-11 14:59 UTC (permalink / raw)
To: Drazen Kacar; +Cc: linux-btrfs
On Thu, Jul 18, 2019 at 1:25 PM Drazen Kacar <drazen.kacar@oradian.com> wrote:
>
> Hello,
>
> I think I've encountered a deadlock between btrfs-transacti and postgres
> process(es). This is system information (btrfs fi usage obtained after
> poweroff and boot):
>
> # cat /etc/redhat-release
> CentOS Linux release 7.6.1810 (Core)
>
> # uname -a
> Linux prod-dbsnap-01 5.2.1-1.el7.elrepo.x86_64 #1 SMP Sun Jul 14 08:15:04 EDT 2019 x86_64 x86_64 x86_64 GNU/Linux
>
> # btrfs --version
> btrfs-progs v5.2
>
> # btrfs filesystem usage /data/pg_data
> Overall:
> Device size: 2.00TiB
> Device allocated: 345.03GiB
> Device unallocated: 1.66TiB
> Device missing: 0.00B
> Used: 338.07GiB
> Free (estimated): 1.67TiB (min: 854.27GiB)
> Data ratio: 1.00
> Metadata ratio: 2.00
> Global reserve: 512.00MiB (used: 0.00B)
>
> Data,RAID0: Size:332.00GiB, Used:329.22GiB
> /dev/sdb 83.00GiB
> /dev/sdc 83.00GiB
> /dev/sdd 83.00GiB
> /dev/sde 83.00GiB
>
> Metadata,RAID10: Size:6.50GiB, Used:4.42GiB
> /dev/sdb 3.25GiB
> /dev/sdc 3.25GiB
> /dev/sdd 3.25GiB
> /dev/sde 3.25GiB
>
> System,RAID10: Size:16.00MiB, Used:48.00KiB
> /dev/sdb 8.00MiB
> /dev/sdc 8.00MiB
> /dev/sdd 8.00MiB
> /dev/sde 8.00MiB
>
> Unallocated:
> /dev/sdb 425.74GiB
> /dev/sdc 425.74GiB
> /dev/sdd 425.74GiB
> /dev/sde 425.74GiB
>
> There were three btrfs subvolumes and on each one there was a Postgres
> database slave doing recovery (single threaded writing). But there was a
> lot of writing. And prior to starting Postgres slaves I was restoring base
> backup from the backup server, which was being done by a number of
> parallel rsync processes (12 at most, I think).
>
> The file system is mounted with:
>
> # grep btrfs /proc/mounts
> /dev/sdd /data/pg_data btrfs rw,noatime,compress-force=zstd:3,space_cache,subvolid=5,subvol=/ 0 0
>
> After several hours I got this in /var/log/messages:
>
> # grep 'INFO: task .*blocked for more than' messages
> Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task btrfs-transacti:1361 blocked for more than 122 seconds.
> Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:62682 blocked for more than 122 seconds.
> Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:80145 blocked for more than 122 seconds.
> Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:87299 blocked for more than 122 seconds.
> Jul 17 16:47:09 prod-dbsnap-01 kernel: INFO: task postgres:93108 blocked for more than 122 seconds.
> Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task btrfs-transacti:1361 blocked for more than 245 seconds.
> Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:62682 blocked for more than 245 seconds.
> Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:80145 blocked for more than 245 seconds.
> Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:87299 blocked for more than 245 seconds.
> Jul 17 16:49:12 prod-dbsnap-01 kernel: INFO: task postgres:93108 blocked for more than 245 seconds.
>
> Full log is in the attachment. It seems to me that there is a deadlock
> between btrfs-transacti and any process which is trying to write
> something (not sure about reading). While this was going on the cpu
> usage (according to top) was non-existant. There are 4 cpus (it's a virtual
> machine in VmWare) and 3 were 100% idle. The 4th was 100% in
> waiting. (I didn't find out which process was on that cpu, unfortunately.)
>
> I powered off the machine (yesterday), booted this morning and things
> are working without errors. I stopped postgres clusters, though.
>
> I have a few questions:
>
> 1. After something like this happens and the machine is rebooted is there
> a procedure which would lower the probablity of encountering the deadlock
> again (maybe btrfs scrub or btrfs defragment or something like that)? This
> happened after a heavy write activity, so maybe fragmentation had
> something to do with it.
>
> 2. Should I run btrfsck (or something else) to verify on-disk integrity after a
> problem like this? Or it's just an in-memory problem, so I can assume that
> nothing bad happened to the data on disks.
>
> 3. I'd like to write a watchdog program to catch deadlocks and reboot
> (probably power-cycle) the VM, but I'm not sure what would the appropriate
> check be. Does it have to write something to the disk or reading would be
> sufficient? And how to bypass the OS buffer cache (fsync() or O_DIRECT
> should do it for writing, but I'm not sure about reading)?
>
> What would the appropriate timeout be? (If the operation doesn't
> complete in xx seconds a reboot should be triggered, but I don't know how
> many seconds to wait when there's a heavy load and things are just slow,
> but there's no deadlock.)
>
> Should I put watchdog process in real-time class (or however the equivalent
> is called on Linux)? Since this is a mainline kernel, I'm not sure if I could assume
> that real-time support won't have bugs of its own.
>
> And last, but not least, is there additional data that could help with debugging
> issues like this? (If possible, something that could be programmed into
> watchdog service.)
It's a regression introduced in 5.2
Fix just sent: https://lore.kernel.org/linux-btrfs/20190911145542.1125-1-fdmanana@kernel.org/T/#u
Thanks.
--
Filipe David Manana,
“Whether you think you can, or you think you can't — you're right.”
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2019-09-11 14:59 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <DB8PR03MB56287A9E527898E5727BB41599C80@DB8PR03MB5628.eurprd03.prod.outlook.com>
2019-07-18 12:23 ` Deadlock between btrfs-transacti and userland on 5.2.1 Drazen Kacar
2019-07-19 12:12 ` Drazen Kacar
2019-09-11 14:59 ` Filipe Manana
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).