I am working on a PowerPC board using kernel version 4.1.35 and encountering significant boot delays, specifically around the RTC clock (ds-1337) operations. During the boot process, a script (hwclock.sh) runs the hwclock --hctosys command, and I've added print statements to log its execution time in the kernel logs.
Here’s a snippet from hwclock.sh:
echo "running command hwclock --hctosys. - arij" | tee /dev/kmsg hwclock $tz --hctosys echo "ending hwclock --hctosys. - arij" | tee /dev/kmsg When the kernel configuration CONFIG_DYNAMIC_DEBUG is disabled, the hwclock command experiences significant delays, sometimes up to 50 seconds. However, when CONFIG_DYNAMIC_DEBUG is enabled, the delays are significantly reduced, with execution times ranging between 4 to 12 seconds.
Here are some kernel log snippets from various boot cycles with CONFIG_DYNAMIC_DEBUG disabled:
Boot cycle 1:
[ 6.401707] running command hwclock --hctosys. - arij [ 39.206200] ending hwclock --hctosys. - arij Boot cycle 2:
[ 7.054404] running command hwclock --hctosys. - arij [ 14.218021] ending hwclock --hctosys. - arij Boot cycle 5:
[ 18.659482] running command hwclock --hctosys. - arij [ 50.005113] ending hwclock --hctosys. - arij With CONFIG_DYNAMIC_DEBUG enabled, the delays decrease:
Example with **CONFIG_DYNAMIC_DEBUG **enabled:
[ 8.833980] running command hwclock --hctosys. - arij [ 14.223970] ending hwclock --hctosys. - arij Additionally, when booting with the configuration CONFIG_PROFILING enabled, the hwclock command consistently takes no more than 2 seconds.
Questions
- What could be causing the drastic increase in boot time when CONFIG_DYNAMIC_DEBUG is disabled?
- Why does enabling CONFIG_DYNAMIC_DEBUG reduce the time taken for the hwclock --hctosys command?
- Could there be any underlying issues with the RTC driver or interactions between the hwclock command and kernel configurations?
- How might CONFIG_PROFILING impact the timing of hwclock --hctosys?
- Any insights into these behaviors would be greatly appreciated.
Update 1: i have tried multiple kernel prints in the rtc drivers and it only showed that the mutex lock is waiting to be acquired. i cant understand whats causing the problem and how is it not appearing when dynamic debugging is enabled
the prints i enabled are like this:
pr_info("--------------------- %s: %s: Line %d - Mutex Locking interruptible - arij\n", __FILE__, __func__, __LINE__); int err = mutex_lock_interruptible(&rtc->ops_lock); pr_info("--------------------- %s: %s: Line %d - Mutex Locked interruptible - arij\n", __FILE__, __func__, __LINE__); and got prints:
[ 17.450075] running command hwclock --hctosys. - arij [ 17.461239] rtc_core: --------------------- /home/pc/kernel-source/drivers/rtc/rtc-dev.c: rtc_dev_ioctl: Line 234 - Mutex locking- arij [ 23.737863] rtc_core: --------------------- /home/pc/kernel-source/drivers/rtc/rtc-dev.c: rtc_dev_ioctl: Line 236 - Mutex locked with cmd=1076129801 - arij [ 23.752437] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_read_time: Line 62 - Mutex Locking interruptible - arij [ 27.005861] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_read_time: Line 65 - Mutex Locked interruptible - arij [ 27.020196] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_read_time: Line 74 - Mutex Unlock interruptible - arij [ 27.034029] rtc_core: --------------------- /home/pc/kernel-source/drivers/rtc/rtc-dev.c: rtc_dev_ioctl: Line 234 - Mutex locking- arij [ 30.637859] rtc_core: --------------------- /home/pc/kernel-source/drivers/rtc/rtc-dev.c: rtc_dev_ioctl: Line 236 - Mutex locked with cmd=536899588 - arij [ 30.652312] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 515 - Mutex Locking interruptible - arij [ 34.805855] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 517 - Mutex Locked interruptible - arij [ 34.819887] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 552 - Mutex unock in out: - arij [ 34.833291] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 515 - Mutex Locking interruptible - arij [ 62.173853] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 517 - Mutex Locked interruptible - arij [ 62.187884] --------------------- /home/pc/kernel-source/drivers/rtc/interface.c: rtc_update_irq_enable: Line 552 - Mutex unock in out: - arij [ 62.204506] ending hwclock --hctosys. - arij Update 2: I also changed the configuration to not get a timeless kernel. but i still observed the same delays
CONFIG_HZ_PERIODIC=y CONFIG_NO_HZ_IDLE not set CONFIG_NO_HZ not set 