Long boot time with PA 4 #2
Comments
flar2
pushed a commit
that referenced
this issue
Nov 27, 2016
Otherwise, we can get mismatched largest extent information. One example is: 1. mount f2fs w/ extent_cache 2. make a small extent 3. umount 4. mount f2fs w/o extent_cache 5. update the largest extent 6. umount 7. mount f2fs w/ extent_cache 8. get the old extent made by #2 Signed-off-by: Jaegeuk Kim <[email protected]>
apascual89
pushed a commit
to apascual89/flo
that referenced
this issue
Sep 9, 2017
commit 6fdda9a9c5db367130cf32df5d6618d08b89f46a upstream.
As part of normal operaions, the hrtimer subsystem frequently calls
into the timekeeping code, creating a locking order of
hrtimer locks -> timekeeping locks
clock_was_set_delayed() was suppoed to allow us to avoid deadlocks
between the timekeeping the hrtimer subsystem, so that we could
notify the hrtimer subsytem the time had changed while holding
the timekeeping locks. This was done by scheduling delayed work
that would run later once we were out of the timekeeing code.
But unfortunately the lock chains are complex enoguh that in
scheduling delayed work, we end up eventually trying to grab
an hrtimer lock.
Sasha Levin noticed this in testing when the new seqlock lockdep
enablement triggered the following (somewhat abrieviated) message:
[ 251.100221] ======================================================
[ 251.100221] [ INFO: possible circular locking dependency detected ]
[ 251.100221] 3.13.0-rc2-next-20131206-sasha-00005-g8be2375-dirty #4053 Not tainted
[ 251.101967] -------------------------------------------------------
[ 251.101967] kworker/10:1/4506 is trying to acquire lock:
[ 251.101967] (timekeeper_seq){----..}, at: [<ffffffff81160e96>] retrigger_next_event+0x56/0x70
[ 251.101967]
[ 251.101967] but task is already holding lock:
[ 251.101967] (hrtimer_bases.lock#11){-.-...}, at: [<ffffffff81160e7c>] retrigger_next_event+0x3c/0x70
[ 251.101967]
[ 251.101967] which lock already depends on the new lock.
[ 251.101967]
[ 251.101967]
[ 251.101967] the existing dependency chain (in reverse order) is:
[ 251.101967]
-> flar2#5 (hrtimer_bases.lock#11){-.-...}:
[snipped]
-> flar2#4 (&rt_b->rt_runtime_lock){-.-...}:
[snipped]
-> flar2#3 (&rq->lock){-.-.-.}:
[snipped]
-> flar2#2 (&p->pi_lock){-.-.-.}:
[snipped]
-> flar2#1 (&(&pool->lock)->rlock){-.-...}:
[ 251.101967] [<ffffffff81194803>] validate_chain+0x6c3/0x7b0
[ 251.101967] [<ffffffff81194d9d>] __lock_acquire+0x4ad/0x580
[ 251.101967] [<ffffffff81194ff2>] lock_acquire+0x182/0x1d0
[ 251.101967] [<ffffffff84398500>] _raw_spin_lock+0x40/0x80
[ 251.101967] [<ffffffff81153e69>] __queue_work+0x1a9/0x3f0
[ 251.101967] [<ffffffff81154168>] queue_work_on+0x98/0x120
[ 251.101967] [<ffffffff81161351>] clock_was_set_delayed+0x21/0x30
[ 251.101967] [<ffffffff811c4bd1>] do_adjtimex+0x111/0x160
[ 251.101967] [<ffffffff811e2711>] compat_sys_adjtimex+0x41/0x70
[ 251.101967] [<ffffffff843a4b49>] ia32_sysret+0x0/0x5
[ 251.101967]
-> #0 (timekeeper_seq){----..}:
[snipped]
[ 251.101967] other info that might help us debug this:
[ 251.101967]
[ 251.101967] Chain exists of:
timekeeper_seq --> &rt_b->rt_runtime_lock --> hrtimer_bases.lock#11
[ 251.101967] Possible unsafe locking scenario:
[ 251.101967]
[ 251.101967] CPU0 CPU1
[ 251.101967] ---- ----
[ 251.101967] lock(hrtimer_bases.lock#11);
[ 251.101967] lock(&rt_b->rt_runtime_lock);
[ 251.101967] lock(hrtimer_bases.lock#11);
[ 251.101967] lock(timekeeper_seq);
[ 251.101967]
[ 251.101967] *** DEADLOCK ***
[ 251.101967]
[ 251.101967] 3 locks held by kworker/10:1/4506:
[ 251.101967] #0: (events){.+.+.+}, at: [<ffffffff81154960>] process_one_work+0x200/0x530
[ 251.101967] flar2#1: (hrtimer_work){+.+...}, at: [<ffffffff81154960>] process_one_work+0x200/0x530
[ 251.101967] flar2#2: (hrtimer_bases.lock#11){-.-...}, at: [<ffffffff81160e7c>] retrigger_next_event+0x3c/0x70
[ 251.101967]
[ 251.101967] stack backtrace:
[ 251.101967] CPU: 10 PID: 4506 Comm: kworker/10:1 Not tainted 3.13.0-rc2-next-20131206-sasha-00005-g8be2375-dirty #4053
[ 251.101967] Workqueue: events clock_was_set_work
So the best solution is to avoid calling clock_was_set_delayed() while
holding the timekeeping lock, and instead using a flag variable to
decide if we should call clock_was_set() once we've released the locks.
This works for the case here, where the do_adjtimex() was the deadlock
trigger point. Unfortuantely, in update_wall_time() we still hold
the jiffies lock, which would deadlock with the ipi triggered by
clock_was_set(), preventing us from calling it even after we drop the
timekeeping lock. So instead call clock_was_set_delayed() at that point.
Cc: Thomas Gleixner <[email protected]>
Cc: Prarit Bhargava <[email protected]>
Cc: Richard Cochran <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Sasha Levin <[email protected]>
Reported-by: Sasha Levin <[email protected]>
Tested-by: Sasha Levin <[email protected]>
Signed-off-by: John Stultz <[email protected]>
Signed-off-by: Greg Kroah-Hartman <[email protected]>
rx78gp01
pushed a commit
to rx78gp01/flo
that referenced
this issue
Jul 8, 2019
…ap()
Error report likely result in IO so it is bad idea to do it from
atomic context.
This patch should fix following issue:
BUG: sleeping function called from invalid context at include/linux/buffer_head.h:349
in_atomic(): 1, irqs_disabled(): 0, pid: 137, name: kworker/u128:1
5 locks held by kworker/u128:1/137:
#0: ("writeback"){......}, at: [<ffffffff81085618>] process_one_work+0x228/0x4d0
flar2#1: ((&(&wb->dwork)->work)){......}, at: [<ffffffff81085618>] process_one_work+0x228/0x4d0
flar2#2: (jbd2_handle){......}, at: [<ffffffff81242622>] start_this_handle+0x712/0x7b0
flar2#3: (&ei->i_data_sem){......}, at: [<ffffffff811fa387>] ext4_map_blocks+0x297/0x430
flar2#4: (&(&bgl->locks[i].lock)->rlock){......}, at: [<ffffffff811f3180>] ext4_read_block_bitmap_nowait+0x5d0/0x630
CPU: 3 PID: 137 Comm: kworker/u128:1 Not tainted 3.17.0-rc2-00184-g82752e4 #165
Hardware name: Intel Corporation W2600CR/W2600CR, BIOS SE5C600.86B.99.99.x028.061320111235 06/13/2011
Workqueue: writeback bdi_writeback_workfn (flush-1:0)
0000000000000411 ffff880813777288 ffffffff815c7fdc ffff880813777288
ffff880813a8bba0 ffff8808137772a8 ffffffff8108fb30 ffff880803e01e38
ffff880803e01e38 ffff8808137772c8 ffffffff811a8d53 ffff88080ecc6000
Call Trace:
[<ffffffff815c7fdc>] dump_stack+0x51/0x6d
[<ffffffff8108fb30>] __might_sleep+0xf0/0x100
[<ffffffff811a8d53>] __sync_dirty_buffer+0x43/0xe0
[<ffffffff811a8e03>] sync_dirty_buffer+0x13/0x20
[<ffffffff8120f581>] ext4_commit_super+0x1d1/0x230
[<ffffffff8120fa03>] save_error_info+0x23/0x30
[<ffffffff8120fd06>] __ext4_error+0xb6/0xd0
[<ffffffff8120f260>] ? ext4_group_desc_csum+0x140/0x190
[<ffffffff811f2d8c>] ext4_read_block_bitmap_nowait+0x1dc/0x630
[<ffffffff8122e23a>] ext4_mb_init_cache+0x21a/0x8f0
[<ffffffff8113ae95>] ? lru_cache_add+0x55/0x60
[<ffffffff8112e16c>] ? add_to_page_cache_lru+0x6c/0x80
[<ffffffff8122eaa0>] ext4_mb_init_group+0x190/0x280
[<ffffffff8122ec51>] ext4_mb_good_group+0xc1/0x190
[<ffffffff8123309a>] ext4_mb_regular_allocator+0x17a/0x410
[<ffffffff8122c821>] ? ext4_mb_use_preallocated+0x31/0x380
[<ffffffff81233535>] ? ext4_mb_new_blocks+0x205/0x8e0
[<ffffffff8116ed5c>] ? kmem_cache_alloc+0xfc/0x180
[<ffffffff812335b0>] ext4_mb_new_blocks+0x280/0x8e0
[<ffffffff8116f2c4>] ? __kmalloc+0x144/0x1c0
[<ffffffff81221797>] ? ext4_find_extent+0x97/0x320
[<ffffffff812257f4>] ext4_ext_map_blocks+0xbc4/0x1050
[<ffffffff811fa387>] ? ext4_map_blocks+0x297/0x430
[<ffffffff811fa3ab>] ext4_map_blocks+0x2bb/0x430
[<ffffffff81200e43>] ? ext4_init_io_end+0x23/0x50
[<ffffffff811feb44>] ext4_writepages+0x564/0xaf0
[<ffffffff815cde3b>] ? _raw_spin_unlock+0x2b/0x40
[<ffffffff810ac7bd>] ? lock_release_non_nested+0x2fd/0x3c0
[<ffffffff811a009e>] ? writeback_sb_inodes+0x10e/0x490
[<ffffffff811a009e>] ? writeback_sb_inodes+0x10e/0x490
[<ffffffff811377e3>] do_writepages+0x23/0x40
[<ffffffff8119c8ce>] __writeback_single_inode+0x9e/0x280
[<ffffffff811a026b>] writeback_sb_inodes+0x2db/0x490
[<ffffffff811a0664>] wb_writeback+0x174/0x2d0
[<ffffffff810ac359>] ? lock_release_holdtime+0x29/0x190
[<ffffffff811a0863>] wb_do_writeback+0xa3/0x200
[<ffffffff811a0a40>] bdi_writeback_workfn+0x80/0x230
[<ffffffff81085618>] ? process_one_work+0x228/0x4d0
[<ffffffff810856cd>] process_one_work+0x2dd/0x4d0
[<ffffffff81085618>] ? process_one_work+0x228/0x4d0
[<ffffffff81085c1d>] worker_thread+0x35d/0x460
[<ffffffff810858c0>] ? process_one_work+0x4d0/0x4d0
[<ffffffff810858c0>] ? process_one_work+0x4d0/0x4d0
[<ffffffff8108a885>] kthread+0xf5/0x100
[<ffffffff810990e5>] ? local_clock+0x25/0x30
[<ffffffff8108a790>] ? __init_kthread_worker+0x70/0x70
[<ffffffff815ce2ac>] ret_from_fork+0x7c/0xb0
[<ffffffff8108a790>] ? __init_kthread_work
Change-Id: I9dfcac3c8527672298e3bc052cde6890ec40a0fc
Signed-off-by: Dmitry Monakhov <[email protected]>
Signed-off-by: Theodore Ts'o <[email protected]>
Cc: [email protected]
rx78gp01
pushed a commit
to rx78gp01/flo
that referenced
this issue
Jul 8, 2019
The logic in __ip6_append_data() assumes that the MTU is at least large enough for the headers. A device's MTU may be adjusted after being added while sendmsg() is processing data, resulting in __ip6_append_data() seeing any MTU. For an mtu smaller than the size of the fragmentation header, the math results in a negative 'maxfraglen', which causes problems when refragmenting any previous skb in the skb_write_queue, leaving it possibly malformed. Instead sendmsg returns EINVAL when the mtu is calculated to be less than IPV6_MIN_MTU. Found by syzkaller: kernel BUG at ./include/linux/skbuff.h:2064! invalid opcode: 0000 [flar2#1] SMP KASAN Dumping ftrace buffer: (ftrace buffer empty) Modules linked in: CPU: 1 PID: 14216 Comm: syz-executor5 Not tainted 4.13.0-rc4+ flar2#2 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 task: ffff8801d0b68580 task.stack: ffff8801ac6b8000 RIP: 0010:__skb_pull include/linux/skbuff.h:2064 [inline] RIP: 0010:__ip6_make_skb+0x18cf/0x1f70 net/ipv6/ip6_output.c:1617 RSP: 0018:ffff8801ac6bf570 EFLAGS: 00010216 RAX: 0000000000010000 RBX: 0000000000000028 RCX: ffffc90003cce000 RDX: 00000000000001b8 RSI: ffffffff839df06f RDI: ffff8801d9478ca0 RBP: ffff8801ac6bf780 R08: ffff8801cc3f1dbc R09: 0000000000000000 R10: ffff8801ac6bf7a0 R11: 43cb4b7b1948a9e7 R12: ffff8801cc3f1dc8 R13: ffff8801cc3f1d40 R14: 0000000000001036 R15: dffffc0000000000 FS: 00007f43d740c700(0000) GS:ffff8801dc100000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 CR2: 00007f7834984000 CR3: 00000001d79b9000 CR4: 00000000001406e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 Call Trace: ip6_finish_skb include/net/ipv6.h:911 [inline] udp_v6_push_pending_frames+0x255/0x390 net/ipv6/udp.c:1093 udpv6_sendmsg+0x280d/0x31a0 net/ipv6/udp.c:1363 inet_sendmsg+0x11f/0x5e0 net/ipv4/af_inet.c:762 sock_sendmsg_nosec net/socket.c:633 [inline] sock_sendmsg+0xca/0x110 net/socket.c:643 SYSC_sendto+0x352/0x5a0 net/socket.c:1750 SyS_sendto+0x40/0x50 net/socket.c:1718 entry_SYSCALL_64_fastpath+0x1f/0xbe RIP: 0033:0x4512e9 RSP: 002b:00007f43d740bc08 EFLAGS: 00000216 ORIG_RAX: 000000000000002c RAX: ffffffffffffffda RBX: 00000000007180a8 RCX: 00000000004512e9 RDX: 000000000000002e RSI: 0000000020d08000 RDI: 0000000000000005 RBP: 0000000000000086 R08: 00000000209c1000 R09: 000000000000001c R10: 0000000000040800 R11: 0000000000000216 R12: 00000000004b9c69 R13: 00000000ffffffff R14: 0000000000000005 R15: 00000000202c2000 Code: 9e 01 fe e9 c5 e8 ff ff e8 7f 9e 01 fe e9 4a ea ff ff 48 89 f7 e8 52 9e 01 fe e9 aa eb ff ff e8 a8 b6 cf fd 0f 0b e8 a1 b6 cf fd <0f> 0b 49 8d 45 78 4d 8d 45 7c 48 89 85 78 fe ff ff 49 8d 85 ba RIP: __skb_pull include/linux/skbuff.h:2064 [inline] RSP: ffff8801ac6bf570 RIP: __ip6_make_skb+0x18cf/0x1f70 net/ipv6/ip6_output.c:1617 RSP: ffff8801ac6bf570 Reported-by: syzbot <[email protected]> Signed-off-by: Mike Maloney <[email protected]> Reviewed-by: Eric Dumazet <[email protected]> Signed-off-by: David S. Miller <[email protected]> (cherry picked from commit 749439bfac6e1a2932c582e2699f91d329658196) Bug: 65023306 Change-Id: I3b713621c749b7fd3a070116be8996ae2e2dd6e8 Signed-off-by: Greg Hackmann <[email protected]>
rx78gp01
pushed a commit
to rx78gp01/flo
that referenced
this issue
Jun 27, 2021
There used to be only one path out of __slab_alloc(), and ALLOC_SLOWPATH got bumped in that exit path. Now there are two, and a bunch of gotos. ALLOC_SLOWPATH can now get set more than once during a single call to __slab_alloc() which is pretty bogus. Here's the sequence: 1. Enter __slab_alloc(), fall through all the way to the stat(s, ALLOC_SLOWPATH); 2. hit 'if (!freelist)', and bump DEACTIVATE_BYPASS, jump to new_slab (goto flar2#1) 3. Hit 'if (c->partial)', bump CPU_PARTIAL_ALLOC, goto redo (goto flar2#2) 4. Fall through in the same path we did before all the way to stat(s, ALLOC_SLOWPATH) 5. bump ALLOC_REFILL stat, then return Doing this is obviously bogus. It keeps us from being able to accurately compare ALLOC_SLOWPATH vs. ALLOC_FASTPATH. It also means that the total number of allocs always exceeds the total number of frees. This patch moves stat(s, ALLOC_SLOWPATH) to be called from the same place that __slab_alloc() is. This makes it much less likely that ALLOC_SLOWPATH will get botched again in the spaghetti-code inside __slab_alloc(). Signed-off-by: Dave Hansen <[email protected]> Acked-by: Christoph Lameter <[email protected]> Acked-by: David Rientjes <[email protected]> Cc: Pekka Enberg <[email protected]> Signed-off-by: Andrew Morton <[email protected]> Signed-off-by: Linus Torvalds <[email protected]>
rx78gp01
pushed a commit
to rx78gp01/flo
that referenced
this issue
Jan 16, 2023
There used to be only one path out of __slab_alloc(), and ALLOC_SLOWPATH got bumped in that exit path. Now there are two, and a bunch of gotos. ALLOC_SLOWPATH can now get set more than once during a single call to __slab_alloc() which is pretty bogus. Here's the sequence: 1. Enter __slab_alloc(), fall through all the way to the stat(s, ALLOC_SLOWPATH); 2. hit 'if (!freelist)', and bump DEACTIVATE_BYPASS, jump to new_slab (goto flar2#1) 3. Hit 'if (c->partial)', bump CPU_PARTIAL_ALLOC, goto redo (goto flar2#2) 4. Fall through in the same path we did before all the way to stat(s, ALLOC_SLOWPATH) 5. bump ALLOC_REFILL stat, then return Doing this is obviously bogus. It keeps us from being able to accurately compare ALLOC_SLOWPATH vs. ALLOC_FASTPATH. It also means that the total number of allocs always exceeds the total number of frees. This patch moves stat(s, ALLOC_SLOWPATH) to be called from the same place that __slab_alloc() is. This makes it much less likely that ALLOC_SLOWPATH will get botched again in the spaghetti-code inside __slab_alloc(). Signed-off-by: Dave Hansen <[email protected]> Acked-by: Christoph Lameter <[email protected]> Acked-by: David Rientjes <[email protected]> Cc: Pekka Enberg <[email protected]> Signed-off-by: Andrew Morton <[email protected]> Signed-off-by: Linus Torvalds <[email protected]>
rx78gp01
pushed a commit
to rx78gp01/flo
that referenced
this issue
Jan 16, 2023
There used to be only one path out of __slab_alloc(), and ALLOC_SLOWPATH got bumped in that exit path. Now there are two, and a bunch of gotos. ALLOC_SLOWPATH can now get set more than once during a single call to __slab_alloc() which is pretty bogus. Here's the sequence: 1. Enter __slab_alloc(), fall through all the way to the stat(s, ALLOC_SLOWPATH); 2. hit 'if (!freelist)', and bump DEACTIVATE_BYPASS, jump to new_slab (goto flar2#1) 3. Hit 'if (c->partial)', bump CPU_PARTIAL_ALLOC, goto redo (goto flar2#2) 4. Fall through in the same path we did before all the way to stat(s, ALLOC_SLOWPATH) 5. bump ALLOC_REFILL stat, then return Doing this is obviously bogus. It keeps us from being able to accurately compare ALLOC_SLOWPATH vs. ALLOC_FASTPATH. It also means that the total number of allocs always exceeds the total number of frees. This patch moves stat(s, ALLOC_SLOWPATH) to be called from the same place that __slab_alloc() is. This makes it much less likely that ALLOC_SLOWPATH will get botched again in the spaghetti-code inside __slab_alloc(). Signed-off-by: Dave Hansen <[email protected]> Acked-by: Christoph Lameter <[email protected]> Acked-by: David Rientjes <[email protected]> Cc: Pekka Enberg <[email protected]> Signed-off-by: Andrew Morton <[email protected]> Signed-off-by: Linus Torvalds <[email protected]>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Hi,
I'm experiencing very long boot times using this kernel with Paranoid Android 4 on 32gb flo. Usual boot time with original kernel is ca 40s but with ElementalX it boots 110-120s. You can find my dmesg logs below - significant delays are visible at 37s and 76s. I hope it will be fixable as it's the best kernel I've ever used.
https://www.dropbox.com/sh/9bsr281y1w2az04/wgM5grgOF_
The text was updated successfully, but these errors were encountered: