Bug 76821 - jbd2 write on disk each 2/3 seconds
Summary: jbd2 write on disk each 2/3 seconds
Status: RESOLVED INVALID
Alias: None
Product: File System
Classification: Unclassified
Component: ext4 (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: fs_ext4@kernel-bugs.osdl.org
URL: https://bbs.archlinux.org/viewtopic.p...
Keywords:
Depends on:
Blocks:
 
Reported: 2014-05-24 12:14 UTC by Abdelhak Bougouffa
Modified: 2014-05-25 12:15 UTC (History)
1 user (show)

See Also:
Kernel Version: 3.14.4-1-ARCH, 3.10.40-1-lts
Subsystem:
Regression: No
Bisected commit-id:


Attachments

Description Abdelhak Bougouffa 2014-05-24 12:14:10 UTC
➜  ~  sudo iotop -obtqqq | grep jbd2             
[sudo] password for hacko: 
13:12:05   390 be/3 root        0.00 B/s    0.00 B/s  0.00 %  0.87 % [jbd2/sda6-8]
13:12:06   390 be/3 root        0.00 B/s   31.45 K/s  0.00 %  2.48 % [jbd2/sda6-8]
13:12:12   111 be/3 root        0.00 B/s   11.53 K/s  0.00 %  4.99 % [jbd2/sda3-8]
13:12:19   390 be/3 root        0.00 B/s    3.84 K/s  0.00 %  2.98 % [jbd2/sda6-8]
13:12:25   390 be/3 root        0.00 B/s    3.84 K/s  0.00 %  5.91 % [jbd2/sda6-8]
13:12:25   111 be/3 root        0.00 B/s   23.03 K/s  0.00 %  5.71 % [jbd2/sda3-8]
13:12:31   390 be/3 root        0.00 B/s    3.84 K/s  0.00 %  4.42 % [jbd2/sda6-8]
13:12:32   390 be/3 root        0.00 B/s    0.00 B/s  0.00 %  0.03 % [jbd2/sda6-8]
13:12:34   390 be/3 root        0.00 B/s   23.05 K/s  0.00 %  7.62 % [jbd2/sda6-8]
13:12:39   390 be/3 root        0.00 B/s   26.86 K/s  0.00 %  4.40 % [jbd2/sda6-8]
13:12:46   390 be/3 root        0.00 B/s    3.83 K/s  0.00 %  4.42 % [jbd2/sda6-8]
13:12:53   390 be/3 root        0.00 B/s   11.49 K/s  0.00 %  4.31 % [jbd2/sda6-8]
13:13:01   390 be/3 root        0.00 B/s   11.53 K/s  0.00 %  4.46 % [jbd2/sda6-8]
13:13:07   390 be/3 root        0.00 B/s    7.69 K/s  0.00 %  4.55 % [jbd2/sda6-8]
13:13:12   390 be/3 root        0.00 B/s   11.56 K/s  0.00 %  4.85 % [jbd2/sda6-8]
13:13:19   390 be/3 root        0.00 B/s   11.56 K/s  0.00 %  4.27 % [jbd2/sda6-8]
13:13:23   390 be/3 root        0.00 B/s   46.13 K/s  0.00 %  9.26 % [jbd2/sda6-8]
13:13:26   390 be/3 root        0.00 B/s    7.54 K/s  0.00 %  6.05 % [jbd2/sda6-8]
13:13:31   390 be/3 root        0.00 B/s   30.01 K/s  0.00 %  4.60 % [jbd2/sda6-8]
Comment 1 Abdelhak Bougouffa 2014-05-24 13:14:05 UTC
Hi,
I have observed that "kworker" is writing to the disk even when no program opened >.<, when I ran `iotop -Po` I see that "kworker" write more than jbd2 :-(

I have no idea how to solve this!

I searched the web and I found that many users have the same problem

https://bbs.archlinux.org/viewtopic.php?id=171608
Comment 2 Theodore Tso 2014-05-24 14:42:23 UTC
If your kernel doesn't have ftrace enabled, please enable it by enabling the following kernel config options:

    CONFIG_FUNCTION_TRACER
    CONFIG_FUNCTION_GRAPH_TRACER
    CONFIG_STACK_TRACER
    CONFIG_DYNAMIC_FTRACE

Once you do that, make sure debugfs is mounted:

mount -t debugfs debugfs /sys/kernel/debug

Now enable the ext4_mark_inode_dirty tracepoint and start tracing:

cd /sys/kernel/debug/tracing
echo 1 > events/ext4/ext4_mark_inode_dirty/enable
cat trace_pipe

You will start seeing lines like this:

   kworker/u16:2-14718 [006] ...1 616239.342464: ext4_mark_inode_dirty: dev 252,0 ino 4203428 caller ext4_writepages+0x743/0x93e
 BrowserBlocking-5875  [006] ...1 616241.972533: ext4_mark_inode_dirty: dev 8,3 ino 3545316 caller ext4_dirty_inode+0x40/0x59


The first line indicates that process 14718, which is a kernel thread named kworking/u16:2, dirtied inode 4203428 on device 252,0, which is /dev/dm-0 (which on my system has major number 252, minor 0, which you can see by the command ls -l /dev/dm-0).   This is probably dirty inode writeback, so that doesn't help tell you who dirtied the file.  You can find the filename using debugfs:

debugfs /dev/dm-0
debugfs: ncheck 4203428
Inode	Pathname
4203428	/build/e2fsprogs-maint/tests/f_eofblocks.1.log

(and since /dev/dm-0 is mounted on /u1, I know the filename is /u1/build/e2fsprogs-maint/....)  

The second line indicates the task id was 5875, and with a name like BrowserBlocking, it's almost certainly one of the Chrome threads.  The ps program won't show individual threads by default, but you can also use the inode number to find which process has the file open by using lsof:

lsof | grep 3545316

Once you're done, don't forget to disable the tracing to save a bit on CPU and battery life:

cat /dev/null > /sys/kernel/debug/tracing/set_event

Anyway, I hope this helps.
Comment 3 Abdelhak Bougouffa 2014-05-25 09:06:35 UTC
Hi, 
Thank you Mr. Theodore

So, I tried this commands, and I get a big number of process! 

I observed that the kworker is not really the cause! the systemd-journal is writing all times to the disk!, When I traced one of his used inodes, I found it writing to /var/log/journal/****.journal, each time a file of 8MB.

http://pastebin.com/W3yu3SVH

It's notable that the debugging options:
    CONFIG_FUNCTION_TRACER
    CONFIG_FUNCTION_GRAPH_TRACER
    CONFIG_STACK_TRACER
    CONFIG_DYNAMIC_FTRACE

Are enabled in my working kernel (I installed it using the Arch repository)

Thanks!
Comment 4 Abdelhak Bougouffa 2014-05-25 09:13:45 UTC
I observed also that all the journal files are binary files and the total size of /var/log/journal directory is 2.0GB O.o ... so what can I do!!
Comment 5 Theodore Tso 2014-05-25 12:15:58 UTC
You can try running "journalctl -f" and see what kind of log messages you are seeing.  But in any case, this isn't an ext4 bug, but rather a systemd, journald, or some system daemon or distro-level bug.

If userspace shovels stuff for us to write, we have to write it!   So for that reason, I've closed out this bug.  If this isn't a configuration issue, please open a bug with the appropriate distribution or systemd bug tracking system.

Note You need to log in before you can comment on or make changes to this bug.