Mystery stack traces in /var/log/messages

Question

I am seeing the following messages in my server's /var/log/messages. They look like stack traces and are not preceded by any narrative (e.g. "such-and-such has gone wrong").

I am almost certain they are related to I/O problems I am experiencing, but it would be instructive to understand what exactly these messages are and what triggers them.

Jan 25 14:56:58 hostname kernel: [15321.586145] master        D 000000010016bfbb     0  2753      1 0x00000004
Jan 25 14:56:58 hostname kernel: [15321.586150]  ffff88030d053a78 0000000000000086 00000000ffffffff 0000000000015980
Jan 25 14:56:58 hostname kernel: [15321.586156]  ffff88030d053fd8 0000000000015980 ffff88030d053fd8 ffff88030dedc4a0
Jan 25 14:56:58 hostname kernel: [15321.586161]  0000000000015980 0000000000015980 ffff88030d053fd8 0000000000015980
Jan 25 14:56:58 hostname kernel: [15321.586166] Call Trace:
Jan 25 14:56:58 hostname kernel: [15321.586176]  [] do_get_write_access+0x2ed/0x5b0
Jan 25 14:56:58 hostname kernel: [15321.586182]  [] ? wake_bit_function+0x0/0x40
Jan 25 14:56:58 hostname kernel: [15321.586189]  [] jbd2_journal_get_write_access+0x31/0x50
Jan 25 14:56:58 hostname kernel: [15321.586192]  [] __ext4_journal_get_write_access+0x38/0x70
Jan 25 14:56:58 hostname kernel: [15321.586195]  [] ext4_reserve_inode_write+0x73/0xa0
Jan 25 14:56:58 hostname kernel: [15321.586197]  [] ? jbd2_journal_start+0xb5/0x100
Jan 25 14:56:58 hostname kernel: [15321.586199]  [] ext4_mark_inode_dirty+0x4c/0x1d0
Jan 25 14:56:58 hostname kernel: [15321.586200]  [] ? ext4_journal_start_sb+0xf8/0x130
Jan 25 14:56:58 hostname kernel: [15321.586202]  [] ext4_dirty_inode+0x40/0x60
Jan 25 14:56:58 hostname kernel: [15321.586205]  [] __mark_inode_dirty+0x42/0x1d0
Jan 25 14:56:58 hostname kernel: [15321.586207]  [] file_update_time+0xfb/0x180
Jan 25 14:56:58 hostname kernel: [15321.586210]  [] pipe_write+0x32b/0x670
Jan 25 14:56:58 hostname kernel: [15321.586212]  [] do_sync_write+0xda/0x120
Jan 25 14:56:58 hostname kernel: [15321.586215]  [] ? apparmor_file_permission+0x18/0x20
Jan 25 14:56:58 hostname kernel: [15321.586218]  [] ? security_file_permission+0x16/0x20
Jan 25 14:56:58 hostname kernel: [15321.586220]  [] vfs_write+0xb8/0x1a0
Jan 25 14:56:58 hostname kernel: [15321.586221]  [] sys_write+0x51/0x80
Jan 25 14:56:58 hostname kernel: [15321.586223]  [] ? sys_poll+0x7c/0x110
Jan 25 14:56:58 hostname kernel: [15321.586226]  [] system_call_fastpath+0x16/0x1b
Jan 25 14:56:58 hostname kernel: [15321.586237] qmgr          D 000000010016bfbb     0  2756   2753 0x00000004
Jan 25 14:56:58 hostname kernel: [15321.586239]  ffff8802f6cefa98 0000000000000082 ffff880200000000 0000000000015980
Jan 25 14:56:58 hostname kernel: [15321.586241]  ffff8802f6ceffd8 0000000000015980 ffff8802f6ceffd8 ffff88030d3c44a0
Jan 25 14:56:58 hostname kernel: [15321.586243]  0000000000015980 0000000000015980 ffff8802f6ceffd8 0000000000015980
Jan 25 14:56:58 hostname kernel: [15321.586245] Call Trace:
Jan 25 14:56:58 hostname kernel: [15321.586247]  [] do_get_write_access+0x2ed/0x5b0
Jan 25 14:56:58 hostname kernel: [15321.586249]  [] ? wake_bit_function+0x0/0x40
Jan 25 14:56:58 hostname kernel: [15321.586251]  [] jbd2_journal_get_write_access+0x31/0x50
Jan 25 14:56:58 hostname kernel: [15321.586253]  [] __ext4_journal_get_write_access+0x38/0x70
Jan 25 14:56:58 hostname kernel: [15321.586255]  [] ext4_reserve_inode_write+0x73/0xa0
Jan 25 14:56:58 hostname kernel: [15321.586257]  [] ? jbd2_journal_start+0xb5/0x100
Jan 25 14:56:58 hostname kernel: [15321.586258]  [] ext4_mark_inode_dirty+0x4c/0x1d0
Jan 25 14:56:58 hostname kernel: [15321.586260]  [] ? ext4_journal_start_sb+0xf8/0x130
Jan 25 14:56:58 hostname kernel: [15321.586263]  [] ? ep_poll_callback+0xbb/0xf0
Jan 25 14:56:58 hostname kernel: [15321.586265]  [] ext4_dirty_inode+0x40/0x60
Jan 25 14:56:58 hostname kernel: [15321.586266]  [] __mark_inode_dirty+0x42/0x1d0
Jan 25 14:56:58 hostname kernel: [15321.586268]  [] touch_atime+0x135/0x180
Jan 25 14:56:58 hostname kernel: [15321.586270]  [] pipe_read+0x2b4/0x4a0
Jan 25 14:56:58 hostname kernel: [15321.586272]  [] do_sync_read+0xda/0x120
Jan 25 14:56:58 hostname kernel: [15321.586275]  [] ? default_spin_lock_flags+0x9/0x10
Jan 25 14:56:58 hostname kernel: [15321.586276]  [] ? ep_poll+0xab/0x2a0
Jan 25 14:56:58 hostname kernel: [15321.586278]  [] ? apparmor_file_permission+0x18/0x20
Jan 25 14:56:58 hostname kernel: [15321.586280]  [] ? security_file_permission+0x16/0x20
Jan 25 14:56:58 hostname kernel: [15321.586282]  [] vfs_read+0xb5/0x1a0
Jan 25 14:56:58 hostname kernel: [15321.586283]  [] sys_read+0x51/0x80
Jan 25 14:56:58 hostname kernel: [15321.586285]  [] ? sys_epoll_wait+0x96/0xe0
Jan 25 14:56:58 hostname kernel: [15321.586287]  [] system_call_fastpath+0x16/0x1b

The kernel is Linux hostname 2.6.35-24-generic #42-Ubuntu SMP Thu Dec 2 02:41:37 UTC 2010 x86_64 GNU/Linux

Answer 1

It specifically looks as though ext4 is experiencing difficulty in writing data to the journal. My experience with ext3 was that the journal is used for writing the metadata you are about to commit to a safe place where it can at least be undone in the event of a system crash. Since writing to the journal is a non-critical, albeit important, function it probably just does an oops and rolls on. Since the system didn't crash at that moment, you only experience a delay during the time the ext4 kernel module was having issues with the journal.

So why is the filesystem having trouble with the journal? Look at the following questions to see if they spark any more ideas:

• Did you put the journal on a separate device that is either having problems or whose %busy is pretty high?
• If the disk is not local (iSCSI, ATAoE, or fiber channel), are you having communication problems, or can you prove that you aren't?
• When was the last time you ran fsck to check for integrity errors?
• If it a single, internal drive, have you tried to run the manufacturer's diagnostic tool to ensure that the disk is still performing to spec?
• For internal drives, is S.M.A.R.T. enabled and are you using tools to watch the device?