jbd2 spin disk
Li Tianqing
jazeltq at 163.com
Tue Aug 26 10:04:01 UTC 2014
Hello,
Our service will update and insert mysql every seconds. Through vmstat 1, i found sometimes there will be one process blocked, even low load average.
#vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
1 0 95052 3297272 331332 4941420 0 0 0 88 1518 3665 1 0 98 1
1 0 95052 3298196 331332 4941424 0 0 0 12 1691 2993 2 0 97 0
2 0 95052 3289128 331336 4941424 0 0 0 68 2046 5909 5 1 93 1
2 1 95052 3289144 331336 4941396 0 0 0 2728 1976 4152 2 0 94 4
1 0 95052 3288384 331336 4941396 0 0 0 104 1349 2555 0 0 99 1
0 0 95052 3287640 331336 4941396 0 0 16 44 1541 3790 2 0 97 0
0 0 95052 3287880 331336 4941404 0 0 0 84 1132 2371 0 0 98 2
0 0 95052 3287640 331344 4941404 0 0 0 76 948 1968 0 0 99 0
0 0 95052 3287888 331344 4941404 0 0 0 72 919 2071 0 0 99 0
0 0 95052 3287632 331344 4941408 0 0 0 56 950 2040 0 0 99 0
0 1 95052 3287020 331344 4941408 0 0 0 68 945 2177 0 0 99 0
1 0 95052 3286788 331344 4941408 0 0 0 16 1799 3082 2 0 97 0
3 0 95052 3310200 331344 4941408 0 0 0 16 1839 5537 4 1 95 0
0 1 95052 3297436 331344 4941408 0 0 0 1144 1915 4847 2 1 96 2
1 0 95052 3292864 331348 4941408 0 0 0 2460 1352 2721 1 0 96 3
2 0 95052 3289392 331348 4941412 0 0 0 40 1479 3583 2 0 97 0
1 0 95052 3288772 331348 4941412 0 0 0 96 1210 2935 2 0 98 1
3 0 95052 3288648 331348 4941416 0 0 32 100 1333 3316 1 0 98 0
0 0 95052 3288400 331348 4941420 0 0 0 16 902 2001 0 0 99 0
0 0 95052 3288276 331348 4941420 0 0 0 52 957 2146 0 0 99 0
0 0 95052 3288392 331356 4941420 0 0 0 72 930 1904 0 0 99 0
1 0 95052 3287904 331356 4941420 0 0 0 32 1695 3027 2 0 97 0
1 0 95052 3287120 331356 4941428 0 0 0 52 1710 5515 4 1 94 1
0 1 95052 3286408 331356 4941424 0 0 0 140 1743 4155 2 0 97 1
1 1 95052 3286540 331356 4941424 0 0 0 2204 1186 2306 0 0 97 3
0 0 95052 3296328 331356 4941432 0 0 0 336 2011 6134 3 1 95 1
0 0 95052 3295832 331360 4941432 0 0 0 232 1066 2155 0 0 98 1
1 0 95052 3288268 331360 4941432 0 0 0 36 1238 2716 1 0 99 0
0 1 95052 3288268 331360 4941432 0 0 0 16 836 1809 0 0 99 1
Though command
# for i in {1..10000}; do echo $i; sleep 1; ps -A -o stat,pid,ppid,cmd | grep ^D; done
I found the blocked process is jbd2
686
687
D 1114 2 [jbd2/sda7-8]
688
689
D 1114 2 [jbd2/sda7-8]
690
691
692
693
694
695
696
697
D 1114 2 [jbd2/sda7-8]
698
D 1114 2 [jbd2/sda7-8]
699
700
701
702
703
704
D 1114 2 [jbd2/sda7-8]
705
706
D 1114 2 [jbd2/sda7-8]
707
D 1114 2 [jbd2/sda7-8]
708
709
710
711
712
713
714
715
716
D 1114 2 [jbd2/sda7-8]
So i have to check why jbd2 blocks.
echo 1 > /sys/kernel/debug/tracing/events/ext4/ext4_sync_file_enter/enable
echo 1 >/sys/kernel/debug/tracing/events/jbd2/jbd2_run_stats/enable
cat /sys/kernel/debug/tracing/trace_pipe
the output is
mysqld-17827 [022] .... 4316483.034183: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316483.095619: jbd2_run_stats: dev 8,7 tid 33547583 wait 0 running 176 locked 0 flushing 0 logging 60 handle_count 21 blocks 5 blocks_logged 6
mysqld-18157 [000] .... 4316483.411990: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316483.454115: jbd2_run_stats: dev 8,7 tid 33547584 wait 0 running 0 locked 0 flushing 0 logging 44 handle_count 4 blocks 1 blocks_logged 2
mysqld-18667 [020] .... 4316484.129698: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316484.187673: jbd2_run_stats: dev 8,7 tid 33547585 wait 0 running 636 locked 0 flushing 0 logging 56 handle_count 7 blocks 2 blocks_logged 3
mysqld-3215 [002] .... 4316484.267753: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316484.304443: jbd2_run_stats: dev 8,7 tid 33547586 wait 0 running 0 locked 0 flushing 0 logging 36 handle_count 4 blocks 1 blocks_logged 2
mysqld-18455 [004] .... 4316484.304611: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316484.346176: jbd2_run_stats: dev 8,7 tid 33547587 wait 0 running 4 locked 0 flushing 0 logging 40 handle_count 4 blocks 1 blocks_logged 2
mysqld-18172 [016] .... 4316484.421423: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
<...>-1114 [000] .... 4316484.479634: jbd2_run_stats: dev 8,7 tid 33547588 wait 0 running 44 locked 0 flushing 0 logging 56 handle_count 9 blocks 2 blocks_logged 3
mysqld-18670 [013] .... 4316484.575137: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316484.613081: jbd2_run_stats: dev 8,7 tid 33547589 wait 0 running 0 locked 0 flushing 0 logging 40 handle_count 4 blocks 1 blocks_logged 2
mysqld-17859 [022] .... 4316484.613262: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316484.654812: jbd2_run_stats: dev 8,7 tid 33547590 wait 0 running 0 locked 0 flushing 0 logging 40 handle_count 4 blocks 1 blocks_logged 2
mysqld-18675 [000] .... 4316484.654944: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316484.713271: jbd2_run_stats: dev 8,7 tid 33547591 wait 0 running 28 locked 0 flushing 0 logging 60 handle_count 9 blocks 2 blocks_logged 3
mysqld-18672 [000] .... 4316484.777990: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
<...>-1114 [000] .... 4316484.821684: jbd2_run_stats: dev 8,7 tid 33547592 wait 0 running 0 locked 0 flushing 0 logging 44 handle_count 4 blocks 1 blocks_logged 2
mysqld-19214 [020] .... 4316485.255733: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316485.313704: jbd2_run_stats: dev 8,7 tid 33547593 wait 0 running 388 locked 0 flushing 0 logging 60 handle_count 21 blocks 6 blocks_logged 7
mysqld-19216 [000] .... 4316485.746448: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316485.805533: jbd2_run_stats: dev 8,7 tid 33547594 wait 0 running 92 locked 0 flushing 0 logging 60 handle_count 13 blocks 3 blocks_logged 4
mysqld-19345 [010] .... 4316485.805740: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
<...>-1114 [000] .... 4316485.838973: jbd2_run_stats: dev 8,7 tid 33547595 wait 0 running 0 locked 0 flushing 0 logging 32 handle_count 6 blocks 1 blocks_logged 2
jbd2/sda2-8-429 [000] .... 4316486.560002: jbd2_run_stats: dev 8,2 tid 1047748 wait 0 running 5424 locked 0 flushing 0 logging 36 handle_count 545 blocks 8 blocks_logged 9
mysqld-18673 [000] .... 4316486.842051: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316487.014462: jbd2_run_stats: dev 8,7 tid 33547596 wait 0 running 1000 locked 0 flushing 0 logging 172 handle_count 28 blocks 7 blocks_logged 8
mysqld-18331 [004] .... 4316487.014624: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316487.047848: jbd2_run_stats: dev 8,7 tid 33547597 wait 0 running 0 locked 0 flushing 0 logging 32 handle_count 4 blocks 1 blocks_logged 2
mysqld-18161 [000] .... 4316487.133665: ext4_sync_file_enter: dev 8,7 ino 9175099 parent 9176932 datasync 0
jbd2/sda7-8-1114 [000] .... 4316487.164705: jbd2_run_stats: dev 8,7 tid 33547598 wait 0 running 80 locked 0 flushing 0 logging 28 handle_count 18 blocks 4 blocks_logged 5
And i thought, every mysql's transaction will flush innodb's log into disk, and then jbd2 will be trigged?
But, there are at most 50 update request and 1 insert request in 10s, mysql is not in high pressure. And the data is not big.
why jbd2 blocks?
Thanks
# some usefull things to help
root at controller:~# free -m
total used free shared buffers cached
Mem: 16039 12844 3194 0 324 4835
-/+ buffers/cache: 7684 8354
Swap: 32747 92 32655
# root at controller:~# tune2fs -l /dev/sda7
tune2fs 1.42 (29-Nov-2011)
Filesystem volume name: <none>
Last mounted on: /var
Filesystem UUID: fc6286df-30af-4708-816a-0c248fe427a3
Filesystem magic number: 0xEF53
Filesystem revision #: 1 (dynamic)
Filesystem features: has_journal ext_attr resize_inode dir_index filetype needs_recovery extent flex_bg sparse_super large_file huge_file uninit_bg dir_nlink extra_isize
Filesystem flags: signed_directory_hash
Default mount options: user_xattr acl
Filesystem state: clean
Errors behavior: Continue
Filesystem OS type: Linux
Inode count: 53927936
Block count: 215708416
Reserved block count: 10785420
Free blocks: 190085907
Free inodes: 53923213
First block: 0
Block size: 4096
Fragment size: 4096
Reserved GDT blocks: 972
Blocks per group: 32768
Fragments per group: 32768
Inodes per group: 8192
Inode blocks per group: 512
Flex block group size: 16
Filesystem created: Wed Jun 18 13:03:47 2014
Last mount time: Mon Jul 7 18:33:05 2014
Last write time: Mon Jul 7 18:33:05 2014
Mount count: 3
Maximum mount count: -1
Last checked: Wed Jun 18 13:03:47 2014
Check interval: 0 (<none>)
Lifetime writes: 2702 MB
Reserved blocks uid: 0 (user root)
Reserved blocks gid: 0 (group root)
First inode: 11
Inode size: 256
Required extra isize: 28
Desired extra isize: 28
Journal inode: 8
First orphan inode: 53215919
Default directory hash: half_md4
Directory Hash Seed: 0ef3feba-0efd-4b91-a58a-c74b3070c2ea
Journal backup: inode blocks
# some content in my.cnf
# Fine Tuning
#
key_buffer_size = 512M
max_allowed_packet = 256M
thread_stack = 256M
thread_cache_size = 512
# This replaces the startup script and checks MyISAM tables if needed
# the first time they are touched
# myisam-recover = BACKUP
max_connections = 1000
table_cache = 800
#thread_concurrency = 10
thread_concurrency = 48
#
# * Query Cache Configuration
#
query_cache_limit = 1024M
query_cache_size = 128M
open_files_limit = 5000
memlock
innodb_buffer_pool_size = 2048M
innodb_open_files = 3000
innodb_log_file_size = 64M
innodb_flush_method=O_DIRECT
max_connect_errors = 100
Thanks a lot
--
Best
Li Tianqing
More information about the Ubuntu-devel-discuss
mailing list