Boot Delays on PowerPC Board with RTC Clock and hwclock --hctosys Command Related to Kernel Configurations
0
votes
0
answers
29
views
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**
1. What could be causing the drastic increase in boot time when CONFIG_DYNAMIC_DEBUG is disabled?
1. Why does enabling CONFIG_DYNAMIC_DEBUG reduce the time taken for the hwclock --hctosys command?
1. Could there be any underlying issues with the RTC driver or interactions between the hwclock command and kernel configurations?
1. How might CONFIG_PROFILING impact the timing of hwclock --hctosys?
1. 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
Asked by Mohammad Arij Kamran
(3 rep)
Aug 21, 2024, 07:06 AM
Last activity: Aug 21, 2024, 07:15 AM
Last activity: Aug 21, 2024, 07:15 AM