Fedora16 "RAID conf printout:" monopolizing dmesg

[BrianMicek]

I'm sorry if this is a duplicate post. I did some searching and wasnt able to find anything relating to this problem but I don't frequent this forum as often as I should so I might have missed something.

My dmesg logs are swamped with my RAID6 configuration every second. I'd like to think this is a new problem but I don't know for sure. This is a snipped from dmesg:

[585067.894490] RAID conf printout:
[585067.894494]  --- level:6 rd:12 wd:12
[585067.894497]  disk 0, o:1, dev:sdb3
[585067.894500]  disk 1, o:1, dev:sdc1
[585067.894502]  disk 2, o:1, dev:sdd1
[585067.894504]  disk 3, o:1, dev:sde1
[585067.894506]  disk 4, o:1, dev:sdf1
[585067.894508]  disk 5, o:1, dev:sdg1
[585067.894510]  disk 6, o:1, dev:sdh1
[585067.894513]  disk 7, o:1, dev:md97
[585067.894515]  disk 8, o:1, dev:sdk1
[585067.894517]  disk 9, o:1, dev:md99
[585067.894519]  disk 10, o:1, dev:sdi1
[585067.894521]  disk 11, o:1, dev:sdr1
[585072.886170] RAID conf printout:
[585072.886174]  --- level:6 rd:12 wd:12
[585072.886178]  disk 0, o:1, dev:sdb3
[585072.886180]  disk 1, o:1, dev:sdc1
[585072.886182]  disk 2, o:1, dev:sdd1
[585072.886184]  disk 3, o:1, dev:sde1
[585072.886186]  disk 4, o:1, dev:sdf1
[585072.886188]  disk 5, o:1, dev:sdg1
[585072.886190]  disk 6, o:1, dev:sdh1
[585072.886192]  disk 7, o:1, dev:md97
[585072.886194]  disk 8, o:1, dev:sdk1
[585072.886196]  disk 9, o:1, dev:md99
[585072.886199]  disk 10, o:1, dev:sdi1
[585072.886201]  disk 11, o:1, dev:sdr1
[585073.087332] RAID conf printout:
[585073.087336]  --- level:6 rd:12 wd:12
[585073.087339]  disk 0, o:1, dev:sdb3
[585073.087341]  disk 1, o:1, dev:sdc1
[585073.087344]  disk 2, o:1, dev:sdd1
[585073.087346]  disk 3, o:1, dev:sde1
[585073.087348]  disk 4, o:1, dev:sdf1
[585073.087350]  disk 5, o:1, dev:sdg1
[585073.087352]  disk 6, o:1, dev:sdh1
[585073.087354]  disk 7, o:1, dev:md97
[585073.087356]  disk 8, o:1, dev:sdk1
[585073.087358]  disk 9, o:1, dev:md99
[585073.087360]  disk 10, o:1, dev:sdi1
[585073.087362]  disk 11, o:1, dev:sdr1

My first guess was that maybe /sbin/mdadm --monitor --scan might be responsible, but strace reveales it gets its data by select()ing on /proc/mdstat.

I did some Google'ing and found one Gentoo thread from about a month ago that goes nowhere here:
http://forums.gentoo.org/viewtopic-t-917936.html

[root@desktop ~]# uname -a
Linux desktop.bmicek.com 3.3.1-5.fc16.x86_64 #1 SMP Tue Apr 10 19:56:52 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux
[root@desktop ~]# cat /proc/mdstat 
Personalities : [raid0] [raid6] [raid5] [raid4] 
md98 : active raid0 sdo1[0] sdm1[1]
      1950326784 blocks super 1.2 512k chunks
      
md99 : active raid0 sdq1[1] sdp1[0]
      1950326784 blocks super 1.2 512k chunks
      
md97 : active raid0 sdl1[1] sdn1[0]
      1950326784 blocks super 1.2 512k chunks
      
md127 : active raid6 md97[7] md99[9] sdf1[4] md98[15](S) sdr1[13] sdb3[0] sde1[3] sdh1[6] sdg1[5] sdi1[12] sdk1[14] sdc1[1] sdd1[2]
      19503247360 blocks super 1.2 level 6, 1024k chunk, algorithm 0 [12/12] [UUUUUUUUUUUU]
      
unused devices: <none>

Does anyone else seem to have this problem?

[tacomac]

I had the same problem, after every boot. Not a fix, but I if I stop the raid and restart it after reboot (mdadm --stop /dev/md*, madm --assemble /dev/md*), I only get the messages every once in a while as opposed to every second.

[BrianMicek]

Hi Tomac,

Thank you for your reply. I suppose there is a clue there ... I'll try that and see what happens. Once per minutes means us humans can use dmesg again, thank you. Here is an semiinteresting development. In this kernel:

[root@desktop ~]# uname -a
Linux desktop.bmicek.com 3.3.1-5.fc16.x86_64 #1 SMP Tue Apr 10 19:56:52 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux

The rate of the messages was 1 Hz. Since then, we were issued a new kernel:

[brian@desktop ~]$ uname -a
Linux desktop.bmicek.com 3.3.2-1.fc16.x86_64 #1 SMP Sat Apr 14 00:31:23 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux

The rate of the messages seems almost random and I suppose is due to some kernel events or pressure:

##  Get the interval between these messages:
##      [489513.628407] RAID conf printout:
[brian@desktop ~]$ dmesg | awk '/^\[[0-9]+.[0-9]+\] RAID conf printout/{ 
  n = substr( $1, 2, length( $1 ) - 2 )
  print n - last
  last = n
}'
[...]
4.6596
0.319104
7.65761
0.201232
1.72282
0.201542
4.84616
0.336878
4.87376
0.201365
4.52162
0.328419
4.78517
0.229086
5.67059
0.201211
3.76636
0.402592
5.58493
0.201225
8.79128
0.212423
4.87007
0.220097
4.78426
0.230108
4.65162
0.401935
5.55004
0.200995
3.96358
0.201374
4.65553
0.202175
5.7405
0.201168
8.84002
0.202664
0.497093
0.245773
4.97768
0.201187
8.84147
0.293098
5.59683
0.201093
10.9305
0.225049
2.7871
0.201213
2.61398
0.228626
8.91676
0.202748
5.59989
0.201225
1.97727
0.253583
6.73978
0.202596
2.77504
0.22628
2.58859
0.201205
8.97826
0.203068
5.5818
0.201239
8.98804
0.235218
2.7092
0.201231
2.6136
0.201229
9.00601
0.20206
5.5393
0.201007
7.54149
0.237857
1.25057
0.203281
5.53019
0.201011
1.96959
0.202355
6.86532
0.201984
5.52404
0.201178
26.8889
0.201122
33.2822
0.203331
4.78607
0.202475
5.03651
0.201137
19.4935
0.201162
4.78422
0.201259
0.053949
0.201337
1.53921
0.25172
4.9636
0.202258
22.7627
0.20247
6.44269
0.787103
5.48227
0.201145
8.49275
0.202869
5.06255
0.201146
9.49791
0.202845
4.77525
0.201177
0.070014
0.201211
9.52813
0.202546
5.03279
0.200959
19.4615
0.201271
14.8214
0.256654
4.97377
0.2012
24.4868
0.202416
89.5194
0.259829

[george_toolan]

Try http://post.gmane.org/post.php?group=gmane.linux.raid