| View previous topic :: View next topic |
| Author |
Message |
NathanZachary
Moderator
Joined: 30 Jan 2007
Posts: 2609
|
 Posted: Mon Jul 16, 2012 11:37 am Post subject: Secondary drive causes I/O ~ every 3-4 seconds |
 |
|
Hello all,
Last night, I made a mistake that cost me some data on my secondary internal disk. However, I'm over that problem, and I simply made a new partition on the drive and mounted it in the same location in order to rebuild what I lost. Now, though, when the drive is mounted, there is a mention of it at the top of iotop about once every 3-4 seconds, and I can't figure out why. I increased the verbosity of JBD2 (echo 2 > /sys/kernel/debug/jbd2/jbd2-debug) in order to see if there was something out of the ordinary, and this is the information in /var/log/messages:
| Code: |
Jul 16 07:30:04 kratos kernel: [37000.713021] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit: JBD2: requesting commit 1176183/1176182
Jul 16 07:30:04 kratos kernel: [37000.713026] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:04 kratos kernel: [37000.713027] (fs/jbd2/journal.c, 211): kjournald2:
Jul 16 07:30:04 kratos kernel: [37000.713029] (fs/jbd2/transaction.c, 1464): jbd2_journal_stop: transaction too old, requesting commit for handle ffff880611a37038
Jul 16 07:30:04 kratos kernel: [37000.713033] woke because of timeout
Jul 16 07:30:04 kratos kernel: [37000.713034] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176182, commit_request=1176183
Jul 16 07:30:04 kratos kernel: [37000.713036] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:04 kratos kernel: [37000.713037] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit:
Jul 16 07:30:04 kratos kernel: [37000.713039] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176183
Jul 16 07:30:04 kratos kernel: [37000.713043] JBD2: requesting commit 1176183/1176182
Jul 16 07:30:04 kratos kernel: [37000.713061] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:04 kratos kernel: [37000.724844] (fs/jbd2/recovery.c, 244): jbd2_journal_recover: No recovery required, last transaction 746
Jul 16 07:30:04 kratos kernel: [37000.724847] (fs/jbd2/journal.c, 1216): journal_reset: JBD2: Skipping superblock update on recovered sb (start 1, seq 747, errno 0)
Jul 16 07:30:04 kratos kernel: [37000.724953] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=746, commit_request=746
Jul 16 07:30:04 kratos kernel: [37000.724956] (fs/jbd2/journal.c, 1693): jbd2_journal_clear_features: Clear features 0x1/0x0/0x4
Jul 16 07:30:04 kratos kernel: [37000.751371] EXT4-fs (sdb1): mounted filesystem with ordered data mode. Opts: (null)
Jul 16 07:30:04 kratos kernel: [37000.786123] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176182, all done
Jul 16 07:30:04 kratos kernel: [37000.786126] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176183 complete, head 1175814
Jul 16 07:30:04 kratos kernel: [37000.786129] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176183, commit_request=1176183
Jul 16 07:30:10 kratos kernel: [37006.647400] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:10 kratos kernel: [37006.647404] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:10 kratos kernel: [37006.647408] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176183, commit_request=1176184
Jul 16 07:30:10 kratos kernel: [37006.647411] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:10 kratos kernel: [37006.647415] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176184
Jul 16 07:30:10 kratos kernel: [37006.647451] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:10 kratos kernel: [37006.709653] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176184 complete, head 1175814
Jul 16 07:30:10 kratos kernel: [37006.709659] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176184, commit_request=1176184
Jul 16 07:30:14 kratos kernel: [37010.650996] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:14 kratos kernel: [37010.651000] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:14 kratos kernel: [37010.651003] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=746, commit_request=747
Jul 16 07:30:14 kratos kernel: [37010.651006] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:14 kratos kernel: [37010.651010] (fs/jbd2/journal.c, 1293): jbd2_journal_update_sb_log_tail: JBD2: updating superblock (start 1, seq 747)
Jul 16 07:30:14 kratos kernel: [37010.651259] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 747
Jul 16 07:30:14 kratos kernel: [37010.651268] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:14 kratos kernel: [37010.677247] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 747 complete, head 747
Jul 16 07:30:14 kratos kernel: [37010.677253] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=747, commit_request=747
Jul 16 07:30:16 kratos kernel: [37012.644881] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:16 kratos kernel: [37012.644885] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:16 kratos kernel: [37012.644888] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176184, commit_request=1176185
Jul 16 07:30:16 kratos kernel: [37012.644892] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:16 kratos kernel: [37012.644895] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176185
Jul 16 07:30:16 kratos kernel: [37012.644920] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:16 kratos kernel: [37012.699317] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176185 complete, head 1175814
Jul 16 07:30:16 kratos kernel: [37012.699322] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176185, commit_request=1176185
Jul 16 07:30:20 kratos kernel: [37016.632385] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:20 kratos kernel: [37016.632389] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:20 kratos kernel: [37016.632392] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=747, commit_request=748
Jul 16 07:30:20 kratos kernel: [37016.632396] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:20 kratos kernel: [37016.632399] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 748
Jul 16 07:30:20 kratos kernel: [37016.632407] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:20 kratos kernel: [37016.658610] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 747, all done
Jul 16 07:30:20 kratos kernel: [37016.658617] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 748 complete, head 747
Jul 16 07:30:20 kratos kernel: [37016.658621] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=748, commit_request=748
Jul 16 07:30:22 kratos kernel: [37018.610301] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:22 kratos kernel: [37018.610305] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:22 kratos kernel: [37018.610308] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176185, commit_request=1176186
Jul 16 07:30:22 kratos kernel: [37018.610312] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:22 kratos kernel: [37018.610315] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176186
Jul 16 07:30:22 kratos kernel: [37018.610341] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:22 kratos kernel: [37018.664157] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176185, all done
Jul 16 07:30:22 kratos kernel: [37018.664163] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176186 complete, head 1175814
Jul 16 07:30:22 kratos kernel: [37018.664168] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176186, commit_request=1176186
Jul 16 07:30:26 kratos kernel: [37022.613747] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:26 kratos kernel: [37022.613751] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:26 kratos kernel: [37022.613754] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=748, commit_request=749
Jul 16 07:30:26 kratos kernel: [37022.613757] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:26 kratos kernel: [37022.613760] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 749
Jul 16 07:30:26 kratos kernel: [37022.613768] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:26 kratos kernel: [37022.639912] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 749 complete, head 747
Jul 16 07:30:26 kratos kernel: [37022.639917] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=749, commit_request=749
Jul 16 07:30:28 kratos kernel: [37024.607654] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:28 kratos kernel: [37024.607658] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:28 kratos kernel: [37024.607662] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176186, commit_request=1176187
Jul 16 07:30:28 kratos kernel: [37024.607665] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:28 kratos kernel: [37024.607669] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176187
Jul 16 07:30:28 kratos kernel: [37024.607694] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:28 kratos kernel: [37024.678898] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176187 complete, head 1175814
Jul 16 07:30:28 kratos kernel: [37024.678904] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176187, commit_request=1176187
Jul 16 07:30:32 kratos kernel: [37028.595182] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:32 kratos kernel: [37028.595186] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:32 kratos kernel: [37028.595189] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=749, commit_request=750
Jul 16 07:30:32 kratos kernel: [37028.595193] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:32 kratos kernel: [37028.595196] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 750
Jul 16 07:30:32 kratos kernel: [37028.595204] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:32 kratos kernel: [37028.621293] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 749, all done
Jul 16 07:30:32 kratos kernel: [37028.621299] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 750 complete, head 747
Jul 16 07:30:32 kratos kernel: [37028.621303] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=750, commit_request=750
Jul 16 07:30:34 kratos kernel: [37030.573020] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:34 kratos kernel: [37030.573026] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:34 kratos kernel: [37030.573030] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176187, commit_request=1176188
Jul 16 07:30:34 kratos kernel: [37030.573035] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:34 kratos kernel: [37030.573039] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176188
Jul 16 07:30:34 kratos kernel: [37030.573073] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:34 kratos kernel: [37030.660329] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176188 complete, head 1175814
Jul 16 07:30:34 kratos kernel: [37030.660335] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176188, commit_request=1176188
Jul 16 07:30:38 kratos kernel: [37034.576553] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:38 kratos kernel: [37034.576557] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:38 kratos kernel: [37034.576561] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=750, commit_request=751
Jul 16 07:30:38 kratos kernel: [37034.576564] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:38 kratos kernel: [37034.576567] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 751
Jul 16 07:30:38 kratos kernel: [37034.576572] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 748, all done
Jul 16 07:30:38 kratos kernel: [37034.576580] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:38 kratos kernel: [37034.602578] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 750, all done
Jul 16 07:30:38 kratos kernel: [37034.602585] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 751 complete, head 747
Jul 16 07:30:38 kratos kernel: [37034.602590] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=751, commit_request=751
Jul 16 07:30:40 kratos kernel: [37036.570439] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:40 kratos kernel: [37036.570443] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:40 kratos kernel: [37036.570446] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176188, commit_request=1176189
Jul 16 07:30:40 kratos kernel: [37036.570450] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:40 kratos kernel: [37036.570453] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176189
Jul 16 07:30:40 kratos kernel: [37036.570461] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176184, all done
Jul 16 07:30:40 kratos kernel: [37036.570466] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176186, all done
Jul 16 07:30:40 kratos kernel: [37036.570470] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176187, all done
Jul 16 07:30:40 kratos kernel: [37036.570511] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:40 kratos kernel: [37036.641822] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176183, all done
Jul 16 07:30:40 kratos kernel: [37036.641828] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176188, all done
Jul 16 07:30:40 kratos kernel: [37036.641833] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176189 complete, head 1175814
Jul 16 07:30:40 kratos kernel: [37036.641838] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176189, commit_request=1176189
Jul 16 07:30:44 kratos kernel: [37040.557940] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:44 kratos kernel: [37040.557944] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:44 kratos kernel: [37040.557947] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=751, commit_request=752
Jul 16 07:30:44 kratos kernel: [37040.557951] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:44 kratos kernel: [37040.557954] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 752
Jul 16 07:30:44 kratos kernel: [37040.557962] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:44 kratos kernel: [37040.728754] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 751, all done
Jul 16 07:30:44 kratos kernel: [37040.728757] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 752 complete, head 747
Jul 16 07:30:44 kratos kernel: [37040.728759] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=752, commit_request=752
Jul 16 07:30:46 kratos kernel: [37042.535847] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:46 kratos kernel: [37042.535851] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:46 kratos kernel: [37042.535854] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176189, commit_request=1176190
Jul 16 07:30:46 kratos kernel: [37042.535858] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:46 kratos kernel: [37042.535861] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176190
Jul 16 07:30:46 kratos kernel: [37042.535896] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:46 kratos kernel: [37042.606554] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176190 complete, head 1175814
Jul 16 07:30:46 kratos kernel: [37042.606560] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176190, commit_request=1176190
Jul 16 07:30:49 kratos kernel: [37045.785980] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit: JBD2: requesting commit 1176191/1176190
Jul 16 07:30:49 kratos kernel: [37045.785988] (fs/jbd2/journal.c, 648): jbd2_log_wait_commit: JBD2: want 1176191, j_commit_sequence=1176190
Jul 16 07:30:49 kratos kernel: [37045.786050] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:49 kratos kernel: [37045.786054] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176190, commit_request=1176191
Jul 16 07:30:49 kratos kernel: [37045.786058] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:49 kratos kernel: [37045.786062] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176191
Jul 16 07:30:49 kratos kernel: [37045.786112] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:49 kratos kernel: [37045.846749] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176190, all done
Jul 16 07:30:49 kratos kernel: [37045.846755] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176191 complete, head 1175814
Jul 16 07:30:49 kratos kernel: [37045.846762] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176191, commit_request=1176191
Jul 16 07:30:50 kratos kernel: [37046.216091] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit: JBD2: requesting commit 1176192/1176191
Jul 16 07:30:50 kratos kernel: [37046.216099] (fs/jbd2/journal.c, 648): jbd2_log_wait_commit: JBD2: want 1176192, j_commit_sequence=1176191
Jul 16 07:30:50 kratos kernel: [37046.216140] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:50 kratos kernel: [37046.216145] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176191, commit_request=1176192
Jul 16 07:30:50 kratos kernel: [37046.216149] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:50 kratos kernel: [37046.216152] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176192
Jul 16 07:30:50 kratos kernel: [37046.216178] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:50 kratos kernel: [37046.279129] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176191, all done
Jul 16 07:30:50 kratos kernel: [37046.279139] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176192 complete, head 1175814
Jul 16 07:30:50 kratos kernel: [37046.279146] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176192, commit_request=1176192
Jul 16 07:30:50 kratos kernel: [37046.443242] (fs/jbd2/transaction.c, 1464): jbd2_journal_stop: transaction too old, requesting commit for handle ffff880611a971c0
Jul 16 07:30:50 kratos kernel: [37046.443248] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit: JBD2: requesting commit 753/752
Jul 16 07:30:50 kratos kernel: [37046.443316] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:50 kratos kernel: [37046.443320] (fs/jbd2/journal.c, 211): kjournald2: woke because of timeout
Jul 16 07:30:50 kratos kernel: [37046.443323] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=752, commit_request=753
Jul 16 07:30:50 kratos kernel: [37046.443327] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:50 kratos kernel: [37046.443330] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 753
Jul 16 07:30:50 kratos kernel: [37046.443338] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:50 kratos kernel: [37046.498826] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 752, all done
Jul 16 07:30:50 kratos kernel: [37046.498832] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 753 complete, head 747
Jul 16 07:30:50 kratos kernel: [37046.498837] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=753, commit_request=753
Jul 16 07:30:50 kratos kernel: [37046.554604] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit: JBD2: requesting commit 1176193/1176192
Jul 16 07:30:50 kratos kernel: [37046.554611] (fs/jbd2/journal.c, 648): jbd2_log_wait_commit: JBD2: want 1176193, j_commit_sequence=1176192
Jul 16 07:30:50 kratos kernel: [37046.554670] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:50 kratos kernel: [37046.554674] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176192, commit_request=1176193
Jul 16 07:30:50 kratos kernel: [37046.554678] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:50 kratos kernel: [37046.554681] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176193
Jul 16 07:30:50 kratos kernel: [37046.554708] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:50 kratos kernel: [37046.595368] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176192, all done
Jul 16 07:30:50 kratos kernel: [37046.595373] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176193 complete, head 1175814
Jul 16 07:30:50 kratos kernel: [37046.595376] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176193, commit_request=1176193
Jul 16 07:30:50 kratos kernel: [37046.797956] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit: JBD2: requesting commit 1176194/1176193
Jul 16 07:30:50 kratos kernel: [37046.797963] (fs/jbd2/journal.c, 648): jbd2_log_wait_commit: JBD2: want 1176194, j_commit_sequence=1176193
Jul 16 07:30:50 kratos kernel: [37046.798026] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:50 kratos kernel: [37046.798030] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176193, commit_request=1176194
Jul 16 07:30:50 kratos kernel: [37046.798034] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:50 kratos kernel: [37046.798037] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176194
Jul 16 07:30:50 kratos kernel: [37046.798063] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:50 kratos kernel: [37046.845047] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176194 complete, head 1175814
Jul 16 07:30:50 kratos kernel: [37046.845051] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176194, commit_request=1176194
Jul 16 07:30:51 kratos kernel: [37047.053287] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit: JBD2: requesting commit 1176195/1176194
Jul 16 07:30:51 kratos kernel: [37047.053294] (fs/jbd2/journal.c, 648): jbd2_log_wait_commit: JBD2: want 1176195, j_commit_sequence=1176194
Jul 16 07:30:51 kratos kernel: [37047.053356] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:51 kratos kernel: [37047.053360] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176194, commit_request=1176195
Jul 16 07:30:51 kratos kernel: [37047.053364] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:51 kratos kernel: [37047.053368] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176195
Jul 16 07:30:51 kratos kernel: [37047.053394] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:51 kratos kernel: [37047.103117] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176194, all done
Jul 16 07:30:51 kratos kernel: [37047.103126] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176195 complete, head 1175814
Jul 16 07:30:51 kratos kernel: [37047.103132] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176195, commit_request=1176195
Jul 16 07:30:52 kratos kernel: [37048.501598] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit: JBD2: requesting commit 1176196/1176195
Jul 16 07:30:52 kratos kernel: [37048.501606] (fs/jbd2/journal.c, 648): jbd2_log_wait_commit: JBD2: want 1176196, j_commit_sequence=1176195
Jul 16 07:30:52 kratos kernel: [37048.501637] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:52 kratos kernel: [37048.501641] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176195, commit_request=1176196
Jul 16 07:30:52 kratos kernel: [37048.501645] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:52 kratos kernel: [37048.501649] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 1176196
Jul 16 07:30:52 kratos kernel: [37048.501678] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:52 kratos kernel: [37048.557426] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 1176195, all done
Jul 16 07:30:52 kratos kernel: [37048.557438] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 1176196 complete, head 1175814
Jul 16 07:30:52 kratos kernel: [37048.557442] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=1176196, commit_request=1176196
Jul 16 07:30:52 kratos kernel: [37048.558040] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit: JBD2: requesting commit 754/753
Jul 16 07:30:52 kratos kernel: [37048.558046] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:52 kratos kernel: [37048.558049] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=753, commit_request=754
Jul 16 07:30:52 kratos kernel: [37048.558051] (fs/jbd2/journal.c, 158): kjournald2: OK, requests differ
Jul 16 07:30:52 kratos kernel: [37048.558053] (fs/jbd2/journal.c, 495): __jbd2_log_start_commit:
Jul 16 07:30:52 kratos kernel: [37048.558055] (fs/jbd2/commit.c, 370): jbd2_journal_commit_transaction: JBD2: starting commit of transaction 754
Jul 16 07:30:52 kratos kernel: [37048.558057] JBD2: requesting commit 754/753
Jul 16 07:30:52 kratos kernel: [37048.558061] (fs/jbd2/journal.c, 648): jbd2_log_wait_commit:
Jul 16 07:30:52 kratos kernel: [37048.558062] (fs/jbd2/revoke.c, 566): jbd2_journal_write_revoke_records: Wrote 0 revoke records
Jul 16 07:30:52 kratos kernel: [37048.558064] JBD2: want 754, j_commit_sequence=753
Jul 16 07:30:52 kratos kernel: [37048.584043] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 753, all done
Jul 16 07:30:52 kratos kernel: [37048.584046] (fs/jbd2/commit.c, 1091): jbd2_journal_commit_transaction: JBD2: commit 754 complete, head 747
Jul 16 07:30:52 kratos kernel: [37048.584049] (fs/jbd2/journal.c, 155): kjournald2: commit_sequence=754, commit_request=754
Jul 16 07:30:52 kratos kernel: [37048.584340] (fs/jbd2/journal.c, 203): kjournald2: kjournald2 wakes
Jul 16 07:30:52 kratos kernel: [37048.584343] (fs/jbd2/journal.c, 220): kjournald2: Journal thread exiting.
Jul 16 07:30:52 kratos kernel: [37048.584346] (fs/jbd2/checkpoint.c, 338): jbd2_log_do_checkpoint: Start checkpoint
Jul 16 07:30:52 kratos kernel: [37048.606497] (fs/jbd2/journal.c, 1293): jbd2_journal_update_sb_log_tail: JBD2: updating superblock (start 23, seq 754)
Jul 16 07:30:52 kratos kernel: [37048.624820] (fs/jbd2/journal.c, 817): __jbd2_update_log_tail: Cleaning journal tail from 747 to 754 (offset 23), freeing 22
Jul 16 07:30:52 kratos kernel: [37048.624823] (fs/jbd2/checkpoint.c, 347): jbd2_log_do_checkpoint: cleanup_journal_tail returned 0
Jul 16 07:30:52 kratos kernel: [37048.624825] (fs/jbd2/checkpoint.c, 338): jbd2_log_do_checkpoint: Start checkpoint
Jul 16 07:30:52 kratos kernel: [37048.624827] (fs/jbd2/checkpoint.c, 347): jbd2_log_do_checkpoint: cleanup_journal_tail returned 1
Jul 16 07:30:52 kratos kernel: [37048.624829] (fs/jbd2/checkpoint.c, 704): __jbd2_journal_drop_transaction: Dropping transaction 754, all done
Jul 16 07:30:52 kratos kernel: [37048.624973] (fs/jbd2/journal.c, 1293): jbd2_journal_update_sb_log_tail: JBD2: updating superblock (start 26, seq 755)
Jul 16 07:30:52 kratos kernel: [37048.633105] (fs/jbd2/journal.c, 817): __jbd2_update_log_tail: Cleaning journal tail from 754 to 755 (offset 26), freeing 3
Jul 16 07:30:52 kratos kernel: [37048.633108] (fs/jbd2/journal.c, 1321): jbd2_mark_journal_empty: JBD2: Marking journal as empty (seq 755)
|
The drive didn't do that before. Interestingly, I have an external drive that I just bought, formatted, and set up ext4 on as well, and it does the same thing. Any suggestions on where to look next?
Cheers,
Nathan Zachary
_________________
“Truth, like infinity, is to be forever approached but never reached.” --Jean Ayres (1972)
---avatar cropped from =AimanStudio--- |
|
| Back to top |
|
 |
alex.blackbit
Advocate
Joined: 26 Jul 2005
Posts: 2397
|
| Posted: Mon Jul 16, 2012 9:32 pm Post subject: |
|
|
NathanZachary,
well, you already tried fuser/lsof, right?
I guess you assume the problem to be on a lower level. |
|
| Back to top |
|
|
NathanZachary
Moderator
Joined: 30 Jan 2007
Posts: 2609
|
| Posted: Mon Jul 16, 2012 11:00 pm Post subject: |
|
|
@alex.blackbit,
Thanks for your response. I'm not ruling out anything at this point, but am, instead, looking for pointers to help me further troubleshoot. The rationale for thinking that it is something to do with ext4 is two-fold:
1) I found this forum post over in the Arch community:
https://bbs.archlinux.org/viewtopic.php?pid=801017
The resolution there seems to be related to HAL, which I don't think is the problem here, but it did lead me in the direction of looking into JBD2.
2) When running iotop -a (for the accumulative total) after mounting the drive, I see the following output after 120 seconds:
| Code: |
Total DISK READ: 0.00 B/s | Total DISK WRITE: 0.00 B/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO COMMAND
7874 be/3 root 0.00 B 16.00 K 0.00 % 0.58 % [jbd2/sdb1-8]
1201 be/3 root 0.00 B 68.00 K 0.00 % 0.10 % [jbd2/sda3-8]
|
and when the drive is not mounted, I see the following output after 120 seconds:
| Code: |
Total DISK READ: 0.00 B/s | Total DISK WRITE: 0.00 B/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
1201 be/3 root 0.00 B 132.00 K 0.00 % 0.08 % [jbd2/sda3-8]
|
It's interesting that the actual writes are higher for sda (my system drive) than for the secondary drive, yet the IO% is higher for sdb. Also, I don't hear sda being accessed whilst it is idle. When sdb is mounted, though, I hear it being accessed every couple seconds.
All that I see with fuser is:
| Code: |
fuser -v -m /secondary
USER PID ACCESS COMMAND
/secondary: root kernel mount /secondary
|
I appreciate the suggestions thus far, and can provide any other output that may help.
Thanks again.
Cheers,
Nathan Zachary
_________________
“Truth, like infinity, is to be forever approached but never reached.” --Jean Ayres (1972)
---avatar cropped from =AimanStudio--- |
|
| Back to top |
|
|
PaulBredbury
Watchman
Joined: 14 Jul 2005
Posts: 7310
|
| Posted: Tue Jul 17, 2012 8:13 am Post subject: |
|
|
Maybe it's udev polling. Check:
| Code: | $ cat /sys/class/block/sdb/events_poll_msecs
-1 |
If it returns 2000, then it's polling every 2 seconds. |
|
| Back to top |
|
|
NathanZachary
Moderator
Joined: 30 Jan 2007
Posts: 2609
|
| Posted: Tue Jul 17, 2012 8:19 pm Post subject: |
|
|
@PaulBredbury,
Thanks for the recommendation, but the drive does show -1. I also checked it for my eSATA drive which is doing the same thing.
Cheers,
Zach
_________________
“Truth, like infinity, is to be forever approached but never reached.” --Jean Ayres (1972)
---avatar cropped from =AimanStudio--- |
|
| Back to top |
|
|
|
|
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum
|
|
Kernel & Hardware
