Bug 43167 - RAIDx conf printout keeps repeating in dmesg for no(?) reason
Summary: RAIDx conf printout keeps repeating in dmesg for no(?) reason
Status: RESOLVED PATCH_ALREADY_AVAILABLE
Alias: None
Product: IO/Storage
Classification: Unclassified
Component: MD (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Neil Brown
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-04-27 16:38 UTC by Andras Korn
Modified: 2012-04-27 21:39 UTC (History)
1 user (show)

See Also:
Kernel Version: 3.3.3
Subsystem:
Regression: Yes
Bisected commit-id:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Description Andras Korn 2012-04-27 16:38:43 UTC 
Since booting the kernel, the kernel log is flooded with RAID conf printout messages for no reason that I can see. Sample (kernel log excerpt with no omissions):

18:31:42.502493500 kern.debug: RAID1 conf printout:
18:31:42.502546500 kern.debug:  --- wd:2 rd:2
18:31:42.502583500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:42.511301500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:42.721334500 kern.debug: RAID1 conf printout:
18:31:42.721421500 kern.debug:  --- wd:2 rd:2
18:31:42.721465500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:42.721503500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:43.074112500 kern.debug: RAID1 conf printout:
18:31:43.074189500 kern.debug:  --- wd:2 rd:2
18:31:43.074227500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:43.074259500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:43.321361500 kern.debug: RAID1 conf printout:
18:31:43.321415500 kern.debug:  --- wd:2 rd:2
18:31:43.321822500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:43.321858500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:45.753518500 kern.debug: RAID10 conf printout:
18:31:45.753626500 kern.debug:  --- wd:14 rd:14
18:31:45.753717500 kern.debug:  disk 0, wo:0, o:1, dev:sda3
18:31:45.753885500 kern.debug:  disk 1, wo:0, o:1, dev:sdb3
18:31:45.761831500 kern.debug:  disk 2, wo:0, o:1, dev:sdc3
18:31:45.761885500 kern.debug:  disk 3, wo:0, o:1, dev:sdd3
18:31:45.761952500 kern.debug:  disk 4, wo:0, o:1, dev:sde3
18:31:45.772952500 kern.debug:  disk 5, wo:0, o:1, dev:sdf3
18:31:45.773007500 kern.debug:  disk 6, wo:0, o:1, dev:sdg3
18:31:45.773073500 kern.debug:  disk 7, wo:0, o:1, dev:sdh3
18:31:45.773173500 kern.debug:  disk 8, wo:0, o:1, dev:sdi3
18:31:45.781473500 kern.debug:  disk 9, wo:0, o:1, dev:sdj3
18:31:45.781527500 kern.debug:  disk 10, wo:0, o:1, dev:sdk3
18:31:45.792857500 kern.debug:  disk 11, wo:0, o:1, dev:sdl3
18:31:45.792913500 kern.debug:  disk 12, wo:0, o:1, dev:sdm3
18:31:45.792977500 kern.debug:  disk 13, wo:0, o:1, dev:sdn3
18:31:45.803595500 kern.debug: RAID1 conf printout:
18:31:45.803647500 kern.debug:  --- wd:2 rd:2
18:31:45.803712500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:45.803820500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:46.021264500 kern.debug: RAID1 conf printout:
18:31:46.021318500 kern.debug:  --- wd:2 rd:2
18:31:46.021385500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:46.021482500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:46.182197500 kern.debug: RAID1 conf printout:
18:31:46.182274500 kern.debug:  --- wd:2 rd:2
18:31:46.182365500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:46.182527500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:46.451378500 kern.debug: RAID1 conf printout:
18:31:46.451433500 kern.debug:  --- wd:2 rd:2
18:31:46.451500500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:46.451600500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:47.011349500 kern.debug: RAID1 conf printout:
18:31:47.011690500 kern.debug:  --- wd:2 rd:2
18:31:47.011799500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:47.011970500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:47.231381500 kern.debug: RAID1 conf printout:
18:31:47.231458500 kern.debug:  --- wd:2 rd:2
18:31:47.231549500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:47.231710500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:50.641913500 kern.debug: RAID1 conf printout:
18:31:50.642029500 kern.debug:  --- wd:2 rd:2
18:31:50.642105500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:50.642271500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:50.683654500 kern.debug: RAID10 conf printout:
18:31:50.683705500 kern.debug:  --- wd:14 rd:14
18:31:50.683760500 kern.debug:  disk 0, wo:0, o:1, dev:sda3
18:31:50.683867500 kern.debug:  disk 1, wo:0, o:1, dev:sdb3
18:31:50.692083500 kern.debug:  disk 2, wo:0, o:1, dev:sdc3
18:31:50.692161500 kern.debug:  disk 3, wo:0, o:1, dev:sdd3
18:31:50.692319500 kern.debug:  disk 4, wo:0, o:1, dev:sde3
18:31:50.703235500 kern.debug:  disk 5, wo:0, o:1, dev:sdf3
18:31:50.703310500 kern.debug:  disk 6, wo:0, o:1, dev:sdg3
18:31:50.703454500 kern.debug:  disk 7, wo:0, o:1, dev:sdh3
18:31:50.703524500 kern.debug:  disk 8, wo:0, o:1, dev:sdi3
18:31:50.711624500 kern.debug:  disk 9, wo:0, o:1, dev:sdj3
18:31:50.711683500 kern.debug:  disk 10, wo:0, o:1, dev:sdk3
18:31:50.711791500 kern.debug:  disk 11, wo:0, o:1, dev:sdl3
18:31:50.721344500 kern.debug:  disk 12, wo:0, o:1, dev:sdm3
18:31:50.721399500 kern.debug:  disk 13, wo:0, o:1, dev:sdn3
18:31:51.601448500 kern.debug: RAID1 conf printout:
18:31:51.601523500 kern.debug:  --- wd:2 rd:2
18:31:51.601680500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:51.601753500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:51.641296500 kern.debug: RAID1 conf printout:
18:31:51.641350500 kern.debug:  --- wd:2 rd:2
18:31:51.641455500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:51.641509500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:51.851276500 kern.debug: RAID1 conf printout:
18:31:51.851398500 kern.debug:  --- wd:2 rd:2
18:31:51.851528500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:51.851606500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:52.022226500 kern.debug: RAID1 conf printout:
18:31:52.022281500 kern.debug:  --- wd:2 rd:2
18:31:52.022389500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:52.022448500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:52.281382500 kern.debug: RAID1 conf printout:
18:31:52.281458500 kern.debug:  --- wd:2 rd:2
18:31:52.281583500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:52.281653500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:52.523258500 kern.debug: RAID1 conf printout:
18:31:52.523320500 kern.debug:  --- wd:2 rd:2
18:31:52.531373500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:52.531428500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:52.851415500 kern.debug: RAID1 conf printout:
18:31:52.851493500 kern.debug:  --- wd:2 rd:2
18:31:52.851619500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:52.851692500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:52.931879500 kern.debug: RAID1 conf printout:
18:31:52.931935500 kern.debug:  --- wd:2 rd:2
18:31:52.932024500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:52.941478500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:31:53.243275500 kern.debug: RAID10 conf printout:
18:31:53.243431500 kern.debug:  --- wd:14 rd:14
18:31:53.243474500 kern.debug:  disk 0, wo:0, o:1, dev:sda3
18:31:53.243539500 kern.debug:  disk 1, wo:0, o:1, dev:sdb3
18:31:53.243701500 kern.debug:  disk 2, wo:0, o:1, dev:sdc3
18:31:53.251642500 kern.debug:  disk 3, wo:0, o:1, dev:sdd3
18:31:53.251696500 kern.debug:  disk 4, wo:0, o:1, dev:sde3
18:31:53.251737500 kern.debug:  disk 5, wo:0, o:1, dev:sdf3
18:31:53.262678500 kern.debug:  disk 6, wo:0, o:1, dev:sdg3
18:31:53.262734500 kern.debug:  disk 7, wo:0, o:1, dev:sdh3
18:31:53.262775500 kern.debug:  disk 8, wo:0, o:1, dev:sdi3
18:31:53.262825500 kern.debug:  disk 9, wo:0, o:1, dev:sdj3
18:31:53.274076500 kern.debug:  disk 10, wo:0, o:1, dev:sdk3
18:31:53.274131500 kern.debug:  disk 11, wo:0, o:1, dev:sdl3
18:31:53.274172500 kern.debug:  disk 12, wo:0, o:1, dev:sdm3
18:31:53.274221500 kern.debug:  disk 13, wo:0, o:1, dev:sdn3
18:31:53.401417500 kern.debug: RAID1 conf printout:
18:31:53.401471500 kern.debug:  --- wd:2 rd:2
18:31:53.401510500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:31:53.401558500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:00.643398500 kern.debug: RAID1 conf printout:
18:32:00.643483500 kern.debug:  --- wd:2 rd:2
18:32:00.643601500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:00.643800500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:00.722872500 kern.debug: RAID10 conf printout:
18:32:00.722980500 kern.debug:  --- wd:14 rd:14
18:32:00.732936500 kern.debug:  disk 0, wo:0, o:1, dev:sda3
18:32:00.732974500 kern.debug:  disk 1, wo:0, o:1, dev:sdb3
18:32:00.733028500 kern.debug:  disk 2, wo:0, o:1, dev:sdc3
18:32:00.733237500 kern.debug:  disk 3, wo:0, o:1, dev:sdd3
18:32:00.744085500 kern.debug:  disk 4, wo:0, o:1, dev:sde3
18:32:00.744141500 kern.debug:  disk 5, wo:0, o:1, dev:sdf3
18:32:00.744222500 kern.debug:  disk 6, wo:0, o:1, dev:sdg3
18:32:00.744374500 kern.debug:  disk 7, wo:0, o:1, dev:sdh3
18:32:00.752470500 kern.debug:  disk 8, wo:0, o:1, dev:sdi3
18:32:00.752524500 kern.debug:  disk 9, wo:0, o:1, dev:sdj3
18:32:00.752601500 kern.debug:  disk 10, wo:0, o:1, dev:sdk3
18:32:00.763922500 kern.debug:  disk 11, wo:0, o:1, dev:sdl3
18:32:00.763976500 kern.debug:  disk 12, wo:0, o:1, dev:sdm3
18:32:00.764053500 kern.debug:  disk 13, wo:0, o:1, dev:sdn3
18:32:01.791319500 kern.debug: RAID1 conf printout:
18:32:01.791525500 kern.debug:  --- wd:2 rd:2
18:32:01.791581500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:01.791740500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:02.073905500 kern.debug: RAID1 conf printout:
18:32:02.073987500 kern.debug:  --- wd:2 rd:2
18:32:02.074055500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:02.074203500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:02.291627500 kern.debug: RAID1 conf printout:
18:32:02.291694500 kern.debug:  --- wd:2 rd:2
18:32:02.291753500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:02.291859500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:02.393166500 kern.debug: RAID1 conf printout:
18:32:02.393227500 kern.debug:  --- wd:2 rd:2
18:32:02.401348500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:02.401409500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:02.801843500 kern.debug: RAID1 conf printout:
18:32:02.801952500 kern.debug:  --- wd:2 rd:2
18:32:02.802032500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:02.802123500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:03.073887500 kern.debug: RAID1 conf printout:
18:32:03.073968500 kern.debug:  --- wd:2 rd:2
18:32:03.074158500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:03.074285500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:03.291263500 kern.debug: RAID1 conf printout:
18:32:03.291323500 kern.debug:  --- wd:2 rd:2
18:32:03.291363500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:03.291442500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:03.341353500 kern.debug: RAID1 conf printout:
18:32:03.341408500 kern.debug:  --- wd:2 rd:2
18:32:03.341450500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:03.341529500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2
18:32:03.423041500 kern.debug: RAID10 conf printout:
18:32:03.423096500 kern.debug:  --- wd:14 rd:14
18:32:03.423136500 kern.debug:  disk 0, wo:0, o:1, dev:sda3
18:32:03.431404500 kern.debug:  disk 1, wo:0, o:1, dev:sdb3
18:32:03.431458500 kern.debug:  disk 2, wo:0, o:1, dev:sdc3
18:32:03.431499500 kern.debug:  disk 3, wo:0, o:1, dev:sdd3
18:32:03.442540500 kern.debug:  disk 4, wo:0, o:1, dev:sde3
18:32:03.442593500 kern.debug:  disk 5, wo:0, o:1, dev:sdf3
18:32:03.442633500 kern.debug:  disk 6, wo:0, o:1, dev:sdg3
18:32:03.442711500 kern.debug:  disk 7, wo:0, o:1, dev:sdh3
18:32:03.453682500 kern.debug:  disk 8, wo:0, o:1, dev:sdi3
18:32:03.453732500 kern.debug:  disk 9, wo:0, o:1, dev:sdj3
18:32:03.453775500 kern.debug:  disk 10, wo:0, o:1, dev:sdk3
18:32:03.453854500 kern.debug:  disk 11, wo:0, o:1, dev:sdl3
18:32:03.462339500 kern.debug:  disk 12, wo:0, o:1, dev:sdm3
18:32:03.462394500 kern.debug:  disk 13, wo:0, o:1, dev:sdn3
18:32:03.561340500 kern.debug: RAID1 conf printout:
18:32:03.561393500 kern.debug:  --- wd:2 rd:2
18:32:03.561433500 kern.debug:  disk 0, wo:0, o:1, dev:sdo2
18:32:03.561510500 kern.debug:  disk 1, wo:0, o:1, dev:sdp2

All the RAID arrays are fine. mdstat says:

Personalities : [raid1] [raid10] [raid6] [raid5] [raid4] 
md125 : active raid10 sda3[0] sdr3[14](S) sdn3[13] sdm3[12] sdl3[11] sdk3[10] sdj3[9] sdi3[8] sdh3[7] sdg3[6] sdf3[5] sde3[4] sdd3[3] sdc3[2] sdb3[1]
      6837146624 blocks super 1.2 512K chunks 3 far-copies [14/14] [UUUUUUUUUUUUUU]
      bitmap: 3/408 pages [12KB], 8192KB chunk, file: /mdbitmap/encrypted

md126 : active raid10 sda2[0] sdr2[14](S) sdn2[13] sdm2[12] sdl2[11] sdk2[10] sdj2[9] sdi2[8] sde2[7] sdd2[6] sdg2[5] sdh2[4] sdb2[3] sdf2[2] sdc2[1]
      225792 blocks super 1.2 512K chunks 2 near-copies [14/14] [UUUUUUUUUUUUUU]
      bitmap: 0/1 pages [0KB], 65536KB chunk

md127 : active raid1 sdo2[0] sdq2[2](S) sdp2[1]
      24428015 blocks super 1.2 [2/2] [UU]
      bitmap: 1/1 pages [4KB], 65536KB chunk

unused devices: <none>

Stopping the mdadm --monitor process has no effect.

This box didn't exhibit this behaviour with its previous kernel (3.2.2).

For completeness's sake, lsscsi:

[0:0:0:0]    disk    ATA      ST31500341AS     CC1H  /dev/sda
[0:0:1:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdb
[0:0:2:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdc
[0:0:3:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdd
[0:0:4:0]    disk    ATA      ST31500341AS     CC1H  /dev/sde
[0:0:5:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdf
[0:0:6:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdg
[0:0:7:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdh
[1:0:0:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdi
[2:0:0:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdj
[3:0:0:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdk
[4:0:0:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdl
[5:0:0:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdm
[6:0:0:0]    disk    ATA      ST31500341AS     CC1H  /dev/sdn
[7:0:0:0]    disk    ATA      OCZ-REVODRIVE    1.20  /dev/sdo
[8:0:0:0]    disk    ATA      OCZ-REVODRIVE    1.20  /dev/sdp
[11:0:0:0]   disk    ATA      KINGSTON SV100S2 D110  /dev/sdq
[12:0:0:0]   disk    ATA      ST31500341AS     CC1H  /dev/sdr
Comment 1 Neil Brown 2012-04-27 21:39:05 UTC 
Thanks for the report.

Already fixed in mainline and queue for the next 3.3.y stable  release.

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commitdiff;h=ed209584c38fb74b7eecc03e5b1bfe674e591bd8
Comment 2 Neil Brown 2012-04-27 21:39:56 UTC 
So: marking as "fixed".

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