Hi: I recently see the error message below when doing the following mount option in hard drive, after a while, Kernel reports BUG_ON. The standard kernel version is 3.10.27. This issue can been seen in many other customer devices with this kernel version. There are several things worthwhile to mention beforehand: 1. I don't believe its a hardware related issue since it could be duplicated in our many devices. 2. I don't think it is a real Filesystem corruption since these box never reboot or remount during the test. 3. Devices are under heavy memory pressure when this issue occur, 4. It is not straightforward and might involve tremendous work to switch to the latest kernel version. Mount Option: /dev/sda1 on /mnt/ type ext4 (rw,nosuid,relatime,nodelalloc,journal_checksum,nobarrier,data=journal) " JBD2: Spotted dirty metadata buffer (dev = sda1, blocknr = 1766784). There's a risk of filesystem corruption in case of system crash. ........................................................... kernel BUG at fs/jbd2/commit.c:1059! [<801b0e10>] (jbd2_journal_commit_transaction+0x1304/0x177c) from [<801b569c>] (kjournald2+0xa8/0x248) [<801b569c>] (kjournald2+0xa8/0x248) from [<800414c8>] (kthread+0xa0/0xac) [<800414c8>] (kthread+0xa0/0xac) from [<8000dc98>] (ret_from_fork+0x14/0x3c) " The code is listed below at Line 1059: jbd2_journal_commit_transaction { ..................................................... J_ASSERT_BH(bh, !buffer_dirty(bh)); /* * The buffer on BJ_Forget list and not jbddirty means * it has been freed by this transaction and hence it * could not have been reallocated until this } So, I firstly get the call stack to understand why JBD2 reports Spotted dirty metadata buffer. The dump stack is listed below: 4,173710,227778211328,-;[<80015cf0>] (unwind_backtrace+0x0/0x118) from [<80011f98>] (show_stack+0x10/0x14) 4,173711,227778220057,-;[<80011f98>] (show_stack+0x10/0x14) from [<80013b5c>] (ipi_backtrace+0x70/0xa8) 4,173712,227778228492,-;[<80013b5c>] (ipi_backtrace+0x70/0xa8) from [<80013cf0>] (arch_trigger_all_cpu_backtrace+0x40/0xe0) 4,173713,227778238689,-;[<80013cf0>] (arch_trigger_all_cpu_backtrace+0x40/0xe0) from [<801ac99c>] (warn_dirty_buffer+0x2c/0x38) 4,173714,227778249227,-;[<801ac99c>] (warn_dirty_buffer+0x2c/0x38) from [<801adcc4>] (__jbd2_journal_file_buffer+0xa8/0x1d0) 4,173715,227778259500,-;[<801adcc4>] (__jbd2_journal_file_buffer+0xa8/0x1d0) from [<801ae8cc>] (jbd2_journal_dirty_metadata+0x1ec/0x258) 4,173716,227778270828,-;[<801ae8cc>] (jbd2_journal_dirty_metadata+0x1ec/0x258) from [<8018f680>] (__ext4_handle_dirty_metadata+0xe0/0x190) 4,173717,227778282332,-;[<8018f680>] (__ext4_handle_dirty_metadata+0xe0/0x190) from [<8016949c>] (write_end_fn+0x50/0x7c) 4,173718,227778292340,-;[<8016949c>] (write_end_fn+0x50/0x7c) from [<8016a860>] (ext4_walk_page_buffers+0x88/0xa0) 4,173719,227778301741,-;[<8016a860>] (ext4_walk_page_buffers+0x88/0xa0) from [<8016ee8c>] (ext4_journalled_write_end+0x160/0x308) 4,173720,227778312462,-;[<8016ee8c>] (ext4_journalled_write_end+0x160/0x308) from [<800afd44>] (generic_file_buffered_write+0x154/0x224) 4,173721,227778323775,-;[<800afd44>] (generic_file_buffered_write+0x154/0x224) from [<800b146c>] (__generic_file_aio_write+0x350/0x3a0) 4,173722,227778334999,-;[<800b146c>] (__generic_file_aio_write+0x350/0x3a0) from [<800b1510>] (generic_file_aio_write+0x54/0xb4) 4,173723,227778345615,-;[<800b1510>] (generic_file_aio_write+0x54/0xb4) from [<80165478>] (ext4_file_write+0x348/0x430) 4,173724,227778355453,-;[<80165478>] (ext4_file_write+0x348/0x430) from [<800ef3ec>] (do_sync_readv_writev+0x74/0x98) 4,173725,227778365115,-;[<800ef3ec>] (do_sync_readv_writev+0x74/0x98) from [<800f01e8>] (do_readv_writev+0xd4/0x200) 4,173726,227778374690,-;[<800f01e8>] (do_readv_writev+0xd4/0x200) from [<800f03dc>] (vfs_writev+0x58/0x70) 4,173727,227778383399,-;[<800f03dc>] (vfs_writev+0x58/0x70) from [<800f0494>] (SyS_writev+0x38/0x68) 4,173728,227778391586,-;[<800f0494>] (SyS_writev+0x38/0x68) from [<8000dbc0>] (ret_fast_syscall+0x0/0x30) Based on the comment of the JBD2 code in __jbd2_journal_file_buffer, I quote "For metadata buffers, we track dirty bit in buffer_jbddirty instead of buffer_dirty. We should not see a dirty bit set here because we clear it in do_get_write_access but e.g. tune2fs can modify the sb and set the dirty bit at any time so we try to gracefully handle that." it means jbd2 code shouldn't set this buffer_dirty anyway. and Another comment in do_get_write_access() in transaction.c, it says more, i quote " it is journaled, and we don't expect dirty buffers in that state (the buffers should be marked JBD_Dirty instead.) So either the IO is being done under our own control and this is a bug, or it's a third party IO such as dump(8) (which may leave the buffer scheduled for read --- ie. locked but not dirty) or tune2fs (which may actually havethe buffer dirtied, ugh.) " In our case, the dirty bit of buffer_head is changed between ext4_write_begin() and ext4_journalled_write_end() as bleow: " ext4_write_begin() --> BH dirty bit is 0 ext4_journalled_write_end() --> BH dirty bit is changed to 1 !!! and error is reported " Then I do an experiment change as below in ext4_journalled_write_end() to see whether the original issue could be duplicated. After almost a week test, the issue doesn't appear. Therefore, it seems there are some race conditions that change the value of BH dirty between ext4_write_begin() and ext4_journalled_write_end(). (Note: do_journal_get_write_access has already been called at ext4_write_begin ) + ret = ext4_walk_page_buffers(handle, page_buffers(page), from, + to, &partial,do_journal_get_write_access); + ret = ext4_walk_page_buffers(handle, page_buffers(page), from, to, &partial, write_end_fn); After reviewing the code, it looks although do_journal_get_write_access() imposes lock on buffer header, it doesn't lock the whole routine between ext4_write_begin() and ext4_journalled_write_end(). so i think the buffer head should be locked at the time until ext4_journalled_write_end() is finished. Initially, I imagine that I can do the following change but then I realise a existing buffer lock has already been placed in jbd2_journal_get_write_access, so making a big buffer lock will quickly become a performance issue and also involves a lot of changes. + lock all the buffer headers belonging to this page ext4_write_begin() ..................................................... ext4_journalled_write_end() + unlock all the buffer headers belonging to this page Therefore, I propose the following change for simplicity and performance: --- /linux-3.10.27_old/fs/ext4/inode.c 2014-01-15 23:29:14.000000000 +0000 +++/linux-3.10.27_new/fs/ext4/inode.c 2017-05-11 22:47:58.986146486 +0100 @@ -1084,10 +1084,18 @@ int ret; if (!buffer_mapped(bh) || buffer_freed(bh)) return 0; + + lock_buffer(); + if (buffer_dirty(bh)) { + clear_buffer_dirty(bh); + } + set_buffer_uptodate(bh); ret = ext4_handle_dirty_metadata(handle, NULL, bh); clear_buffer_meta(bh); clear_buffer_prio(bh); + + unlock_buffer(); return ret; } Thanks Jmqiao
It tells us that clk_set_parent() will potentially goes to sleep under some circumstances(in this case, to acquire the mutex lock). Therefore,with regard to the Driver caller routine shown below, it must incorrect runs in critical section, which possible call spin_lock() or other related functions which disable the preemption. Since it is not in the IRQ context, it is very likely spink lock is called in this failure case. Looking into the Driver code, should give the clue. [Fri May 05 05:26:09.992 2017] [40636.613352] [<7eea79ec>] (vibe_os_clk_set_parent+0x34/0xb0 [vibe_os]) from [<7eec3cd0>] (_ZN12CSTmClockLLA6EnableE29stm_clk_divider_output_name_t31stm_clk_divider_output_source_t31stm_clk_divider_output_divide_t+0xd4/0xf0 [stmcore_display_stiH407]) [Fri May 05 05:26:10.017 2017] [40636.635408] [<7eec3cd0>] (_ZN12CSTmClockLLA6EnableE29stm_clk_divider_output_name_t31stm_clk_divider_output_source_t31stm_clk_divider_output_divide_t+0xd4/0xf0 [stmcore_display_stiH407]) from [<7eec8c2c>] (_ZN16CSTmMainTVOutput15SetOutputFormatEj+0xc8/0x1b0 [stmcore_display_stiH407]) [Fri May 05 05:26:10.036 2017] [40636.660506] [<7eec8c2c>] (_ZN16CSTmMainTVOutput15SetOutputFormatEj+0xc8/0x1b0 [stmcore_display_stiH407]) from [<7eebbd40>] (_ZN16CSTmMasterOutput5StartEPK18stm_display_mode_s+0x1b8/0x1f8 [stmcore_display_stiH407]) [Fri May 05 05:26:10.069 2017] [40636.679522] [<7eebbd40>] (_ZN16CSTmMasterOutput5StartEPK18stm_display_mode_s+0x1b8/0x1f8 [stmcore_display_stiH407]) from [<7eeba0ac>] (stm_display_output_start+0x6c/0xb4 [stmcore_display_stiH407]) [Fri May 05 05:26:10.069 2017] [40636.697123] [<7eeba0ac>] (stm_display_output_start+0x6c/0xb4 [stmcore_display_stiH407]) from [<7f444650>] (dil_blender_output_start+0x8c/0x17c [stm_cdi_dvb]) [Fri May 05 05:26:10.079 2017] [40636.711321] [<7f444650>] (dil_blender_output_start+0x8c/0x17c [stm_cdi_dvb]) from [<7f45717c>] (cdi_hdmi_exit+0xb64/0xbc4 [stm_cdi_dvb]) [Fri May 05 05:26:10.092 2017] [40636.723660] [<7f45717c>] (cdi_hdmi_exit+0xb64/0xbc4 [stm_cdi_dvb]) from [<7f4578a4>] (dil_hdmi_set_video_code+0x4c/0x1d4 [stm_cdi_dvb]) [Fri May 05 05:26:10.104 2017] [40636.735912] [<7f4578a4>] (dil_hdmi_set_video_code+0x4c/0x1d4 [stm_cdi_dvb]) from [<7f44ed74>] (hdmi_release+0x316c/0x781c [stm_cdi_dvb]) [Fri May 05 05:26:10.151 2017] [40636.748251] [<7f44ed74>] (hdmi_release+0x316c/0x781c [stm_cdi_dvb]) from [<7f4539a0>] (hdmi_ioctl+0x57c/0x2d40 [stm_cdi_dvb]) [Fri May 05 05:26:10.152 2017] [40636.759631] [<7f4539a0>] (hdmi_ioctl+0x57c/0x2d40 [stm_cdi_dvb]) from [<800fd4dc>] (vfs_ioctl+0x28/0x3c) [Fri May 05 05:26:10.152 2017] [40636.769137] [<800fd4dc>] (vfs_ioctl+0x28/0x3c) from [<800fdf48>] (do_vfs_ioctl+0x4b0/0x560) [Fri May 05 05:26:10.152 2017] [40636.777484] [<800fdf48>] (do_vfs_ioctl+0x4b0/0x560) from [<800fe02c>] (SyS_ioctl+0x34/0x60) [Fri May 05 05:26:10.152 2017] [40636.785836] [<800fe02c>] (SyS_ioctl+0x34/0x60) from [<8000dbc0>] (ret_fast_syscall+0x0/0x30)
So briefly speaking, one following call must incorrect call spin_lock or other functions that disable the preemption in this failure case: For example: Failure case: stm_display_output_start() spin_lock() _ZN16CSTmMasterOutput5StartEPK18stm_display_mode_s -------> We can't sleep here since it is in the critical section !!! spin_unlock() Call Sequence: (1) vibe_os_clk_set_parent (2) _ZN12CSTmClockLLA6EnableE29stm_clk_divider_output_name_t31stm_clk_divider_output_source_t31stm_clk_divider_output_divide_t (3) _ZN16CSTmMainTVOutput15SetOutputFormatEj (4) _ZN16CSTmMasterOutput5StartEPK18stm_display_mode_s (5) stm_display_output_start() (6) dil_blender_output_start (7) cdi_hdmi_exit (8) dil_hdmi_set_video_code (9) hdmi_release (10) hdmi_ioctl()
This is the root cause, which is pretty straightforward: The spin lock is firstly acquired at the following function: OutputResults CSTmMasterOutput::Start(const stm_display_mode_t* pModeLine) { vibe_os_lock_resource(m_lock); if(!this->SetOutputFormat(m_ulOutputFormat)) { TRC; goto stop_and_exit; } vibe_os_unlock_resource(m_lock); } and this->SetOutputFormat will eventually call vibe_os_clk_set_parent() as below: bool CSTmClockLLA::Enable { vibe_os_clk_set_parent(output, source); } Based on the callstack, we know vibe_os_clk_set_parent will call clk_set_parent(). clk_set_parent() is a basic kernel API that would potentially go to sleep, based on the call stack in the log. Therefore, CSTmMasterOutput::Start would potentially go to sleeps while holding spin_Lock().
ST needs to review the code and decide which is the best place to place spin_lock or change to mutex.
Oh...Sorry, Comment post to wrong place, I will close this ticket and create a new one...