on VMware Workstation guests systemd-197-1.fc18.2.x86_64 at boot floods the syslog very often and in some cases in a endless-loop prevent from finish boot linux /vmlinuz-3.8.3-203.fc18.x86_64 root=UUID=b99c8add-2876-46c2-903d-0ee364d9183f ro audit=0 rd.plymouth=0 plymouth.enable=0 rd_MD_UUID=9e072dda:e6f9d547:537f606a:891662c1 rd_MD_UUID=61e64330:1ecc65bb:2b46ebaf:69e5d5da printk.time=0 rd_NO_LUKS rd_NO_LVM rd_NO_DM nomodeset selinux=0 ipv6.disable=1 scsi_mod.scan=sync biosdevname=0 elevator=noop divider=10 clocksource=hpet nousb noisapnp nosmp noacpi noapic consoleblank=0 noresume nodomains nobar norom printk.time=0 thermal.off=1 cgroup_disable=memory LANG=de_DE.UTF-8 Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Started Postfix MTA. Mar 23 02:11:41 raid systemd[1]: Starting Multi-User. Mar 23 02:11:41 raid systemd[1]: Reached target Multi-User. Mar 23 02:11:41 raid systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 23 02:11:41 raid systemd[1]: Time has been changed Mar 23 02:11:41 raid systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse.
systemd detects when CLOCK_REALTIME is set and acts accordingly. It is not expected to be frequently recurring event. I don't know why in your case it is. Perhaps VMware does something unusual to the time.
that may all be true but there is no valid reason to trigger this more than 10000 times in a 9 second boot-process - this should be delayed the same way as readahead and rate-controlled in general
I have downgraded the "time change, recalculating next elapse" message to debug level: http://cgit.freedesktop.org/systemd/systemd/commit/?id=c5962bd1d11553425e3784ee00aa8d101c1b80fc I am keeping the "Time has been changed" at info level, because I believe that setting of the realtime clock is a sufficiently noteworthy event. In this BZ I would like to find why it's set to many times during your boot. Does the flood stop eventually, or do you keep getting more of these messages long after boot?
after the system has finished boot and i call "dmesg -c" and clean "/var/log/messages" all is silent and the messages no longer appearing interesting is that this affects only one virtual machine out of three and i have comapred the vmx-settings, kernel-params, package-vesions and all is the same except that this one has nearly no running services because it is only a rpmbuild-environment sometimes wehn i reboot this specific VM the messages are ending in a loop and sshd nor console login is possible and that is what alarmed me most besides the flood on my rsyslog to a mysql-db on the host
Please boot this virtual machine with the following two parameters on the kernel command line: ftrace=function ftrace_filter=clock_was_set,clock_was_set_delayed,do_settimeofday,timekeeping_inject_offset,timekeeping_inject_sleeptime After booting, please show me the contents of /sys/kernel/debug/tracing/trace. It's likely going to be huge and periodically repetitive, so only a small part of it will suffice.
hmm with the debug params this does not happen and currently after remove them also not, dmaned until a few hours ago this was reproduceable every boot :-( i let them enabled and report back here if it happens the next time # tracer: function # # entries-in-buffer/entries-written: 4/4 #P:8 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | systemd-1 [007] .... 1.780621: do_settimeofday <-rtc_hctosys systemd-1 [007] .... 1.780628: clock_was_set <-do_settimeofday systemd-1 [000] .... 2.677528: do_settimeofday <-do_sys_settimeofday systemd-1 [000] .... 2.677536: clock_was_set <-do_settimeofday
it happened again now, but the trace is small comaped with how often it happened [root@buildserver64:~]$ cat messages | grep "Time has been changed" | wc -l 28961 ____________________________________________________________ [root@buildserver64:~]$ cat /sys/kernel/debug/tracing/trace # tracer: function # # entries-in-buffer/entries-written: 6/6 #P:8 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | systemd-1 [000] .... 1.960471: do_settimeofday <-rtc_hctosys systemd-1 [000] .... 1.960478: clock_was_set <-do_settimeofday systemd-1 [000] .... 4.148129: do_settimeofday <-do_sys_settimeofday systemd-1 [000] .... 4.148267: clock_was_set <-do_settimeofday vmtoolsd-418 [005] .... 6.909326: do_settimeofday <-do_sys_settimeofday vmtoolsd-418 [005] .... 6.909335: clock_was_set <-do_settimeofday [root@buildserver64:~]$ ____________________________________________________________ time-sync of the vm-tools is disabled but this is triggered once after actions like boot/resume/vmotion and should not have this bad effect [root@srv-rhsoft:~]$ cat /vmware/Buildserver64/*.vmx | grep -i time tools.syncTime = "FALSE" after boot has finished all is silent as you can see here Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: systemd-tmpfiles-clean.timer: time change, recalculating next elapse. Mar 26 23:13:41 buildserver64 kernel: eth0: NIC Link is Up 10000 Mbps Mar 26 23:13:43 buildserver64 network[472]: Schnittstelle eth0 hochfahren: [ OK ] Mar 26 23:13:43 buildserver64 systemd[1]: Started LSB: Bring up/down networking. Mar 26 23:13:43 buildserver64 systemd[1]: Starting Network. Mar 26 23:13:44 buildserver64 systemd[1]: Reached target Network. Mar 26 23:13:44 buildserver64 systemd[1]: Starting OpenSSH server daemon... Mar 26 23:13:44 buildserver64 systemd[1]: Started OpenSSH server daemon. Mar 26 23:13:44 buildserver64 systemd[1]: Starting Postfix MTA... Mar 26 23:13:44 buildserver64 systemd[1]: Started Postfix MTA. Mar 26 23:13:44 buildserver64 systemd[1]: Starting Multi-User. Mar 26 23:13:44 buildserver64 systemd[1]: Reached target Multi-User. Mar 26 23:13:44 buildserver64 systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 26 23:13:44 buildserver64 systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 26 23:13:44 buildserver64 systemd[1]: Startup finished in 1s 723ms 541us (kernel) + 2s 277ms 368us (initrd) + 14s 63ms 393us (userspace) = 18s 64ms 302us. ____________________________________________________________ all from the same boot: Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed Mar 26 23:13:38 buildserver64 systemd[1]: Time has been changed
The trace shows there's no crazy process setting the time repeatedly. That's good. So a single change of the time causes systemd to wake up spuriously many times. I see. The problem must be the missing removal of the time change watch fd from the epoll set that got fixed in v198 by this commit: http://cgit.freedesktop.org/systemd/systemd/commit/?id=f1324eaa6868f196cccfec839e126ea0046cb6b6
can i have a koji-build for fedora 18 with this patch applied to test and report back?
scratch build: http://koji.fedoraproject.org/koji/taskinfo?taskID=5181760
thank you for the scratch-build installed on the specific VM the first 5 reboots are clean but as we saw this not always to be reproduceable too soon to confirm i will reboot this VM the next days randomly and would say if the problem no longer happens it would be go to updates-testing with the patched version to get a broader tester-base
The same issue occurred in the RHEL7.0 (3.7.0-0.36.el7.x86_64) guest running in the MS Hyper-V host. The dmesg log attached.(Hyper-V_dmesg.txt)
Created attachment 717528 [details] Hyper-V_dmesg.txt
for me after countelss random reboots the scratch-build http://koji.fedoraproject.org/koji/taskinfo?taskID=5181760 is fixing the problem and i strongly recommend to include the patch in a "official" systemd-update for F18 since i have to upgrade the porduction-infrastructure in a few months which is all running on VMware ESXi
thank you especially for systemd-201 for F18 http://koji.fedoraproject.org/koji/buildinfo?buildID=410598 running on two test-VM's as far as i can say pretty fine i plan to upgrade my physical machines tonight or at least tomorrow and give ASAP ositive karma - besides the problem of this bugreport it will fix the "never removed PrivateTmp"-folders and i am really happy that with F18 systemd get updates too, the v44 in F17 is really frustrating thank you!
systemd-201-2.fc18.1 has been submitted as an update for Fedora 18. https://admin.fedoraproject.org/updates/systemd-201-2.fc18.1
systemd-201-2.fc18.1 works also fine on my physical machines acting as workstation/server/router/firewall/wlan-ap is it intentional that "/var/log/journal/" is created for F18 well after see this in F19 i changed my configs everywhere for journald, but maybe this should be avoided in F18
It is a mistake. Thanks for pointing this out. I'll fix it in the next build.
ok, i thought so and liked to warn because most users may not be prepared for the change like my machines since a few days :-) BTW: a cosmetic problem, in dmesg it says it's "systemd 197" instead 201 while /var/log/messages is correct, saw it at a recent reboot by playing around with interface-names [root@buildserver64:~]$ dmesg | grep "system mode" [ 1.560258] systemd[1]: systemd 197 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ) [root@buildserver64:~]$ cat /var/log/messages | grep "system mode" Apr 11 14:28:03 buildserver64 systemd[1]: systemd 201 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ)
(In reply to comment #19) > [ 1.560258] systemd[1]: systemd 197 running in system mode. (+PAM > +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ) That's likely because you still have systemd-197 in the initramfs. If you regenerate it with dracut, it should show 201 then too.
you are right! good to know that a "dracut -f" is a good idea after a systemd update to get potential bugs also fixed there - shouldn't this be done with a rpm-post-script like after a kernel-update? [root@testserver:~]$ dmesg | grep "system mode" [ 1.720107] systemd[1]: systemd 201 running in system mode. (+PAM +LIBWRAP +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ)
(In reply to comment #12) > The same issue occurred in the RHEL7.0 (3.7.0-0.36.el7.x86_64) guest running > in the MS Hyper-V host. > The dmesg log attached.(Hyper-V_dmesg.txt) File a bug to trace the Hyper-V RHEL7.0 guest issue. Bug 951099 - [Hyper-V][RHEL7.0]flood: systemd-tmpfiles-clean.timer: time change, recalculating next elapse
systemd-201-2.fc18.2.x86_64 does fix the regressions for F18 but there are some minor-issues in dmesg: [ 1.000753] systemd[1]: Cannot add dependency job for unit timers.target, ignoring: Unit timers.target failed to load: No such file or directory. See system logs and 'systemctl status timers.target' for details. [ 1.000902] systemd[1]: Cannot add dependency job for unit paths.target, ignoring: Unit paths.target failed to load: No such file or directory. See system logs and 'systemctl status paths.target' for details. [root@rh:~]$ systemctl status timers.target timers.target - Timers Loaded: loaded (/usr/lib/systemd/system/timers.target; static) Active: active since Do 2013-04-11 21:18:50 CEST; 5min ago Docs: man:systemd.special(7) [root@rh:~]$ systemctl status paths.target paths.target - Paths Loaded: loaded (/usr/lib/systemd/system/paths.target; static) Active: active since Do 2013-04-11 21:18:50 CEST; 6min ago Docs: man:systemd.special(7) [root@rh:~]$ cat /usr/lib/systemd/system/timers.target # This file is part of systemd. # # systemd is free software; you can redistribute it and/or modify it # under the terms of the GNU Lesser General Public License as published by # the Free Software Foundation; either version 2.1 of the License, or # (at your option) any later version. [Unit] Description=Timers Documentation=man:systemd.special(7) [root@rh:~]$ cat /usr/lib/systemd/system/paths.target # This file is part of systemd. # # systemd is free software; you can redistribute it and/or modify it # under the terms of the GNU Lesser General Public License as published by # the Free Software Foundation; either version 2.1 of the License, or # (at your option) any later version. [Unit] Description=Paths Documentation=man:systemd.special(7)
Package systemd-201-2.fc18.2: * should fix your issue, * was pushed to the Fedora 18 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing systemd-201-2.fc18.2' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-5452/systemd-201-2.fc18.2 then log in and leave karma (feedback).
(In reply to comment #23) > systemd-201-2.fc18.2.x86_64 does fix the regressions for F18 but > there are some minor-issues in dmesg: > > [ 1.000753] systemd[1]: Cannot add dependency job for unit timers.target, > ignoring: Unit timers.target failed to load: No such file or directory. See > system logs and 'systemctl status timers.target' for details. > [ 1.000902] systemd[1]: Cannot add dependency job for unit paths.target, > ignoring: Unit paths.target failed to load: No such file or directory. See > system logs and 'systemctl status paths.target' for details. These might be from the initramfs, because old dracut does not know about these new units.
nope, after learned yesterday that "dracut -f" is strongly recommended after systemd-updates i did this for the reboot and some minutes ago on the test-VM again as you can see in the ls-output [root@testserver:~]$ dmesg | grep unit [ 1.851004] systemd[1]: Cannot add dependency job for unit timers.target, ignoring: Unit timers.target failed to load: No such file or directory. See system logs and 'systemctl status timers.target' for details. [ 1.853770] systemd[1]: Cannot add dependency job for unit paths.target, ignoring: Unit paths.target failed to load: No such file or directory. See system logs and 'systemctl status paths.target' for details. [root@testserver:~]$ ls /boot/ insgesamt 14M drwxr-xr-x. 3 root root 1,0K 2008-08-09 18:14 efi drwxr-xr-x 6 root root 1,0K 2013-04-10 15:10 grub2 drwx------. 2 root root 12K 2008-08-09 18:07 lost+found -rw------- 1 root root 6,0M 2013-04-12 10:13 initramfs-3.8.6-203.fc18.x86_64.img -rw-r--r-- 1 root root 123K 2013-04-09 21:37 config-3.8.6-203.fc18.x86_64 -rw------- 1 root root 2,5M 2013-04-09 21:37 System.map-3.8.6-203.fc18.x86_64 -rwxr-xr-x 1 root root 4,8M 2013-04-09 21:37 vmlinuz-3.8.6-203.fc18.x86_64
ah sorry forget it i missed the "old dracut" and parsed only the "initramfs" sorry!
Ah, yes, basic.target refers to these units, but they are not included in the initramfs. Since initramfs has no need for these units, the messages are harmless. I don't think I'm going to add any workarounds for these.
thank you for your feedback yes, all running fine here on 2 physical und 4 virtual machines these harmless messages can be cleaned up somewhere in the future with a new dracut-release
Package systemd-201-2.fc18.4: * should fix your issue, * was pushed to the Fedora 18 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing systemd-201-2.fc18.4' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-5452/systemd-201-2.fc18.3 then log in and leave karma (feedback).
Package systemd-201-2.fc18.5: * should fix your issue, * was pushed to the Fedora 18 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing systemd-201-2.fc18.5' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-5452/systemd-201-2.fc18.5 then log in and leave karma (feedback).
systemd-201-2.fc18.6 has been submitted as an update for Fedora 18. https://admin.fedoraproject.org/updates/FEDORA-2013-5452/systemd-201-2.fc18.6
Package systemd-201-2.fc18.6: * should fix your issue, * was pushed to the Fedora 18 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing systemd-201-2.fc18.6' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2013-5452/systemd-201-2.fc18.6 then log in and leave karma (feedback).
systemd-201-2.fc18.6 has been pushed to the Fedora 18 stable repository. If problems still persist, please make note of it in this bug report.