Hi all,
I'm debugging a strange memory hotplug issue on CentOS 6.5(2.6.32-431.17.1.el6): when a chunk of memory is hot-added, it seems the kernel *occasionally* can send a MEMORY ADD event to the udev daemon before the kernel actually creates the sys file 'state'!
As a result, udev can't reliably make new memory online by this udev rule:
SUBSYSTEM=="memory", ACTION="" ATTR{state}="online"
Please see the end of the mail for the strace log of udevd when I run udevd manually:
When udevd gets a MEMORY ADD event for /sys/devices/system/memory/memory23, it tries to write "online" to /sys/devices/system/memory/memory23/state, but the file hasn't been created by the kernel yet. In this case, when I manually check the file at once with ls, it has been created, and I can manually echo online into it to make it online correctly.
Please note: this bad behavior of the kernel is only occasional, which may imply there is a race condition somewhere?
BTW, it looks the issue does't exist in 3.10+ kernels. Is this a known issue already fixed in new kernels?
I'm trying to dig into the code and I hope I can get some suggestions here. Thanks!
-- DX
The strace log is:
1427 1400822167.053704 socket(PF_NETLINK, SOCK_DGRAM|SOCK_CLOEXEC, 15) = 5
...
1427 1400822372.247210 recvmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000001}, msg_iov(1)=[{"add@/devices/system/memory/memory23\0ACTION=add\0DEVPATH=/devices/system/memory/memory23\0SUBSYSTEM=memory\0SEQNUM=1358\0\0\0\0\0\0\0\0\0\0\0\0\\0\0\0\0\0\0\0"..., 8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=0, uid=0, gid=0}}, msg_flags=0}, 0) = 116
1427 1400822372.247298 lseek(10, 0, SEEK_CUR) = 1332
1427 1400822372.247320 write(10, "N\5\0\0\0\0\0\0\37\0/devices/system/memory/memory23", 41) = 41
1427 1400822372.247352 gettimeofday({1400822372, 247358}, NULL) = 0
1427 1400822372.247387 writev(2, [{"udevd[1427]: seq 1358 queued, 'add' 'memory'\n", 45}], 1) = 45
1427 1400822372.247428 sendto(3, "<30>May 23 06:19:32 udevd[1427]: seq 1358 queued, 'add' 'memory'\n", 65, MSG_NOSIGNAL, NULL, 0) = 65
1427 1400822372.247511 sendmsg(5, {msg_name(12)={sa_family=AF_NETLINK, pid=-4139, groups=00000000}, msg_iov(2)=[{"udev-147\0\0\0\0\0\0\0\0\312\376\35\352 \0[\0\312\n\234<\0\0\0\0", 32}, {"UDEV_LOG=7\0ACTION=add\0DEVPATH=/devices/system/memory/memory23\0SUBSYSTEM=memory\0SEQNUM=1358\0", 91}], msg_controllen=0, msg_flags=0}, 0 <unfinished ...>
1456 1400822372.247568 <... ppoll resumed> ) = 1 ([{fd=11, revents=POLLIN}])
1427 1400822372.247578 <... sendmsg resumed> ) = 123
1456 1400822372.247595 recvmsg(11, <unfinished ...>
1427 1400822372.247602 gettimeofday( <unfinished ...>
1456 1400822372.247615 <... recvmsg resumed> {msg_name(12)={sa_family=AF_NETLINK, pid=1427, groups=00000000}, msg_iov(1)=[{"udev-147\0\0\0\0\0\0\0\0\312\376\35\352 \0[\0\312\n\234<\0\0\0\0UDEV_LOG=7\0ACTION=add\0DEVPATH=/devices/system/memory/memory23\0SUBSYSTEM=memory\0SEQNUM=1358\0\0\0\0\0\0\0\\0\0\0\0\0"..., 8192}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=1427, uid=0, gid=0}}, msg_flags=0}, 0) = 123
1427 1400822372.247658 <... gettimeofday resumed> {1400822372, 247610}, NULL) = 0
1456 1400822372.247688 gettimeofday( <unfinished ...>
1427 1400822372.247695 writev(2, [{"udevd[1427]: passed 123 bytes to monitor 0x7f71f4c6a6c0\n", 56}], 1 <unfinished ...>
1456 1400822372.247715 <... gettimeofday resumed> {1400822372, 247706}, NULL) = 0
1427 1400822372.247722 <... writev resumed> ) = 56
1456 1400822372.247738 writev(2, [{"udevd-work[1456]: seq 1358 running\n", 35}], 1 <unfinished ...>
1427 1400822372.247750 sendto(3, "<30>May 23 06:19:32 udevd[1427]: passed 123 bytes to monitor 0x7f71f4c6a6c0\n", 76, MSG_NOSIGNAL, NULL, 0 <unfinished ...>1456 1400822372.247785 <... writev resumed> ) = 35
1427 1400822372.247792 <... sendto resumed> ) = 76
1456 1400822372.247805 sendto(3, "<30>May 23 06:19:32 udevd-work[1456]: seq 1358 running\n", 55, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
1427 1400822372.247816 poll([{fd=4, events=POLLIN}, {fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=8, events=POLLIN}], 5, -1 <unfinished ...>
1456 1400822372.247847 <... sendto resumed> ) = 55
1456 1400822372.247861 alarm(180) = 0
1456 1400822372.247892 gettimeofday({1400822372, 247898}, NULL) = 0
1456 1400822372.247917 writev(2, [{"udevd-work[1456]: ATTR '/sys/devices/system/memory/memory23/state' writing 'online' /etc/udev/rules.d/100-balloons.rules:1\n", 123}], 1) = 123
1456 1400822372.247946 sendto(3, "<30>May 23 06:19:32 udevd-work[1456]: ATTR '/sys/devices/system/memory/memory23/state' writing 'online' /etc/udev/rules.d/100-balloons.rules:1\n", 143, MSG_NOSIGNAL, NULL, 0) = 143
1456 1400822372.247992 open("/sys/devices/system/memory/memory23/state", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 ENOENT (No such file or directory)