JBD2 error ,cause imx8 linux kernel hung up

mashaofeng · ‎11-14-2021

our product use imx8qxp chip and linux 5.4.24 system, the system may be hung up occasionally, in this time the console can not connected .

we open defconfig item DETECT_HUNG_TASK, it will show call dump like follow :

[ 1994.418834] INFO: task jbd2/mmcblk0p13:457 blocked for more than 30 seconds.

[ 1994.426504] Not tainted 5.4.24 #1

[ 1994.430843] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[ 1994.439208] jbd2/mmcblk0p13 D 0 457 2 0x00000228

[ 1994.445046] Call trace:

[ 1994.447832] __switch_to+0xf8/0x160

[ 1994.451683] __schedule+0x224/0x560

[ 1994.455440] schedule+0x40/0xe0

[ 1994.458847] io_schedule+0x18/0x98

[ 1994.462553] bit_wait_io+0x14/0x58

[ 1994.466807] __wait_on_bit+0x70/0xe0

[ 1994.471281] out_of_line_wait_on_bit+0x80/0xa0

[ 1994.479664] __wait_on_buffer+0x2c/0x38

[ 1994.485045] jbd2_journal_commit_transaction+0xd9c/0x1988

[ 1994.492272] kjournald2+0xb8/0x258

[ 1994.496101] kthread+0xf0/0x120

[ 1994.499559] ret_from_fork+0x10/0x18

[ 1994.503396] INFO: task jbd2/mmcblk0p12:512 blocked for more than 30 seconds.

[ 1994.511134] Not tainted 5.4.24 #1

[ 1994.515403] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

[ 1994.523932] jbd2/mmcblk0p12 D 0 512 2 0x00000228

[ 1994.529985] Call trace:

[ 1994.532541] __switch_to+0xf8/0x160

[ 1994.536176] __schedule+0x224/0x560

[ 1994.539900] schedule+0x40/0xe0

[ 1994.543141] io_schedule+0x18/0x98

[ 1994.546657] bit_wait_io+0x14/0x58

[ 1994.550271] __wait_on_bit+0x70/0xe0

[ 1994.553958] out_of_line_wait_on_bit+0x80/0xa0

[ 1994.558522] __wait_on_buffer+0x2c/0x38

[ 1994.562566] jbd2_journal_commit_transaction+0xd9c/0x1988

[ 1994.568078] kjournald2+0xb8/0x258

[ 1994.571634] kthread+0xf0/0x120

[ 1994.574900] ret_from_fork+0x10/0x18

we use a patch in linux community to fix it , it will show new error :

[ 1681.538807] fs/jbd2/transaction.c: (jbd2_journal_stop, 1829): transaction too old, requesting commit for handle 00000000a9f135b7

[ 1681.538820] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 502): JBD2: commit phase 1

[ 1681.538833] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 535): JBD2: commit phase 2a

[ 1681.538844] fs/jbd2/revoke.c: (jbd2_journal_write_revoke_records, 557): Wrote 0 revoke records

[ 1681.538849] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 548): JBD2: commit phase 2b

[ 1681.538854] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 605): JBD2: get descriptor

[ 1681.538883] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 615): JBD2: got buffer 68986 (000000004642fd24)

[ 1681.538890] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 00000000a9f135b7 going live.

[ 1681.538901] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 00000000a9f135b7 given 2 credits (total 2, free 3730)

[ 1681.538912] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 000000004bb18b3d, force_copy 0

[ 1681.538920] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 701): JBD2: Submit 4 IOs

[ 1681.539080] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 803): JBD2: commit phase 3

[ 1682.367551] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 0000000021996ddd going live.

[ 1682.367568] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 0000000021996ddd given 2 credits (total 4, free 3730)

[ 1682.367586] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 00000000fd7f7868, force_copy 0

[ 1682.988269] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 000000009e95567f going live.

[ 1682.988287] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 000000009e95567f given 2 credits (total 6, free 3730)

[ 1682.988306] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 00000000f48e0f75, force_copy 0

[ 1685.155985] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 00000000ff0e3c1a going live.

[ 1685.156011] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 00000000ff0e3c1a given 3 credits (total 3, free 7834)

[ 1685.156026] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 00000000bb74af7b, force_copy 0

[ 1685.156040] fs/jbd2/revoke.c: (jbd2_journal_cancel_revoke, 425): journal_head 00000000bb74af7b, cancelling revoke

[ 1685.156062] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 00000000c5da4b6c, force_copy 0

[ 1685.156070] fs/jbd2/revoke.c: (jbd2_journal_cancel_revoke, 425): journal_head 00000000c5da4b6c, cancelling revoke

[ 1685.156081] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000bb74af7b

[ 1685.156098] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156108] fs/ext4/namei.c: (ext4_orphan_add, 2974): superblock will point to 23

[ 1685.156117] fs/ext4/namei.c: (ext4_orphan_add, 2975): orphan inode 23 will point to 0

[ 1685.156129] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156138] fs/jbd2/transaction.c: (jbd2_journal_stop, 1744): Handle 00000000ff0e3c1a going down

[ 1685.156213] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 00000000ff0e3c1a going live.

[ 1685.156225] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 00000000ff0e3c1a given 8 credits (total 10, free 7834)

[ 1685.156240] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156277] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 00000000fb079739, force_copy 0

[ 1685.156286] fs/jbd2/revoke.c: (jbd2_journal_cancel_revoke, 425): journal_head 00000000fb079739, cancelling revoke

[ 1685.156297] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 000000004fa7d23d, force_copy 0

[ 1685.156306] fs/jbd2/revoke.c: (jbd2_journal_cancel_revoke, 425): journal_head 000000004fa7d23d, cancelling revoke

[ 1685.156338] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156346] fs/jbd2/transaction.c: (jbd2_journal_stop, 1739): h_ref 3 -> 2

[ 1685.156360] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000fb079739

[ 1685.156370] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 000000004fa7d23d

[ 1685.156382] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156397] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156405] fs/jbd2/transaction.c: (jbd2_journal_stop, 1739): h_ref 2 -> 1

[ 1685.156415] fs/ext4/namei.c: (ext4_orphan_del, 3010): remove inode 23 from orphan list

[ 1685.156421] fs/ext4/namei.c: (ext4_orphan_del, 3026): superblock will point to 0

[ 1685.156429] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000bb74af7b

[ 1685.156440] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156449] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156457] fs/jbd2/transaction.c: (jbd2_journal_stop, 1744): Handle 00000000ff0e3c1a going down

[ 1685.156470] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 00000000ff0e3c1a going live.

[ 1685.156480] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 00000000ff0e3c1a given 2 credits (total 6, free 7834)

[ 1685.156491] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156500] fs/jbd2/transaction.c: (jbd2_journal_stop, 1744): Handle 00000000ff0e3c1a going down

[ 1685.156577] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 00000000ff0e3c1a going live.

[ 1685.156589] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 00000000ff0e3c1a given 1 credits (total 5, free 7834)

[ 1685.156653] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.156662] fs/jbd2/transaction.c: (jbd2_journal_stop, 1739): h_ref 2 -> 1

[ 1685.156671] fs/jbd2/transaction.c: (jbd2_journal_stop, 1744): Handle 00000000ff0e3c1a going down

[ 1685.160206] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 0000000090cdb8f8 going live.

[ 1685.160222] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 0000000090cdb8f8 given 8 credits (total 12, free 7834)

[ 1685.160265] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 00000000f22d44e7, force_copy 0

[ 1685.160278] fs/jbd2/revoke.c: (jbd2_journal_cancel_revoke, 425): journal_head 00000000f22d44e7, cancelling revoke

[ 1685.160298] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000f22d44e7

[ 1685.160307] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 000000004fa7d23d

[ 1685.160330] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.160343] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.160350] fs/jbd2/transaction.c: (jbd2_journal_stop, 1739): h_ref 2 -> 1

[ 1685.160368] fs/jbd2/transaction.c: (jbd2_journal_file_inode, 2586): Adding inode 23, tid:3822

[ 1685.160408] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000c5da4b6c

[ 1685.160415] fs/jbd2/transaction.c: (jbd2_journal_stop, 1744): Handle 0000000090cdb8f8 going down

[ 1685.160457] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 0000000090cdb8f8 going live.

[ 1685.160465] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 0000000090cdb8f8 given 8 credits (total 13, free 7834)

[ 1685.160471] fs/jbd2/transaction.c: (jbd2_journal_stop, 1744): Handle 0000000090cdb8f8 going down

[ 1685.160743] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 00000000ff0e3c1a going live.

[ 1685.160765] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 00000000ff0e3c1a given 17 credits (total 18, free 3982)

[ 1685.160829] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 00000000d4729d88, force_copy 0

[ 1685.160842] fs/jbd2/revoke.c: (jbd2_journal_cancel_revoke, 425): journal_head 00000000d4729d88, cancelling revoke

[ 1685.160852] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 000000004d89059a, force_copy 0

[ 1685.160859] fs/jbd2/revoke.c: (jbd2_journal_cancel_revoke, 425): journal_head 000000004d89059a, cancelling revoke

[ 1685.160875] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 00000000d4729d88

[ 1685.160883] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 000000004d89059a

[ 1685.160894] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 000000005be8a815, force_copy 0

[ 1685.160901] fs/jbd2/revoke.c: (jbd2_journal_cancel_revoke, 425): journal_head 000000005be8a815, cancelling revoke

[ 1685.160910] fs/jbd2/transaction.c: (jbd2_journal_dirty_metadata, 1386): journal_head 000000005be8a815

[ 1685.160926] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 0000000013316585, force_copy 0

[ 1689.538324] fs/jbd2/transaction.c: (start_this_handle, 338): New handle 00000000818be1cc going live.

[ 1689.538345] fs/jbd2/transaction.c: (start_this_handle, 411): Handle 00000000818be1cc given 2 credits (total 8, free 3730)

[ 1689.538368] fs/jbd2/transaction.c: (do_get_write_access, 870): journal_head 000000004bb18b3d, force_copy 0

[ 1691.313797] fs/jbd2/journal.c: (kjournald2, 252): kjournald2 wakes

[ 1691.313809] fs/jbd2/journal.c: (kjournald2, 260): woke because of timeout

[ 1691.313815] fs/jbd2/journal.c: (kjournald2, 203): commit_sequence=3821, commit_request=3822

[ 1691.313820] fs/jbd2/journal.c: (kjournald2, 207): OK, requests differ

[ 1691.313827] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 410): superblock not updated

[ 1691.313832] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 419): JBD2: starting commit of transaction 3822

[ 1691.313840] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 502): JBD2: commit phase 1

[ 1691.313853] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 535): JBD2: commit phase 2a

[ 1691.313865] fs/jbd2/revoke.c: (jbd2_journal_write_revoke_records, 557): Wrote 0 revoke records

[ 1691.313869] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 548): JBD2: commit phase 2b

[ 1691.313876] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 605): JBD2: get descriptor

[ 1691.313932] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 615): JBD2: got buffer 203085 (00000000ba018fc8)

[ 1691.313963] fs/jbd2/commit.c: (jbd2_journal_commit_transaction, 701): JBD2: Submit 6 IOs

how to fix the issue ?

thanks

igorpadykov · ‎11-14-2021

Hi Ma

may be recommended to move to more new kernels L5.10.x described on

https://www.nxp.com/design/software/embedded-software/i-mx-software/embedded-linux-for-i-mx-applicat...

As for linux 5.4.24, one can try to rerun ddr test, try overnight and at different temperatures,

use latest rpa tool from

https://community.nxp.com/t5/i-MX-Processors-Knowledge-Base/i-MX8QXP-DXP-DX-DDR-Register-Programming...

Then rebuild all image from scratch, pay attention to revisions of various software components

(atf, scfw, seco, e.t.c.), they are described in Release Notes for each bsp included in documentation package

https://www.nxp.com/design/software/embedded-software/i-mx-software/embedded-linux-for-i-mx-applicat...

Also may be recommended to try with different emmc parts.

Best regards
igor